Detectors¶

A detector is one self-contained .sql file. Metadata in the header, {{param}} placeholders substituted from the config:

-- @id: my_detector
-- @title: What we are looking for
-- @why: why it matters
-- @param: threshold_ms = 50
-- @identity: location, detail

SELECT name AS location, COUNT(*) AS count,
       ROUND(SUM(dur)/1e6, 2) AS total_ms,
       ROUND(MAX(dur)/1e6, 2) AS max_ms,
       thread_name AS detail
FROM _slice_win
WHERE dur >= {{threshold_ms}} * 1000000
GROUP BY name, thread_name
ORDER BY total_ms DESC
LIMIT 20;

Drop the file into echolot/sql/detectors/ and it runs. There is no registration in code, and @param values are the defaults the project config overrides. Running is not the same as shipping, though — what else a new detector needs is in the checklist below.

The column contract is shared: location, count, self_ms, total_ms, max_ms, covered_ms, detail. Not every detector fills every column, but the report renders uniformly and the agent reads a stable schema.

@identity names the columns that tell one row of the result from another — what the query groups by, as it reaches the report. It defaults to location and has to include it. The example groups by the thread as well as the name, so it says location, detail. Left at the default, two threads running the same name come out as two rows of one trace, and merging repeats — which folds rows on their identity — puts a single median across both. compare pairs rows on the identity too, and would match either thread against either. A column named there is part of the row's name rather than evidence, which is also why compare shows detail in its Evidence column only for detectors that list it.

So a column in the identity carries nothing that can change from one repeat to the next. io_wait is named by location, thread: thread says main or background, and the kernel functions a thread stopped in stay in detail. Which functions those are, and in what order, changes between repeats, and with them in the name one thread became a row per variant, each seen once.

The context views¶

They are already narrowed to our process and the scenario window, so nothing project-specific belongs inside a detector.

The async ones are kept apart on purpose. A section on no thread has no place in a sum per thread — counted with the rest it would land under no thread, at a depth of its own, and every self-time and coverage figure would be off by its length. So no shipped detector reads _aslice_win. The markers table in every report does: the project's own names are usually async, and it measures them by name rather than by thread.

_claimed_name is the set's own vocabulary, collected from every shipped detector's masks with the project's overrides applied. It is read by repeated_work and app_init, the two detectors that look at every slice name in their stretch: they ask about shape, not about a family of names, and NOT IN (SELECT name FROM _claimed_name) is how they stay off names that belong to another question. Widening a *name_glob* mask in echolot.yml takes those names out of both. Twice it reported a finding that was already in the report under its own heading — an ART lock wait, then a GC phase — and this is the rule that replaced naming those families one at a time.

Not everything worth detecting is a slice. frame_jank reads actual_frame_timeline_slice and expected_frame_timeline_slice directly — SurfaceFlinger's own per-frame record, which has no context view because nothing else needs it. A detector reaching outside the views takes on two jobs the views were doing for it: joining _proc so it stays inside our process, and clipping to _window itself. Both are visible at the top of that file.

Two duration columns are not a duplicate¶

_slice_win carries both:

• dur — the real slice length. This is what humans are shown: a 200 ms block stays a 200 ms block even if the window cut it in half;
• dur_win — only the part inside the window. For share and coverage arithmetic.

Adding up dur when computing coverage is a way to get past 100% and miss the problem. On _tstate_win the dur field is already clipped, because the question there is always "how long did the thread spend in this state inside the scenario".

A slice that never closed is the longest one, not a zero¶

trace_processor gives a slice still open when the trace stopped dur = -1. _slice_win reads that as running to the end of the window and sets unfinished beside it, so a detector that wants to say "at least" has the fact rather than inferring it from a number that happens to land on the window's edge.

The reading matters more than it sounds. On a real freeze the main thread sat in ART's contention slice for twenty seconds, the lock was never released, the slice never closed — and folding that to zero made the worst thing in the trace the one thing invisible in it. Two detectors missed it and neither had a bug of its own.

The rest of the pipeline reads an open interval the same way:

• the window's end. An end anchor that never closed ends the window at the end of the trace, and the report marks it end_anchor.unfinished. Read as zero long, it cut the window off where the scenario got stuck. With no end anchor, the window ends where the process's last slice does, and an open one runs to the end of the trace.
• thread states. _tstate_win reads a thread's last state, still open when the recording stopped, as running to the end of the window. Dropped, it took each thread's last stretch out of the budget, io_wait, uninstrumented_cpu and anr_risk.
• children. _child_sum reads an open child as running to the end of the window, and stops each child of an open slice there, so self times still add up to no more than the window.

A stretch is a third shape, and the window is not always right¶

anr_risk asks neither "how much went into this name" nor "was this one occurrence unusual" but "how long did the main thread go without returning to the message queue". Fifty different pieces of work back to back freeze an app exactly as one long one does, and a detector that groups by name cannot see it.

It takes evidence from slices at depth 1 and below, plus the thread's own states. Depth 0 is deliberately excluded. A scenario anchor — AppStart around a cold start, and every marker of that shape echolot mark proposes — is a top-level slice covering the whole run including its idle moments. Counting it would report every scenario as one unbroken stall on any project that has an anchor at all, which is every project this tool asks to add one.

anr breaks the other rule: it is the one detector not clipped to the scenario window. An ANR fires five seconds after the event that could not be served, and a cold start's window closes at the first frame. Clipped, it would be absent from nearly every trace that contains one — and absence reads as "no freeze", which is the thing that detector exists to contradict. It reads the whole trace and says in detail where the record fell relative to the window.

A detector needing a Perfetto stdlib module declares it in the header:

-- @module: android.anrs

The runner includes it once per session, before any query. It belongs in the header rather than in the SQL because a detector runs as a single statement, and an INCLUDE in front of the SELECT would make it two.

Sums and single occurrences are different detectors¶

Most of the shipped ones gate on an accumulated sum for a name: how much time went into inflate across the window. That is the right shape for "the whole thing got slower" and blind to a heavy tail — one occurrence of 86 ms among thousands dissolves into any sum you care to take, which is how a benchmark reporting P50 14.7 ms and P99 86 ms met silence from six detectors at once.

main_thread_outlier is the other shape: a single occurrence against the median for that same name. Worth knowing before writing a detector, because the question decides the gate, and a HAVING SUM(...) answers only one of them. Two floors go under a ratio, or it is worthless at small sizes — an absolute one, so "four times longer than 0.5 ms" is not a finding, and a minimum number of occurrences, because a name seen three times has no typical duration to be an outlier from.

A column may mean something else, if the header says so¶

The contract is shared, and one detector bends it. In frame_jank total_ms and max_ms are time past the deadline rather than duration, because the loss is the actionable number and the frame's own length is not. The frame duration is in detail instead, since that is the number a benchmark's percentiles are quoted in.

composables bends self_ms the same way. A composable's own slice holds about a millisecond, the rest being the library's composables under it, so its self_ms is the calls less the app's own composables nested in them, the library's counted in. The rows still add up without counting a moment twice, which is what self time is for.

That is allowed and it is not free: anything reading the report generically — compare, the markdown table — treats the numbers as milliseconds and gets milliseconds, but a reader who assumes duration reads them wrong. So the deviation is stated in the detector's own header, in the report reference, and here. A detector that bends the contract quietly is a bug.

Window functions are available, and worth reaching for¶

The bundled SQLite is 3.50 and has had window functions since 3.25. A median per group — which SQLite has no aggregate for — is one sort rather than a correlated subquery per group:

ranked AS (
    SELECT name, dur,
           ROW_NUMBER() OVER (PARTITION BY name ORDER BY dur) AS rk,
           COUNT(*)     OVER (PARTITION BY name)              AS n
    FROM _slice_win
),
baseline AS (SELECT name, n, dur AS median_ns FROM ranked WHERE rk = (n + 1) / 2)

main_thread_outlier is built on exactly that. The alternatives considered before checking what the bundled SQLite could do were a per-group ORDER BY … LIMIT 1 OFFSET n/2, an AVG that the outlier itself would drag, and computing the base in Python and substituting numbers. None was needed.

Use _cpu_in_slice, do not rebuild it¶

The question "what share of a thread's work ran inside instrumented code" requires intersecting Running intervals with slices. Written directly as a JOIN ... ON overlap, SQLite executes it as a nested loop: on a live trace with 475k slices the run did not finish within ten minutes.

The prepared intersection uses SPAN_JOIN, a trace_processor operator built for exactly this — merging two sorted sets of non-overlapping intervals within a partition. On the same trace it takes 0.1 s. It is built once in the context; do not write that join by hand.

Why the window arrives as numbers¶

ts_start / ts_end are substituted into these views as literals, not computed by a view. While the window was a view, every reference to _slice_win recomputed it, and on a 475k-slice trace a run did not finish within ten minutes.

Hence the phases: context.sql finds the window, the CLI reads it, and window.sql builds everything else on top of plain numbers. environment.sql is a third, run on the same numbers right after it: the clock, the temperature, throttling and memory the report states every duration under. Nothing in it is a detector — no threshold, no finding — and its views are there for a detector that wants them all the same.

Self time versus total time¶

main_thread_block measures self time — the slice's duration minus its children. The reason shows up immediately on a live trace, where sorting by total duration produced:

d0  355.4 ms  Choreographer#doFrame 55112
d1  354.6 ms  Choreographer#doFrame - resynced to 55120 in 21.1ms
d2  354.4 ms  traversal

Three rows about one event. An agent reading that report would count the same 355 ms three times over. Meanwhile the real consumer — draw with its own 125 ms — sat fifth, and TextLayout:initLayout at nesting depth six never appeared at all.

Self times do not overlap by construction: their sum across a thread cannot exceed the thread's own time. That property is pinned by a check.

Total duration stays alongside in its own column, because the pair says more than either number alone:

Two conditions, not one¶

Several detectors fire on either a single large occurrence or an accumulated total. That is not belt-and-braces either.

On a live cold start the main thread took 76 binder transactions totalling 65.9 ms, the longest 9.71 ms. Not one cleared the 10 ms bar, so the detector stayed silent while synchronous IPC ate 8.5% of startup. The same shape appeared with locks: 200 blocks of a quarter of a millisecond each.

Death by a thousand cuts is no less real than one long call.

What time the rows stand for¶

A row says how much. The report also says how much of the window the findings cover — Covered by the findings below under the budget, window.main_thread.in_rows_pct in the JSON — and that needs to know which moments each row stands for, so that a moment two rows describe is counted once. A line reading -- @intervals after the query starts a second query that says so:

ORDER BY total_ms DESC
LIMIT 20;

-- @intervals
SELECT s.ts, s.dur
FROM _slice_win s
JOIN _rows r ON r.location = s.name AND r.detail = s.thread_name
WHERE s.is_main_thread = 1;

analyze runs it straight after the first, with the same thresholds and with the rows the first returned in a table named _rows — location and detail, the latter NULL where a row has none. It returns ts and dur in nanoseconds, one line per stretch of the main thread's time. Stretches may overlap and may run past the window: they are clipped and every moment is counted once. A row about another thread returns nothing, because the window's length is made of the main thread's time; a background thread working in parallel explains none of it until the main thread waits for it, and then the waiting is the main thread's, where a row of its own can stand for it.

What decides the query:

• The marker comes straight after the first query, so that the first still ends in its LIMIT — calibrate strips it from there.
• Stand for what the row counts. main_thread_block counts self time, so its stretches are the slices with their children taken out; a detector that counts whole slices returns whole slices. Which rows cleared a threshold is already in _rows and is not decided again — only a selection inside a row is, the way main_thread_outlier picks the occurrences past its factor.
• A slice that spans the whole window is the window. Usually it is the scenario's anchor, and its self time is the part of the window no child accounts for. main_thread_block leaves it out, for the reason anr_risk does not take depth zero as evidence.
• Rows that are not the main thread's time say so with a query that returns nothing, and a comment saying why: frame_jank's lateness is on the display's timeline, and anr is a record of the system giving up. A detector with no second query at all is named in the report as not counted.

Every shipped detector has one, and the tests hold each to its own rows: on the fixture, the stretches behind the rows about the main thread add up to those rows' own milliseconds.

What ran there¶

A line reading -- @samples starts a third query, which picks out the callstack samples behind each row. uninstrumented_cpu has one:

-- @samples
SELECT t.name AS location, s.callsite_id
FROM _samples_by_slice s
JOIN thread t ON t.utid = s.utid
WHERE s.instrumented IS NULL
  AND t.name IN (SELECT location FROM _rows);

It sees the same _rows as the second query and returns location and callsite_id, one line per sample, with a NULL callsite for a sample that came without a stack. A row is a thread's name, so the samples are every thread's of that name. The rest is the same for every detector and happens in echolot/stacks.py: each stack is walked from its leaf, and two things are counted — what ran, the first Kotlin or Java method with a name, and the nearest frame of the project's own code, decided the way an ANR's frames are, or whether the stack had none of it all the way down or was cut short. The row gets stacks in the json and the gist at the end of its detail:

100.0% of CPU outside slices · 28 stacks: GzipSink.write 54%, ReadBarrier::Mark 21% · ours: Store.save 36%, cut 29%

Why those rules, from a phone's stacks, is in Analysing.

What decides the query:

• It runs only where a sampler ran. analyze asks the trace whether a sampler started, and a trace without samples gets the rows it always got.
• _samples_by_slice, not a join on ts. Placing a sample inside a stretch by hand is the nested loop the section above warns about. _samples_by_slice is SPAN_JOIN over _cpu_by_slice, with each sample given one nanosecond.
• A detail in the identity stays as it is. There it is part of the row's name, and a name that moved with the samples would not merge across repeats. Such a row carries stacks alone.
• Repeats keep the evidence of one that has stacks. The worst repeat gives a merged row its detail and stacks, unless its sampler lost the process while another repeat's did not; then the worst of those with stacks does.

What trips people up¶

Three things that cost an afternoon each. All three are about trace_processor rather than about SQL, which is why knowing SQL does not save you from them, and all three were checked against the pinned version rather than taken on trust.

SPAN_JOIN does not fail on overlapping input — it double-counts¶

It merges two sets of intervals and needs them not to overlap within a partition. Feed it overlap and there is no error: it produces rows, they look ordinary, and the durations are wrong.

Two intervals of one partition, [0,100) and [50,150), joined against [0,200):

That sums to 200 against a true union of 150. The overlapping fifty is counted twice, and any detector that sums durations — coverage, on-CPU time, a share of the window — reports a number that is too large with nothing anywhere saying so.

So the guarantee has to come from the input, and it has to be written down:

DROP TABLE IF EXISTS _cpu_in_slice;
CREATE VIRTUAL TABLE _cpu_in_slice
USING SPAN_JOIN(_running_span PARTITIONED utid, _top_slice_span PARTITIONED utid);

PARTITIONED utid is safe here because two Running intervals of one thread cannot overlap. PARTITIONED cpu in environment.sql is safe for a different reason: one core runs one thread at a time. Both are properties of the machine rather than of the query, so say which one you are leaning on — the next person cannot re-derive it from the SQL, and nothing will tell them they were wrong.

Read the schema, do not guess it¶

SELECT * FROM <table> LIMIT 1 prints the column names along with a row. LIMIT 0 is the tidier-looking version and is useless through the Python API: zero rows means zero column names, because the columns arrive as the keys of the rows.

Two minutes of this beats twenty minutes of a query that runs and answers the wrong question. thread_state.cpu is filled in only while the thread is Running; counter_track.type says which kind of counter a track is; neither is guessable.

The same goes for what a value looks like after trace_processor has finished with it. A thermal zone arrives as a track named cpu-therm Temperature and not cpu-therm. A temperature arrives in millidegrees, as the kernel wrote it — environment.sql divides by a thousand — while meminfo arrives in bytes where /proc wrote kilobytes. One unit is converted on the way in and the other is not, and nothing but a query says which. Build a five-line trace carrying the events you care about, query it, and look.

A thread's waker is on the state after its sleep¶

thread_state.waker_utid names the thread that woke this one, from sched/sched_waking, and trace_processor writes it on the state the thread was woken into, the R that follows the sleep. The sleep itself carries no waker. main_thread_waits reads it with LEAD over the main thread's states in order; a join of the table to itself on ts + dur does the same and costs far more on a trace of a few hundred thousand states.

Everything must survive being run twice¶

A detector runs against a session that already holds the views from the last one, and a plain CREATE VIEW fails the second time. Hence DROP VIEW IF EXISTS in front of every view in the context files. CREATE OR REPLACE PERFETTO {TABLE|VIEW|MACRO|FUNCTION} does the same job for the Perfetto forms. A virtual table from SPAN_JOIN has no OR REPLACE and needs the explicit DROP TABLE IF EXISTS shown above.

The symptom is a detector that works alone and fails in a full run, which sends you reading the query instead of the session.

Adding a detector¶

A file in echolot/sql/detectors/ runs on the next analyze. Shipping it takes more. The first three things below fail the build until they are done. The other three decide what the tool does with the detector once it runs — what survives a merge, which overrides it accepts, which masks names can see — and a mistake there fails nothing until somebody reads the report or writes a config.

• A problem planted for it in the fixture. doctor's self-check counts the detector files, and "every shipped detector ran, and every one fired" fails until echolot/fixture.py plants something the new one finds — or until SILENT_ON_FIXTURE in echolot/selftest.py names it, with the reason the fixture is the wrong shape to hold one, the way it names anr_risk. Then the checks that pin what it must find and what it must not, beside the others in selftest.py.
• The README. tests/test_docs.py reads the number in "runs fifteen SQL detectors" and in the sample report's Detectors fired: **N of 15**, and fails while either disagrees with the files. The sample report is what analyze prints for the demo app, echolot/demo.py, and tests/test_doc_samples.py holds it to that character for character, down to the Silent line, which names every detector that did not fire there — a new detector included. The README's table of detectors is a picture drawn from each detector's @title, in the order DETECTOR_ORDER in docs/assets/render.py gives, and the script stops until the new one has a place there. Both tests fail until python docs/assets/render.py writes the sample and draws the table again. The table in references/report.md is a list kept by hand.
• The time its rows stand for. A shipped detector needs an -- @intervals query, and a first query that ends in LIMIT n: test_every_shipped_detector_has_one in tests/test_in_rows.py fails without either, and once the detector fires on the fixture, doctor's check that the findings' share of the window counts every detector fails too. A file only dropped in still runs without one, and the coverage line names it as not counted whenever it fires. See What time the rows stand for.
• Only part of a row survives a merge. Repeats are folded row by row, and a merged row keeps its @identity columns, runs, the numeric contract columns — count, self_ms, total_ms, max_ms and covered_ms, as medians — and detail, taken from the worst repeat unless the identity already holds it. stacks, from a -- @samples query, comes from that same repeat, so the evidence and the list it quotes agree. A column the detector invents is rendered in a report of one trace and is gone from a report of five, so what a reader needs goes into detail.
• A threshold keeps the kind of its default. An override from echolot.yml or from --set must be what the @param default is — a number for a number, a string for a string, and a bool is neither — and a key the detector does not declare is refused. Both stop analyze with exit 2 before a trace is opened, so the default decides: 16 makes a number of the parameter, *GC a string.
• A mask says so in its name. A parameter with name_glob in its name is read as a mask over slice names — by names, and by _claimed_name, which keeps repeated_work and app_init off what another detector speaks for — and names reads one with skip_glob as an exclusion. A mask named anything else still works in the query and is invisible to both.

Robustness¶

A failed detector never fails the run: the error goes to stderr and into report.json, and the rest still execute. SQL is version-fragile — failures are expected and must not cost a run.