Bound the JVM suite's hangs so a deadlock ends in minutes with a stack #127

Merged
JMR-dev merged 4 commits from test/bound-the-hangs into main 2026-08-26 05:21:48 +00:00
JMR-dev commented 2026-08-26 04:35:46 +00:00 (Migrated from github.com)

Bounds the JVM half of the two hangs. Refs #125, and Refs #122 for the
half deliberately not done — both stay open, neither is diagnosed here.

What was wrong

Neither suite had a timeout, so both hangs ran until something external gave up.
#125 is a real lock-order inversion between Room's TransactionExecutor and
WorkManager's SerialExecutorImpl; one local run sat in it for 47 minutes, and
on CI it would burn the Unit tests job's cap (30 minutes, not 60) and report
as a job timeout with no cause.

The mechanism, and why not the obvious one

A JUnit Timeout runs the test body on a separate thread, and this source set is
thread-affine. Measured both forms against a createComposeRule() Robolectric
test:

java.lang.UnsupportedOperationException: main looper can only be controlled from main thread
	at org.robolectric.shadows.ShadowPausedLooper.executeOnLooper(ShadowPausedLooper.java:761)
	at org.robolectric.android.internal.RoboMonitoringInstrumentation.runOnMainSync(...)
	at androidx.compose.ui.test.RobolectricIdlingStrategy.runUntilIdle(...)

@Rule Timeout and @Test(timeout = 30_000) both fail this way; the identical
two tests with the timeout removed pass, so it is the mechanism and not the
probe. That rules out anything that moves a test off its own thread.

So the bound comes from outside the test JVM: timeout on the Test tasks, plus
a watchdog that jstacks the forked worker two minutes before the kill. The jstack
is the valuable half — Gradle's timeout kills silently, and the JVM's own
deadlock report is the only reason #125 could be described at all. It prints to
stdout as well as to build/reports/hang/, because the Unit tests job uploads
only app/build/reports/tests/.

Proof that it fires

A throwaway test reproducing #125's shape — two monitors taken in opposite
orders, which is not interruptible, unlike a latch — with the bound
temporarily at 2 min / 45 s:

> Task :app:testDebugUnitTest
:app:testDebugUnitTest is still running after 0 minutes and is about to be timed out.
Thread dump of pid 833327 ... look for 'Found one Java-level deadlock' (that is #125).

> Task :app:testDebugUnitTest FAILED
Requesting stop of task ':app:testDebugUnitTest' as it has exceeded its configured timeout of 2m.
...
* What went wrong:
Execution failed for task ':app:testDebugUnitTest' (registered by plugin 'com.android.internal.application').
> Timeout has been exceeded

BUILD FAILED in 2m 6s

and the dump it left:

Found one Java-level deadlock:
=============================
"SDK 36 Main Thread":
  waiting to lock monitor 0x00007f66612372b0 (object 0x00000000e5200000, a java.lang.Object),
  which is held by "Thread-8"
...
"SDK 36 Main Thread":
	at org.libremediaconverter.probe.HangProbeTest.aLockOrderInversionThatTheJvmItselfCallsADeadlock(HangProbeTest.kt:38)
	- waiting to lock <0x00000000e5200000> (a java.lang.Object)
	- locked <0x00000000e5200010> (a java.lang.Object)

The probes are deleted. A latch-shaped hang was run for comparison and is bounded
identically, with the blocked frame named but no deadlock section — as expected,
since a latch is not one.

No XML is written for a class that hangs, so the dump is that test's only
attribution. That is what makes the watchdog the load-bearing half.

The number

10 minutes, against the slowest observed pass rather than the typical one:
eight CI samples of the whole ./gradlew :app:testDebugUnitTest invocation on
2026-08-26 were 62, 76, 77, 79, 81, 84, 86 and 90 s, with this task a subset of
that. ~6.7x the slowest, and a third of the job's 30-minute cap so a fired
timeout still has room to report. HangBoundTest pins it to 3..29 minutes in
both directions — a later "fix the flakiness" bump past the job cap goes red.

Healthy runs are unchanged

454 tests / 0 failures before, 456 / 0 after — the two added HangBoundTest
cases and nothing else. No hang report is produced on a green run.

Why #122 is argued rather than coded

The instrumented half is deliberately not attempted, and the full argument
with its measurements is in
this comment.
In short:

  1. The obvious mechanism (timeout_msec / @Test(timeout=)) is the one just
    measured to break this library stack on the JVM. The failing assertion is
    Robolectric-only, so it neither condemns nor clears the device path — which is
    the problem: unresolvable from here, and the cost of being wrong is the
    rotation test failing on every gating leg.
  2. The mechanism that would fit — a watchdog TestRule that self-SIGQUITs and
    halts, without moving a thread — cannot be shown to fire: the instrumented
    suite does not run on this host (a VirtualBox VM holds VT-x).
  3. The leg-level bound that already exists is correctly sized. Measured the exact
    thing WEDGE_TIMEOUT wraps across twelve passing gating legs: slowest 292
    s
    , so 1200 s is 4.1x headroom. Lowering it moves toward the trap, not
    away from it.

tasks.withType<Test>() does not match connectedDebugAndroidTest — it is a
DeviceProviderInstrumentTestTask, not a Test — so nothing in this PR reaches
the instrumented legs.

Bounds the JVM half of the two hangs. **Refs #125**, and **Refs #122** for the half deliberately not done — both stay open, neither is diagnosed here. ## What was wrong Neither suite had a timeout, so both hangs ran until something external gave up. #125 is a real lock-order inversion between Room's `TransactionExecutor` and WorkManager's `SerialExecutorImpl`; one local run sat in it for 47 minutes, and on CI it would burn the Unit tests job's cap (**30** minutes, not 60) and report as a job timeout with no cause. ## The mechanism, and why not the obvious one A JUnit `Timeout` runs the test body on a separate thread, and this source set is thread-affine. Measured both forms against a `createComposeRule()` Robolectric test: ``` java.lang.UnsupportedOperationException: main looper can only be controlled from main thread at org.robolectric.shadows.ShadowPausedLooper.executeOnLooper(ShadowPausedLooper.java:761) at org.robolectric.android.internal.RoboMonitoringInstrumentation.runOnMainSync(...) at androidx.compose.ui.test.RobolectricIdlingStrategy.runUntilIdle(...) ``` `@Rule Timeout` and `@Test(timeout = 30_000)` both fail this way; the identical two tests with the timeout removed pass, so it is the mechanism and not the probe. That rules out anything that moves a test off its own thread. So the bound comes from outside the test JVM: `timeout` on the `Test` tasks, plus a watchdog that jstacks the forked worker two minutes before the kill. The jstack is the valuable half — Gradle's timeout kills silently, and the JVM's own deadlock report is the only reason #125 could be described at all. It prints to stdout as well as to `build/reports/hang/`, because the Unit tests job uploads only `app/build/reports/tests/`. ## Proof that it fires A throwaway test reproducing #125's shape — two monitors taken in opposite orders, which is **not** interruptible, unlike a latch — with the bound temporarily at 2 min / 45 s: ``` > Task :app:testDebugUnitTest :app:testDebugUnitTest is still running after 0 minutes and is about to be timed out. Thread dump of pid 833327 ... look for 'Found one Java-level deadlock' (that is #125). > Task :app:testDebugUnitTest FAILED Requesting stop of task ':app:testDebugUnitTest' as it has exceeded its configured timeout of 2m. ... * What went wrong: Execution failed for task ':app:testDebugUnitTest' (registered by plugin 'com.android.internal.application'). > Timeout has been exceeded BUILD FAILED in 2m 6s ``` and the dump it left: ``` Found one Java-level deadlock: ============================= "SDK 36 Main Thread": waiting to lock monitor 0x00007f66612372b0 (object 0x00000000e5200000, a java.lang.Object), which is held by "Thread-8" ... "SDK 36 Main Thread": at org.libremediaconverter.probe.HangProbeTest.aLockOrderInversionThatTheJvmItselfCallsADeadlock(HangProbeTest.kt:38) - waiting to lock <0x00000000e5200000> (a java.lang.Object) - locked <0x00000000e5200010> (a java.lang.Object) ``` The probes are deleted. A latch-shaped hang was run for comparison and is bounded identically, with the blocked frame named but no deadlock section — as expected, since a latch is not one. **No XML is written for a class that hangs**, so the dump is that test's only attribution. That is what makes the watchdog the load-bearing half. ## The number 10 minutes, against the slowest observed **pass** rather than the typical one: eight CI samples of the whole `./gradlew :app:testDebugUnitTest` invocation on 2026-08-26 were 62, 76, 77, 79, 81, 84, 86 and 90 s, with this task a subset of that. ~6.7x the slowest, and a third of the job's 30-minute cap so a fired timeout still has room to report. `HangBoundTest` pins it to 3..29 minutes in both directions — a later "fix the flakiness" bump past the job cap goes red. ## Healthy runs are unchanged 454 tests / 0 failures before, **456 / 0** after — the two added `HangBoundTest` cases and nothing else. No hang report is produced on a green run. ## Why #122 is argued rather than coded The instrumented half is deliberately **not** attempted, and the full argument with its measurements is in [this comment](https://github.com/JMR-dev/LibreMediaConverter/pull/127#issuecomment-5420659582). In short: 1. The obvious mechanism (`timeout_msec` / `@Test(timeout=)`) is the one just measured to break this library stack on the JVM. The failing assertion is Robolectric-only, so it neither condemns nor clears the device path — which is the problem: unresolvable from here, and the cost of being wrong is the rotation test failing on every gating leg. 2. The mechanism that *would* fit — a watchdog `TestRule` that self-SIGQUITs and halts, without moving a thread — cannot be shown to fire: the instrumented suite does not run on this host (a VirtualBox VM holds VT-x). 3. The leg-level bound that already exists is correctly sized. Measured the exact thing `WEDGE_TIMEOUT` wraps across twelve passing gating legs: slowest **292 s**, so 1200 s is **4.1x** headroom. Lowering it moves toward the trap, not away from it. `tasks.withType<Test>()` does not match `connectedDebugAndroidTest` — it is a `DeviceProviderInstrumentTestTask`, not a `Test` — so nothing in this PR reaches the instrumented legs.
JMR-dev commented 2026-08-26 04:36:12 +00:00 (Migrated from github.com)

Why #122 is not bounded here

Refs #122. The instrumented half is deliberately left alone. Three findings,
in the order that decided it.

1. The obvious mechanism is the one just measured to break this library stack.
timeout_msec and @Test(timeout=) both go through JUnit's FailOnTimeout,
which runs the body on a spawned thread. On the JVM that is a hard failure
against createComposeRule() — quoted in the PR body. SafPickerRoundTripTest
uses createAndroidComposeRule plus UiAutomator, and @Test(timeout=) sits
inside the rules, so the compose rule's runTest would stay on the test thread
while the body ran on another — exactly the split that failed.

The failing assertion is Robolectric's own ShadowPausedLooper, which does not
exist on a device, so this does not condemn the on-device path. That is the
point: it is unresolvable from here, and the failure mode if it is wrong is the
rotation test failing on every API 33-36 gating leg, which the brief forbids.

2. The mechanism that would fit cannot be proven here. A TestRule that
starts a watchdog thread, self-SIGQUITs on expiry (android.os.Process.sendSignal (Process.myPid(), 3)) and then halts would bound it without moving a thread —
and self-signalling fixes #122's kill: 6473: Operation not permitted, which was
adb shell signalling another uid, not a process signalling itself. But its
firing cannot be demonstrated: the instrumented suite does not run on this host
(a VirtualBox VM holds VT-x, every AVD dies with KVM: entry failed, hardware error 0x0), and one green CI matrix is not a fired-bound proof for a 1-in-N
hang. Shipping unfired machinery into four gating legs on reasoning alone is the
speculative whole the brief warns against.

3. The leg-level bound that already exists is correctly sized, so lowering it
would move toward the trap, not away from it.
Measured the exact thing
WEDGE_TIMEOUT wraps — the gradle client, from the E2E step logs of three runs,
twelve passing gating legs:

API 32928818278 32928000548 32924660057
33 4m 52s 4m 5s 3m 53s
34 4m 5s 3m 8s 4m 20s
35 4m 9s 4m 3s 3m 10s
36 4m 10s 3m 30s 4m 30s

Slowest observed pass 292 s; WEDGE_TIMEOUT=1200 is 4.1x that. For
comparison, the JVM bound in this PR is 6.7x. Halving it to 600 s would leave
2.1x on a runner whose spread here is already 3m 8s to 4m 52s.

So what #122 still needs is a per-test bound, and per-test is precisely the
thing that cannot be added from this host without guessing. Task.timeout on
connectedDebugAndroidTest is not an answer either — e2e-run.sh's timeout -k 30s 1200 already bounds the gradle client, and both CI and
tools/local-emulator/run-e2e.sh go through it.

Named exemptions

  • Nothing instrumented was changed, so nothing instrumented was verified beyond
    compileDebugAndroidTestKotlin.
  • The watchdog's jstack path is exercised locally on Linux/JDK 25 only. On CI it
    is guarded by jstack.canExecute() and writes a note instead if absent;
    setup-java installs a full temurin JDK, so it should be there, but that is
    reasoning, not a measurement.
  • The 1-in-2 local reproduction of #125 itself was not attempted. The bound was
    proven against a synthetic deadlock of the same shape, which is stronger for
    this purpose: it fires every time.
## Why #122 is not bounded here **Refs #122.** The instrumented half is deliberately left alone. Three findings, in the order that decided it. **1. The obvious mechanism is the one just measured to break this library stack.** `timeout_msec` and `@Test(timeout=)` both go through JUnit's `FailOnTimeout`, which runs the body on a spawned thread. On the JVM that is a hard failure against `createComposeRule()` — quoted in the PR body. `SafPickerRoundTripTest` uses `createAndroidComposeRule` plus UiAutomator, and `@Test(timeout=)` sits *inside* the rules, so the compose rule's `runTest` would stay on the test thread while the body ran on another — exactly the split that failed. The failing assertion is Robolectric's own `ShadowPausedLooper`, which does not exist on a device, so this does **not** condemn the on-device path. That is the point: it is unresolvable from here, and the failure mode if it is wrong is the rotation test failing on **every** API 33-36 gating leg, which the brief forbids. **2. The mechanism that would fit cannot be proven here.** A `TestRule` that starts a watchdog thread, self-SIGQUITs on expiry (`android.os.Process.sendSignal (Process.myPid(), 3)`) and then halts would bound it without moving a thread — and self-signalling fixes #122's `kill: 6473: Operation not permitted`, which was `adb shell` signalling *another* uid, not a process signalling itself. But its firing cannot be demonstrated: the instrumented suite does not run on this host (a VirtualBox VM holds VT-x, every AVD dies with `KVM: entry failed, hardware error 0x0`), and one green CI matrix is not a fired-bound proof for a 1-in-N hang. Shipping unfired machinery into four gating legs on reasoning alone is the speculative whole the brief warns against. **3. The leg-level bound that already exists is correctly sized, so lowering it would move toward the trap, not away from it.** Measured the exact thing `WEDGE_TIMEOUT` wraps — the gradle client, from the E2E step logs of three runs, twelve passing gating legs: | API | 32928818278 | 32928000548 | 32924660057 | |---|---|---|---| | 33 | 4m 52s | 4m 5s | 3m 53s | | 34 | 4m 5s | 3m 8s | 4m 20s | | 35 | 4m 9s | 4m 3s | 3m 10s | | 36 | 4m 10s | 3m 30s | 4m 30s | Slowest observed pass **292 s**; `WEDGE_TIMEOUT=1200` is **4.1x** that. For comparison, the JVM bound in this PR is 6.7x. Halving it to 600 s would leave 2.1x on a runner whose spread here is already 3m 8s to 4m 52s. **So what #122 still needs is a per-test bound**, and per-test is precisely the thing that cannot be added from this host without guessing. `Task.timeout` on `connectedDebugAndroidTest` is not an answer either — `e2e-run.sh`'s `timeout -k 30s 1200` already bounds the gradle client, and both CI and `tools/local-emulator/run-e2e.sh` go through it. ### Named exemptions - Nothing instrumented was changed, so nothing instrumented was verified beyond `compileDebugAndroidTestKotlin`. - The watchdog's jstack path is exercised locally on Linux/JDK 25 only. On CI it is guarded by `jstack.canExecute()` and writes a note instead if absent; `setup-java` installs a full temurin JDK, so it should be there, but that is reasoning, not a measurement. - The 1-in-2 local reproduction of #125 itself was not attempted. The bound was proven against a synthetic deadlock of the same shape, which is stronger for this purpose: it fires every time.
Sign in to join this conversation.