Advice on debugging a layout test that seems to be hanging after completion?

[Dale Curtis]

I have a testharness.js layout test which uses throttled network loading and tends to complete in ~2 seconds, but after ~26-28 iterations it starts taking >> 2 seconds; timing out frequently on Mac without a SlowTest suppression and sometimes even with.

Logging seems to indicate that the test has completed, but the layout test runner isn't tearing down for some reason.

Test w/ debugging logs enabled:

https://chromium-review.googlesource.com/#/c/chromium/src/+/907221

Good run:

https://chromium-review.googlesource.com/c/chromium/src/+/907221/2/good.txt

Bad run:

https://chromium-review.googlesource.com/c/chromium/src/+/907221/2/bad.txt

I know the test is completing because I can see testharness.js replace the body content via HTMLMediaElement::removedFrom(). There then seems to be something blocking content::BrowserMainRunner::Run() from completing though. I've tried --trace-startup but that doesn't seem to work with layout tests.

I'm unclear on what could stall browser shutdown like this, but it feels like a thread worth tugging on in case this is a real issue somewhere.

Any and all advice welcome. Thanks in advance!

- dale

$ ./blink/tools/run_layout_tests.py --no-retry-failures http/tests/media/media-src-suspend-after-have-future-* --exit-after-n-failures=1 --repeat-each=100 -f --timing --verbose

[1/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.9929s

[2/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.9942s

[3/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.1590s

[4/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.1652s

[5/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.1743s

[6/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 2.1884s

<...>

[28/100] http/tests/media/media-src-suspend-after-have-future-data.html passed 12.1446s

[Dale Curtis]

I got a bit further, it seems the ShellViewHostMsg_TestFinished message is not arriving in a timely fashion... I.e. in the log below it's sent at 174059.066629 but doesn't arrive until 174109.090258, or ~10 seconds later. Still digging into why.

ERR: [69204:775:0207/174059.066483:ERROR:blink_test_runner.cc(766)] CaptureDump\n

ERR: [69204:775:0207/174059.066532:ERROR:blink_test_runner.cc(789)] DUMP NOW\n

ERR: [69204:775:0207/174059.066590:ERROR:layout_dump.cc(92)] DumpLayout: 4.4e-05 s\n

ERR: [69204:775:0207/174059.066629:ERROR:blink_test_runner.cc(856)] CaptureDumpComplete\n

<...>

ERR: [69200:775:0207/174109.090258:ERROR:blink_test_controller.cc(775)] OnTestFinished\n

[srirama chandra sekhar]

Looking at the logs in bad.txt, after the 2nd "OnPipelineSuspended" log there is some activity still going on (ReadTask, OnProgress ....). By any chance are these coming after "CaptureDumpComplete" and blocking the msg to be delivered?

[Dale Curtis]

This turned out to be a call into CoreAudio API blocking the main thread for > 10 seconds. Issue filed here:

https://bugs.chromium.org/p/chromium/issues/detail?id=811525

The reason startup tracing didn't work is that you must wait for your specified --trace-duration to elapse or no log file will be generated. I'll add a comment to the flag about this so it's clearer for future folks. Figuring out where we should call BrowserMainLoop::EndStartupTracing() if it terminates before running is hard for layout tests since they run the main loop multiple times, but don't go through the normal shutdown path.

- dale

--
You received this message because you are subscribed to the Google Groups "blink-dev" group.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/blink-dev/ab06b498-dc35-4849-895c-f64904074761%40chromium.org.

[Dale Curtis]

To close the loop, as of https://chromium.googlesource.com/chromium/src/+/4c163bf47195d39e40fa2dbe78cbf8d7c6d62ab3, when you specify --trace-startup or --trace-shutdown to layout tests, we'll go through the clean shutdown path.

- dale