A mochitest timeout that was really a 14-millisecond cross-process race

browser_creditCard_telemetry_manage.js failed every time on Windows when the test ran with the Gecko profiler enabled (MOZ_PROFILER_STARTUP=1), reporting test_histogram - Test timed out. The same test was already ~5% intermittent on Windows without the profiler. A startup profile of one failing run was attached, so I went looking for what the test was waiting on.

It’s a wait, not a spin

The first instinct with a “hang” is to find the thread pegged at 100% doing the wrong thing. This was the opposite. The profile was 49 seconds long — exactly a harness timeout — and the aggregate CPU activity tapered off after about 12 seconds and then flatlined. (The per-thread CPU column read 0.000ms for everything, which is just a missing-data artifact of this capture; it nearly fooled me into thinking I had no signal.)

Selecting the parent-process GeckoMain — the thread the mochitest driver runs on, not the WebExtensions thread the daemon picked by default — and sampling with idle included told the real story: 88.8% of wall-clock was parked in nsAppShell::ProcessNextNativeEvent::Wait. The test wasn’t doing anything. It was blocked on an event that never came. From that point the question changed from “what is slow” to “what is it waiting for, and why does that thing never happen.”

The gap names the culprit

Mochitests narrate themselves through INFO/Test markers, and the harness drops a TEST-UNEXPECTED-FAIL | Test timed out marker when it gives up. Listing the test markers showed a clean wall: the last meaningful one was focus on element (id=cc-number) at 12.825s, then 36 seconds of dead air until the timeout at 49.229s. The marker stack for the timeout itself was just setTimeout → TimeoutExecutor — the harness alarm, not the bug. The bug was wherever “focus on element” left the test stuck.

That marker is logged by focusUpdateSubmitForm in the formautofill test head.js, which focuses the field and then awaits a fieldsIdentifiedPromise that only resolves when the content process sends a FieldsIdentified notification. The next step, “submit form”, never logged. So the content process never sent the message.

Two processes, one timeline

The active tab’s content process was the one sitting at Process Priority: FOREGROUND. Its markers around 12.8s showed the focus landing on #cc-number at 12.824s, a clearFillOnFormChangeTimeoutID timer firing at 12.838s, and then nothing but idle housekeeping. A search for FieldsIdentified anywhere on that thread came up empty — the notification was genuinely never sent.

Lining the two processes up on one timeline made the 14-millisecond gap obvious. After an autofill, FormAutofillChild opens a “dynamic form change” window and, by design, suppresses field identification for any focus that lands inside it. The test waits out that window with its own timer before focusing — but the test’s timer lives in the parent and the suppression window’s clear-timer lives in content, both around 1000 ms, anchored at slightly different moments. The focus arrived 14 ms before the content cleared the window, so identification was suppressed, no FieldsIdentified was sent, and the parent waited forever.

That explained everything: a near-tie race that normally loses ~5% of the time, and that the profiler’s per-sample overhead in the content process tips consistently to the losing side — hence the perma-fail under MOZ_PROFILER_STARTUP=1. The fix was to disable the heuristic in the tests that don’t exercise it (which also let us delete the now-pointless 1 s wait, speeding the tests up) and re-enable the test on all platforms.

What made this fast

  • Sampling the right thread with idle included immediately classified it as a deadlock and saved me from chasing hot functions that didn’t exist.

  • The last marker before the dead air pointed straight at the offending line of test code.

  • Cross-process timestamp correlation was the only thing that could expose a 14 ms race — no single thread’s view contains it. That technique generalizes to any “event that never fired” timeout.