The trace is a database: anatomy of a 14 ms lock wait

31 Aug 2026 · aospperfettotracinginputsystem-servercuttlefish

There’s a two-line trick for measuring lock contention on Android, and once you know it you start leaving it everywhere. Take a lock the framework fights over — say mGlobalLock, the ActivityTaskManager/WindowManager global lock — and bracket one acquisition of it with a trace slice. In frameworks/base/services/core/java/com/android/server/wm/ActivityStarter.java:795, the funnel that every activity launch on the device passes through:

Trace.traceBegin(Trace.TRACE_TAG_WINDOW_MANAGER, "lockwait:executeRequest");
synchronized (mService.mGlobalLock) {
    Trace.traceEnd(Trace.TRACE_TAG_WINDOW_MANAGER);
    // ... original body, unchanged ...
}

Note where the traceEnd sits: inside the block, as its first statement. The slice therefore ends the instant the monitor is acquired, so its duration is purely the time this thread stood in line — not the work done while holding the lock. Rebuild (m services), adb sync, reboot, capture a trace with the wm category enabled, and every activity start now leaves a lockwait:executeRequest slice whose duration answers “how long did this launch wait for the biggest lock in system_server?”

In the Perfetto UI this is lovely. Search for the slice, click it, read the duration. For the five activity starts in my trace, clicking is a perfectly good analysis method.

Then I did the same thing to a C++ lock, and clicking stopped being an analysis method.

The same trick, three lines at a time

system_server is mostly Java, but not entirely — the input pipeline’s two native threads, InputReader and InputDispatcher, live inside it. The dispatcher guards everything it owns with a single std::mutex (InputDispatcher.h:182), acquired by its own thread on every dispatch cycle, by InputReader delivering events, by binder threads injecting events or moving the focus, and by the thread that delivers window layout updates. One lock, five kinds of traffic. InputDispatcher.cpp already sets ATRACE_TAG_INPUT, so the native version of the trick costs three lines — here at the top of dispatchOnce() (InputDispatcher.cpp:1006):

{ // acquire lock
    ATRACE_BEGIN("lockwait:dispatchOnce");
    std::scoped_lock _l(mLock);
    ATRACE_END();
    ATRACE_NAME("lockhold:dispatchOnce");
    // ... original body, unchanged ...
}

Same shape as the Java version — begin, acquire, end — plus one extra: ATRACE_NAME is scoped, so lockhold:dispatchOnce covers the rest of the block and records how long the dispatcher keeps the lock once it has it. Wait slices tell you who suffers; hold slices tell you who to blame. You want both, at least on the thread you suspect.

I planted the wait probe at four more acquisitions: notifyMotion() (the path real touchscreen events take, via InputReader), both branches of injectInputEvent() (the path adb shell input takes, on binder threads), and onWindowInfosChanged() (window layout updates). Where the code says mLock.lock() instead of a scoped lock, the probe is the same two macros around one line. Rebuild both halves and push:

m services libinputflinger
adb root && adb remount && adb sync system && adb reboot

The tags matter: TRACE_TAG_WINDOW_MANAGER records only when the wm category is enabled at capture time, ATRACE_TAG_INPUT only under input. Categories off, both probes cost nanoseconds — which is why the platform can afford to ship instrumented everywhere, always.

One workload, three doors into the dispatcher

Everything below is android-15.0.0_r36 on the same Cuttlefish as the boot post — aosp_cf_x86_64_auto-userdebug, two vCPUs, one 1080×600 display. One 30-second trace:

adb shell perfetto -o /data/misc/perfetto-traces/locks.pftrace -t 30s -b 128mb \
    -a '*' am wm view gfx input sched freq idle binder_driver

While it ran: two cold launches (car Settings, 470 ms; KitchenSink, 279 ms), one warm relaunch, and two bursts of overlapping adb shell input swipe commands — deliberately in parallel, so several binder threads inject motion streams at once. Plus one gesture through a door most people forget exists: a finger drawn directly on the virtual touchscreen with sendevent on /dev/input/event2, forty MOVE events written into the evdev node the way real hardware would deliver them. (Two traps: the injected input swipe path never touches evdev at all — my first capture had zero notifyMotion slices until I realized adb shell input is a binder call into system_server, not a synthetic touch — and SELinux denies the shell domain write access to /dev/input/*, so the raw drag needs adb root.)

The trace is a database

The result is a 15 MB file containing 161,246 slices with 11,727 distinct names. My probes alone contributed 998 wait slices. Nobody clicks through that; the UI’s search box finds a slice, not the pattern.

The tool for patterns ships as a single static binary — the same engine that powers the UI’s Query (SQL) page, so everything below also runs in the browser:

curl -LO https://get.perfetto.dev/trace_processor
chmod +x trace_processor
./trace_processor -q census.sql locks.pftrace

The schema’s core is one table: slice(ts, dur, name, track_id, ...), timestamps in nanoseconds. Which thread a slice ran on is two joins away (slice → thread_track → thread → process), and because everyone needs those joins, the standard library packages them: INCLUDE PERFETTO MODULE slices.with_context gives you thread_slice, which is slice plus thread_name, process_name, utid. First question — what did my probes actually record:

INCLUDE PERFETTO MODULE slices.with_context;
SELECT name, COUNT(*) AS n,
       CAST(AVG(dur) AS INT)     AS avg_ns,
       CAST(MAX(dur)/1e3 AS INT) AS max_us
FROM thread_slice
WHERE name GLOB 'lockwait:*' OR name GLOB 'lockhold:*'
GROUP BY name ORDER BY name;

The census already settles several questions. The famous WM global lock? Five activity starts went through executeRequest — three on binder threads carrying an am start, two on android.display — and none waited more than 14 µs. On this idle-ish device, the scariest lock in system_server is free. The evdev door? Forty-one notifyMotion calls, worst case 1 µs: the reader→dispatcher handoff is tuned so that real input essentially never queues. The window-update and dispatcher-self acquisitions top out around a quarter millisecond.

And then there’s injection, where the average is pulled to 325 µs by something ugly in the tail. Averages hide tails; ask for the distribution:

SELECT COUNT(*) AS n,
  CAST(MAX(CASE WHEN pct <= 0.50 THEN us END) AS INT) AS p50_us,
  CAST(MAX(CASE WHEN pct <= 0.95 THEN us END) AS INT) AS p95_us,
  CAST(MAX(CASE WHEN pct <= 0.99 THEN us END) AS INT) AS p99_us,
  CAST(MAX(us) AS INT) AS max_us
FROM (SELECT dur/1e3 AS us, PERCENT_RANK() OVER (ORDER BY dur) AS pct
      FROM slice WHERE name = 'lockwait:injectInputEvent');

n=280   p50=0 µs   p95=1,574 µs   p99=5,405 µs   max=14,032 µs

The median injector walks straight in. The 99th percentile waits five milliseconds, and one binder thread stood in line for 14 milliseconds — in input terms, a full frame of latency, spent entirely on one mLock.lock() call. That slice is the rest of this post.

The obvious suspect is acquitted

I had a theory before I had data (always dangerous): the dispatcher’s own holds must be the problem. The census supports it — lockhold:dispatchOnce runs up to 3 ms while the dispatcher processes queued events. So: how many of the long waits actually overlap a dispatcher hold? In SQL, “A blocked B” is just an interval intersection:

INCLUDE PERFETTO MODULE slices.with_context;
SELECT
  (SELECT COUNT(*) FROM slice
    WHERE name GLOB 'lockwait:*' AND dur > 500000) AS long_waits,
  COUNT(DISTINCT w.id) AS overlapping_a_dispatcher_hold
FROM thread_slice w
JOIN thread_slice h ON h.name = 'lockhold:dispatchOnce'
 AND h.ts < w.ts + w.dur AND h.ts + h.dur > w.ts AND h.utid != w.utid
WHERE w.name GLOB 'lockwait:*' AND w.dur > 500000;

long_waits=27   overlapping_a_dispatcher_hold=1

Twenty-seven waits longer than half a millisecond; exactly one of them ever coexisted with a dispatcher hold, and adding up the actual intersection for that one comes to about a microsecond. The dispatcher did not block anybody. My theory was dead in one query — which is precisely the thing clicking around a timeline never does for you. The UI shows you what you look at; the query answers over all the evidence, including the evidence that ruins your story.

Cross-examining 14 milliseconds

So who was the lock going to, if not the dispatcher? Every lockwait slice ends at the moment its thread wins the lock. That means acquisitions are already in the data — take the longest wait’s window and list everyone else who acquired inside it:

INCLUDE PERFETTO MODULE slices.with_context;
SELECT CAST((s.ts + s.dur - w.ts)/1e6 AS REAL) AS at_ms,
       s.thread_name, CAST(s.dur/1e3 AS INT) AS their_wait_us
FROM thread_slice s,
     (SELECT ts, dur FROM slice WHERE name = 'lockwait:injectInputEvent'
      ORDER BY dur DESC LIMIT 1) w
WHERE s.name GLOB 'lockwait:*'
  AND s.ts + s.dur BETWEEN w.ts AND w.ts + w.dur
  AND NOT (s.ts = w.ts AND s.dur = w.dur)
ORDER BY at_ms;

While binder:772_E stood in line, binder:772_13 — another of my parallel swipe injectors — took the lock twice, waiting zero microseconds each time. std::mutex on bionic, like nearly every mutex you’ll ever use, makes no fairness promise: a thread that shows up at an unlocked mutex takes it immediately, even if others have been asleep in the futex queue for milliseconds. It’s called barging, it’s deliberate (handing a lock to a sleeping thread costs a wake-up round-trip), and here it is in a table.

But barging is only half the verdict. What was our waiter doing for 14 ms? The sched category recorded every state of every thread, and thread_state even keeps who woke it:

SELECT CAST((st.ts - w.ts)/1e6 AS REAL) AS at_ms, st.state,
       CAST(st.dur/1e3 AS INT) AS dur_us, wt.name AS woken_by
FROM thread_state st
LEFT JOIN thread wt ON st.waker_utid = wt.utid,
     (SELECT s.ts, s.dur, tt.utid AS waiter FROM slice s
      JOIN thread_track tt ON s.track_id = tt.id
      WHERE s.name = 'lockwait:injectInputEvent'
      ORDER BY s.dur DESC LIMIT 1) w
WHERE st.utid = w.waiter
  AND st.ts < w.ts + w.dur AND st.ts + st.dur > w.ts
ORDER BY st.ts;

Read the two tables together and the whole crime is on the record. The waiter sleeps 3.5 ms; 772_13 releases the lock and wakes it — then, while the woken thread waits 5.4 ms for one of this device’s two vCPUs, 772_13 circles back and re-takes the lock without waiting at all. Our thread finally gets 6 µs of CPU, finds the mutex taken again, and goes back to sleep for another 4.4 ms until 772_6 (which had itself waited 10.9 ms) releases and wakes it. This time it only sits runnable for 0.7 ms before it gets a core and wins.

Total: 7.9 ms genuinely asleep waiting for the lock, 6.2 ms runnable but starved of CPU, 111 µs actually running. Nearly half of my “14 ms lock wait” was never about the lock — it was two overcommitted vCPUs. A lockwait slice measures wall time, and wall time on a busy machine is a sum of stories; thread_state is the table that itemizes them. If I’d filed a bug titled “input injection blocks 14 ms on InputDispatcher::mLock,” it would have been a third true, a third mutex-fairness physics, and a third my own test rig’s CPU budget.

What the queries bought

The UI stays the right tool for orientation — you scrub, you recognize shapes, you form hypotheses. But every hypothesis I formed today was settled by a query: how many, how bad at the tail, who overlapped whom, who woke whom. Two of the three verdicts contradicted what the timeline seemed to show, and one query acquitted the thread I’d already convicted. Slice-clicking produces anecdotes. The database produces counts, distributions, and joins across evidence the UI never draws next to each other — a trace slice and a scheduler state, ten pixels and three tables apart.

Reading list

• frameworks/native/services/inputflinger/dispatcher/InputDispatcher.cpp:1006 — dispatchOnce(), the lock’s busiest customer; :4826 is injectInputEvent(), the tail’s victim.
• frameworks/base/services/core/java/com/android/server/wm/ActivityStarter.java:795 — execute(), where the Java probe goes.
• Perfetto: Trace Processor — the -q batch mode, the interactive shell, and the data model.
• PerfettoSQL standard library — slices.with_context and friends; most joins you’re about to write by hand already exist here.
• The previous post, on Android’s boot sequence, measured the same device with system properties instead of a trace — the poor man’s version of exactly this workflow.