Closed Bug 1615203 Opened 5 years ago Closed 2 years ago

Intermittent org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms

Categories

(GeckoView :: General, defect, P2)

Unspecified
All
defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=288663612&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/OqRKtz92Q8y8x8oncLM8VQ/runs/0/artifacts/public/logs/live_backing.log


[task 2020-02-13T07:33:15.106Z] 07:33:15 INFO - TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent
[task 2020-02-13T07:34:15.038Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=641
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | Error in crashParent(org.mozilla.geckoview.test.crash.ParentCrashTest):
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:235)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:43)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2020-02-13T07:34:15.040Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2020-02-13T07:34:15.048Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test |
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:235)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:43)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at java.lang.reflect.Method.invoke(Native Method)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2020-02-13T07:34:15.049Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2020-02-13T07:34:15.050Z] 07:34:15 INFO - org.mozilla.geckoview.test | at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2020-02-13T07:34:15.050Z] 07:34:15 INFO - org.mozilla.geckoview.test | at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test |
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=641
[task 2020-02-13T07:34:15.051Z] 07:34:15 INFO - org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2020-02-13T07:34:15.051Z] 07:34:15 WARNING - TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms

Would it be possible to address this issue, as this is blocking work to get performance optimizations to Android.

The blocked work (Bug 1710884) already provided, on desktop, a 9% speed-up of content process startup as well as a resident memory usage reduction between 5% to 8%. (see Bug 1709135)

Flags: needinfo?(geckoview)

6c6f5da9-bf33-4082-a19d-7d99e8083d97 Mass rename intermittents due to Bug 1723034.

Summary: Intermittent org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms → Intermittent org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms

Nicolas, could you explain how this intermittent is related to Bug 1710884? Also I don't think anybody watches geckoview@firefox-for-android.bugs, please ni me or Emily Toop for GeckoView/Android bugs in the future :)

Flags: needinfo?(geckoview)
Priority: P5 → --

This has had lots of failures recently. Resetting priority for re-triage.

Flags: needinfo?(nicolas.b.pierron)

Update:

There have been 36 failures within the last 7 days:

  • 10 failures on android-em-7-0-x86_64-lite-qr debug
  • 26 failures on Android 7.0 x86-64 WebRender debug/ debug-isolated-process

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=349347586&repo=mozilla-central&lineNumber=15636

[task 2021-08-24T04:13:30.756Z] 04:13:30     INFO -  TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent
[task 2021-08-24T04:14:30.757Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=795
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | Error in crashParent(org.mozilla.geckoview.test.crash.ParentCrashTest):
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.758Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:251)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:41)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-08-24T04:14:30.759Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2021-08-24T04:14:30.760Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2021-08-24T04:14:30.761Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.762Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2021-08-24T04:14:30.763Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.764Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2021-08-24T04:14:30.765Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test |
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.766Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.util.RuntimeCreator.shutdownRuntime(RuntimeCreator.java:251)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.setup(ParentCrashTest.kt:41)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-08-24T04:14:30.767Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:76)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.rule.ServiceTestRule$ServiceStatement.evaluate(ServiceTestRule.java:335)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
[task 2021-08-24T04:14:30.768Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.769Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:104)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:128)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.Suite.runChild(Suite.java:27)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
[task 2021-08-24T04:14:30.770Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:388)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1932)
[task 2021-08-24T04:14:30.771Z] 04:14:30     INFO -  org.mozilla.geckoview.test |
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=795
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -2
[task 2021-08-24T04:14:30.772Z] 04:14:30     INFO -  Printing logcat for test:
[task 2021-08-24T04:14:30.829Z] 04:14:30     INFO -  None
[task 2021-08-24T04:14:30.830Z] 04:14:30  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | java.lang.RuntimeException: java.util.concurrent.ExecutionException: org.mozilla.geckoview.test.util.UiThreadUtils$TimeoutException: Timed out after 60000ms
[task 2021-08-24T04:14:30.830Z] 04:14:30     INFO -  TEST-INFO took 60075ms
Whiteboard: [stockwell needswork:owner]

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #8)

Nicolas, could you explain how this intermittent is related to Bug 1710884? Also I don't think anybody watches geckoview@firefox-for-android.bugs, please ni me or Emily Toop for GeckoView/Android bugs in the future :)

Bug 1710884 adds a new File Descriptor, for shared memory, which is passed from the parent process to each child processes.

When using the patch present in Bug 1710884, I was able to constantly reproduce these timeouts, which are similar to the the one reported here.
To be precise, I have no idea whether the timeout I experienced with attachment 9221638 [details] were the same or not. I only noticed that we were taking a lot of time, even before this patch, and that my patch probably made the time trip over the nearby timeout limit.

I honestly do not know whether the approach taken in attachment 9221638 [details] is the correct way to share memory across processes on Android, and I blindly followed what was done for other shared memory pages.

Flags: needinfo?(nicolas.b.pierron)
Flags: needinfo?(agi)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

Flags: needinfo?(agi) → needinfo?(nicolas.b.pierron)
Priority: -- → P5

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

I send it to try once more, I did not noticed any more timeout being reported. On the other hand the test case org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent does not seems to be executed anymore in most configuration where it used to timeout.

The test suites gv-junit and gv-junit-e10s-single are no longer running the test case, and gv-junit-fis reports failure to instrument:

[task 2021-09-06T17:41:24.930Z] 17:41:24     INFO -  TEST-START | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent
[task 2021-09-06T17:41:24.975Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: numtests=796
[task 2021-09-06T17:41:24.975Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stream=
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | org.mozilla.geckoview.test.crash.ParentCrashTest:
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: id=AndroidJUnitRunner
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: test=crashParent
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: class=org.mozilla.geckoview.test.crash.ParentCrashTest
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: stack=org.junit.AssumptionViolatedException: got: <true>, expected: <false>
[task 2021-09-06T17:41:24.976Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.Assume.assumeThat(Assume.java:95)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.mozilla.geckoview.test.crash.ParentCrashTest.crashParent(ParentCrashTest.kt:54)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[task 2021-09-06T17:41:24.977Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at androidx.test.internal.runner.junit4.statement.UiThreadStatement$1.run(UiThreadStatement.java:55)
[task 2021-09-06T17:41:24.978Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:428)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:1950)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.os.Looper.loop(Looper.java:154)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at java.lang.reflect.Method.invoke(Native Method)
[task 2021-09-06T17:41:24.979Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test |
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS: current=796
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  org.mozilla.geckoview.test | INSTRUMENTATION_STATUS_CODE: -4
[task 2021-09-06T17:41:24.980Z] 17:41:24     INFO -  TEST-FAIL | org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent | took 47ms

Which are not reported as test suite failures.
https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Flags: needinfo?(nicolas.b.pierron)

(In reply to Nicolas B. Pierron [:nbp] from comment #15)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Apparently this bug got reproduced on this try push with the gv-junit test suite on android-em-7-0-x86_64-lite-qr opt

(In reply to Nicolas B. Pierron [:nbp] from comment #15)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

I send it to try once more, I did not noticed any more timeout being reported. On the other hand the test case org.mozilla.geckoview.test.crash.ParentCrashTest#crashParent does not seems to be executed anymore in most configuration where it used to timeout.

Oh man! What you were seeing is Bug 1729561, which I found while looking at this. The stack=org.junit.AssumptionViolatedException: got: <true>, expected: <false> is expected, it's the way we "skip" tests on Android.

(In reply to Nicolas B. Pierron [:nbp] from comment #16)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #14)

I see, do you see the same timeouts if you rebase to master? we aren't seeing this intermittent anymore from what I can tell.

If you do see them, can you link a try run?

https://treeherder.mozilla.org/jobs?repo=try&revision=40c5c5f617af8b9d4bb5ca2269cf42dffb907932

Apparently this bug got reproduced on this try push with the gv-junit test suite on android-em-7-0-x86_64-lite-qr opt

OK good. I'll see if I can guess what's the problem there.

Flags: needinfo?(agi)

I attached logging output when running the test on a local device. It seems the parent is crashing as expected, however there is still a timeout when retrieving the result.
If you have any idea how to debug further, please let me know.

mcomella brought up that this is blocking a perf fix (Bug 1618391) we should probably reprioritize.

Flags: needinfo?(agi)
Priority: P5 → --
Priority: -- → P2
Severity: normal → S3

Resolving as WFM because there have been no test failures in the last three months.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
Whiteboard: [stockwell needswork:owner]

(In reply to Chris Peterson [:cpeterson] from comment #20)

Resolving as WFM because there have been no test failures in the last three months.

Just to make sure I understand better …
Can we land Bug 1710884 without being blocked by this issue?

Flags: needinfo?(cpeterson)

(In reply to Nicolas B. Pierron [:nbp] from comment #21)

(In reply to Chris Peterson [:cpeterson] from comment #20)

Resolving as WFM because there have been no test failures in the last three months.

Just to make sure I understand better …
Can we land Bug 1710884 without being blocked by this issue?

I don't know the full details of this two-year-old bug, but if the current tests are passing with bug 1710884's IPC glue code, then you can try landing it.

Flags: needinfo?(cpeterson)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: