blob: 6a85b7c004236b7f569e5e09428c70b89ea8516b [file]
# Copyright 2026 The Fuchsia Authors. All rights reserved.
# Use of this source code is governed by a BSD-style license that can be
# found in the LICENSE file.
"""Starnix binder delays, missed wakeups, and thread pool analysis plugin.
This plugin audits:
1. Thread wakeup scheduling delays (Runnable state duration) for binder worker threads.
2. Incomplete and delayed binder transactions (queue latencies).
3. SpawnLooper instant events indicating binder waker threads spawned during high contention.
4. no_available_threads instant events indicating binder thread pool exhaustion.
5. process_queue_depth counters measuring transaction queue backlog.
A "bottleneck" is when a thread is in the runnable state, but is not run on the CPU due to scheduling constraints, or
when a slice is longer than some cut-off (e.g. 10ms) indicating it is blocked by another thread or resource.
See: go/systemperf-perfetto-queries#binder for additional info.
"""
import math
from collections.abc import Set
from typing import Sequence
from plugins import (
AnalyzePlugin,
PluginArgumentError,
PluginArgumentParser,
SectionResult,
)
from tp_shell import PerfettoTraceProcessor
CATEGORY_NOT_FOUND_NOTE: str = (
"The 'starnix:binder' category was not found in this trace. "
"Fell back to 'binder_ioctl' and 'binder:%' thread name heuristics. "
"Including 'starnix:binder' in the trace will strengthen the binder performance analysis "
"with transaction queue latencies, waker milestones, and thread pool exhaustion events."
)
def _has_starnix_binder_category(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
) -> bool:
"""Checks whether the trace contains slices with the 'starnix:binder' category."""
if "slice" not in db_objects:
return False
try:
rows = tp.run_query(
"SELECT 1 FROM slice WHERE category = 'starnix:binder' LIMIT 1"
)
return len(rows) > 0
except Exception:
return False
def _analyze_missed_wakeups(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
threshold_ns: int,
has_category: bool = True,
) -> SectionResult:
"""Analyzes thread runnable state durations to detect scheduling delays and missed wakeups."""
name = "Missed Wakeups (Wakeup Latencies)"
note = CATEGORY_NOT_FOUND_NOTE if not has_category else None
required_tables = {
"thread_state",
"slice",
"thread_track",
"thread",
"process",
}
if missing := required_tables - db_objects:
return SectionResult(
name=name,
error=f"Required schema tables/views missing: {', '.join(sorted(missing))}",
note=note,
)
if has_category:
binder_threads_cte = """
WITH binder_threads AS (
SELECT DISTINCT utid
FROM slice
JOIN thread_track ON slice.track_id = thread_track.id
WHERE slice.category = 'starnix:binder'
OR slice.name = 'binder_ioctl'
)
"""
else:
binder_threads_cte = """
WITH binder_threads AS (
SELECT DISTINCT utid
FROM thread
WHERE name LIKE 'binder:%' OR name LIKE 'binder_%'
UNION
SELECT DISTINCT utid
FROM slice
JOIN thread_track ON slice.track_id = thread_track.id
WHERE slice.name = 'binder_ioctl'
)
"""
query = f"""
{binder_threads_cte}
SELECT
ts.ts as wakeup_ts,
ts.dur as scheduling_delay_ns,
t.name as thread_name,
t.tid as tid,
p.name as process_name,
p.pid as pid,
waker.name as waker_thread_name,
waker.tid as waker_tid
FROM thread_state ts
JOIN binder_threads USING (utid)
JOIN thread t USING (utid)
LEFT JOIN process p USING (upid)
LEFT JOIN thread waker ON ts.waker_utid = waker.utid
WHERE ts.state IN ('R', 'R+') AND ts.dur > {threshold_ns}
ORDER BY ts.dur DESC
"""
try:
missed_wakeups = tp.run_query(query)
return SectionResult(
name=name,
results=missed_wakeups,
note=note,
)
except Exception as e:
return SectionResult(
name=name,
error=f"Query execution failed: {e}",
note=note,
)
def _analyze_binder_delays(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
threshold_ns: int,
complete_only: bool,
has_category: bool = True,
) -> SectionResult:
"""Analyzes flow slice latencies to identify delayed or incomplete binder transactions."""
name = "Binder Delays (Transaction Queue Latencies)"
note = CATEGORY_NOT_FOUND_NOTE if not has_category else None
required_tables = {
"flow",
"slice",
"thread_track",
"thread",
"args",
"trace_bounds",
}
if missing := required_tables - db_objects:
return SectionResult(
name=name,
error=f"Required schema tables/views missing: {', '.join(sorted(missing))}",
note=note,
)
if has_category:
completed_filter = f"""
WHERE s_out.category = 'starnix:binder'
AND (s_in.ts - s_out.ts) > {threshold_ns}
"""
incomplete_filter = f"""
WHERE s.category = 'starnix:binder'
AND (s.name = 'Transaction' OR s.name = 'HandleTransaction' OR s.name = 'BinderTransaction')
AND s.id NOT IN (SELECT slice_out FROM flow WHERE slice_out IS NOT NULL)
AND s.id NOT IN (SELECT slice_in FROM flow WHERE slice_in IS NOT NULL)
AND ((SELECT end_ts FROM trace_bounds) - s.ts) > {threshold_ns}
"""
else:
completed_filter = f"""
WHERE (s_out.name = 'binder_ioctl'
OR t_out.name LIKE 'binder:%' OR t_out.name LIKE 'binder_%'
OR t_in.name LIKE 'binder:%' OR t_in.name LIKE 'binder_%')
AND (s_in.ts - s_out.ts) > {threshold_ns}
"""
incomplete_filter = f"""
WHERE (s.name = 'binder_ioctl' OR s.name = 'Transaction'
OR t.name LIKE 'binder:%' OR t.name LIKE 'binder_%')
AND s.id NOT IN (SELECT slice_out FROM flow WHERE slice_out IS NOT NULL)
AND s.id NOT IN (SELECT slice_in FROM flow WHERE slice_in IS NOT NULL)
AND ((SELECT end_ts FROM trace_bounds) - s.ts) > {threshold_ns}
"""
completed_query = f"""
SELECT
flow.id as flow_id,
s_out.ts as send_ts,
s_in.ts as recv_ts,
(s_in.ts - s_out.ts) as queue_latency_ns,
t_out.name as sender_thread,
t_out.tid as sender_tid,
t_in.name as receiver_thread,
t_in.tid as receiver_tid,
'Completed' as status,
COALESCE(
(SELECT string_value FROM args WHERE arg_set_id = s_out.arg_set_id AND key = 'cmd'),
(SELECT 'code: ' || int_value FROM args WHERE arg_set_id = s_out.arg_set_id AND key = 'code'),
s_out.name
) as cmd
FROM flow
JOIN slice s_out ON flow.slice_out = s_out.id
JOIN slice s_in ON flow.slice_in = s_in.id
JOIN thread_track track_out ON s_out.track_id = track_out.id
JOIN thread t_out ON track_out.utid = t_out.utid
JOIN thread_track track_in ON s_in.track_id = track_in.id
JOIN thread t_in ON track_in.utid = t_in.utid
{completed_filter}
"""
if complete_only:
query = f"{completed_query}\n ORDER BY queue_latency_ns DESC"
else:
incomplete_query = f"""
SELECT
NULL as flow_id,
s.ts as send_ts,
NULL as recv_ts,
((SELECT end_ts FROM trace_bounds) - s.ts) as queue_latency_ns,
t.name as sender_thread,
t.tid as sender_tid,
NULL as receiver_thread,
NULL as receiver_tid,
'Incomplete' as status,
COALESCE(
(SELECT string_value FROM args WHERE arg_set_id = s.arg_set_id AND key = 'cmd'),
(SELECT 'code: ' || int_value FROM args WHERE arg_set_id = s.arg_set_id AND key = 'code'),
s.name
) as cmd
FROM slice s
JOIN thread_track tr ON s.track_id = tr.id
JOIN thread t USING(utid)
{incomplete_filter}
"""
query = f"{completed_query}\n UNION ALL\n{incomplete_query}\n ORDER BY queue_latency_ns DESC"
try:
binder_delays = tp.run_query(query)
return SectionResult(
name=name,
results=binder_delays,
note=note,
)
except Exception as e:
return SectionResult(
name=name,
error=f"Query execution failed: {e}",
note=note,
)
def _analyze_spawn_loopers(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
has_category: bool = True,
) -> SectionResult:
"""Analyzes SpawnLooper instant events to identify thread pool exhaustion and late-spawned wakers."""
name = "Spawn Looper Events (Late-Spawned Wakers)"
note = CATEGORY_NOT_FOUND_NOTE if not has_category else None
required_tables = {
"slice",
"thread_track",
"thread",
"process",
}
if missing := required_tables - db_objects:
return SectionResult(
name=name,
error=f"Required schema tables/views missing: {', '.join(sorted(missing))}",
note=note,
)
if not has_category:
return SectionResult(
name=name,
results=[],
note=note,
)
query = """
SELECT
s.ts AS ts,
p.name AS process_name,
p.pid AS pid,
t.name AS thread_name,
t.tid AS tid,
parent.name AS parent_slice_name,
parent.dur AS parent_dur_ns
FROM slice s
JOIN thread_track tt ON s.track_id = tt.id
JOIN thread t ON tt.utid = t.utid
JOIN process p ON t.upid = p.upid
LEFT JOIN slice parent ON s.parent_id = parent.id
WHERE s.category = 'starnix:binder' AND s.name = 'SpawnLooper'
ORDER BY s.ts ASC
"""
try:
spawn_loopers = tp.run_query(query)
return SectionResult(
name=name,
results=spawn_loopers,
note=note,
)
except Exception as e:
return SectionResult(
name=name,
error=f"Query execution failed: {e}",
note=note,
)
def _analyze_no_available_threads(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
has_category: bool = True,
) -> SectionResult:
"""Analyzes no_available_threads instant events indicating binder thread pool exhaustion."""
name = "No Available Threads Events (Thread Pool Exhaustion)"
note = CATEGORY_NOT_FOUND_NOTE if not has_category else None
required_tables = {
"slice",
"thread_track",
"thread",
"process",
"args",
}
if missing := required_tables - db_objects:
return SectionResult(
name=name,
error=f"Required schema tables/views missing: {', '.join(sorted(missing))}",
note=note,
)
if not has_category:
return SectionResult(
name=name,
results=[],
note=note,
)
if "process_track" in db_objects:
process_join = """
LEFT JOIN process_track pt ON s.track_id = pt.id
LEFT JOIN process p_proc ON pt.upid = p_proc.upid
"""
proc_name_expr = "COALESCE(p_proc.name, p_thread.name)"
pid_expr = "COALESCE(p_proc.pid, p_thread.pid)"
else:
process_join = ""
proc_name_expr = "p_thread.name"
pid_expr = "p_thread.pid"
query = f"""
SELECT
s.ts AS ts,
{proc_name_expr} AS process_name,
{pid_expr} AS pid,
(SELECT int_value FROM args WHERE arg_set_id = s.arg_set_id AND key = 'target_pid') AS target_pid,
(SELECT string_value FROM args WHERE arg_set_id = s.arg_set_id AND key = 'command') AS command
FROM slice s
{process_join}
LEFT JOIN thread_track tt ON s.track_id = tt.id
LEFT JOIN thread t ON tt.utid = t.utid
LEFT JOIN process p_thread ON t.upid = p_thread.upid
WHERE s.category = 'starnix:binder' AND s.name = 'no_available_threads'
ORDER BY s.ts ASC
"""
try:
events = tp.run_query(query)
return SectionResult(
name=name,
results=events,
note=note,
)
except Exception as e:
return SectionResult(
name=name,
error=f"Query execution failed: {e}",
note=note,
)
def _analyze_process_queue_depth(
tp: PerfettoTraceProcessor,
db_objects: Set[str],
has_category: bool = True,
) -> SectionResult:
"""Analyzes process_queue_depth counter tracks to quantify transaction queue backlog."""
name = "Binder Process Queue Depth (Counter Summary)"
note = CATEGORY_NOT_FOUND_NOTE if not has_category else None
required_tables = {
"counter",
"process_counter_track",
"process",
}
if missing := required_tables - db_objects:
return SectionResult(
name=name,
error=f"Required schema tables/views missing: {', '.join(sorted(missing))}",
note=note,
)
if not has_category:
return SectionResult(
name=name,
results=[],
note=note,
)
query = """
SELECT
p.name AS process_name,
p.pid AS pid,
MAX(c.value) AS max_queue_depth,
AVG(c.value) AS avg_queue_depth,
COUNT(*) AS sample_count
FROM counter c
JOIN process_counter_track pct ON c.track_id = pct.id
JOIN process p ON pct.upid = p.upid
WHERE pct.name = 'process_queue_depth'
GROUP BY p.name, p.pid
HAVING MAX(c.value) > 0
ORDER BY max_queue_depth DESC
"""
try:
queue_depths = tp.run_query(query)
return SectionResult(
name=name,
results=queue_depths,
note=note,
)
except Exception as e:
return SectionResult(
name=name,
error=f"Query execution failed: {e}",
note=note,
)
class BinderPlugin(AnalyzePlugin):
name: str = "binder"
description: str = "Analyze Starnix binder delays and missed wakeups"
def analyze(
self,
remaining_args: Sequence[str],
trace_path: str,
cache: bool = True,
) -> Sequence[SectionResult]:
parser = PluginArgumentParser(
prog=f"perf-analyze analyze --plugin {self.name}"
)
parser.add_argument(
"--threshold-ms",
type=float,
default=10.0,
help="Threshold for scheduling delay and queue latency in milliseconds (default: 10.0)",
)
parser.add_argument(
"--complete-only",
action="store_true",
help="Only return complete transactions (default: False, includes incomplete)",
)
args = parser.parse_args(remaining_args)
if not math.isfinite(args.threshold_ms) or args.threshold_ms < 0.0:
raise PluginArgumentError(
"Latency threshold must be a finite, non-negative number."
)
threshold_ns = int(args.threshold_ms * 1_000_000)
with PerfettoTraceProcessor(trace_path, cache=cache) as tp:
db_objects = tp.get_tables()
has_category = _has_starnix_binder_category(tp, db_objects)
results: list[SectionResult] = []
if not has_category:
results.append(
SectionResult(
name="Trace Category Status",
note=CATEGORY_NOT_FOUND_NOTE,
results=[
{
"category": "starnix:binder",
"status": "Not Found (using fallback heuristics)",
"recommendation": (
"Including 'starnix:binder' in the trace will"
" strengthen binder performance analysis."
),
}
],
)
)
results.extend(
[
_analyze_missed_wakeups(
tp, db_objects, threshold_ns, has_category
),
_analyze_binder_delays(
tp,
db_objects,
threshold_ns,
args.complete_only,
has_category,
),
_analyze_spawn_loopers(tp, db_objects, has_category),
_analyze_no_available_threads(tp, db_objects, has_category),
_analyze_process_queue_depth(tp, db_objects, has_category),
]
)
return results