Trouble understanding why `headless_shell_wpt_tests` is red on the bots

[Łukasz Anforowicz]

Hello @blink-dev,

I would appreciate help with understanding why `headless_shell_wpt_tests` step is red in my tryjobs (presumably because of my CL which enables Rust PNG via `fieldtrial_testing_config.json`?).  In https://crbug.com/395446442 I link to an example where `mac-rel` is red, and says things like "result unexpectedly crashed" or "1450 failures", but I am unable to find test logs that would show a callstack of a crash, or a specific test assertion that fails.

Did I miss something when looking at the tryjob results?  Maybe I should ask the infra team for help with this?

Best regards,

Lukasz

[Xianzhu Wang]

I believe this is an infra issue. I've moved the bug to Blink>Infra. 

--
You received this message because you are subscribed to the Google Groups "blink-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to blink-dev+...@chromium.org.
To view this discussion visit https://groups.google.com/a/chromium.org/d/msgid/blink-dev/CAA_NCUFV7MgpXgK9PgaNFBrFtqBNYAGeYWf7F3t3-iAjhCrb9w%40mail.gmail.com.

[Weizhong Xia]

Hi Lukasz

Can you check if your change has slowed down the test? I see on mac-rel the total test time for headless_shell_wpt_tests is 352 min, while the P50 now is 190 min. This is similarly true for linux-rel and win-rel.

Looking into the log I see a lot of tests timed out. Maybe that is the reason why the total test time increased a lot.

Please always feel free to reach out if you need help, :-).

thanks, Weizhong

[Łukasz Anforowicz]

On Mon, Feb 10, 2025 at 11:01 AM Weizhong Xia <weiz...@google.com> wrote:

Looking into the log I see a lot of tests timed out. Maybe that is the reason why the total test time increased a lot.

Just to double-check: Have you also looked at mac-rel step 164 ("headless_shell_wpt_tests (without patch) on Mac-14") which is red *without* my patch?  Is it also red because of test timeouts?  FWIW I see that stdout of this step reports only 2 timeouts:

$ cat stdout | grep TIMEOUT.*expected
  ▶ TIMEOUT [expected OK] external/wpt/svg/interact/scripted/focus-events.svg
  ▶ TIMEOUT [expected OK] external/wpt/compute-pressure/compute_pressure_disconnect_idempotent.https.window.html?globalScope=window

 

Can you check if your change has slowed down the test? I see on mac-rel the total test time for headless_shell_wpt_tests is 352 min, while the P50 now is 190 min. This is similarly true for linux-rel and win-rel.

There are indeed some timeouts, but much less than the "1450 failures" reported at the top of the mac-rel results.  In stdout of step 130 I see 133 timeouts:

$ cat stdout\?format\=raw | grep TIMEOUT.*expected | wc -l
grep: (standard input): binary file matches

I expect that my CL will have some impact on performance of PNG decoding and encoding.  Looking at the (Google-internal link) Finch/UMA dashboard at https://uma.googleplex.com/p/chrome/variations?sid=d8ca164209cfbd8c7cff6fd2574a03bb, I indeed see some slowdown in PNG decoding speed as reported by Renderer4.ImageDecodeTaskDurationUs.Png.Software and ImageDecoder.Png.UiGfxIntoSkBitmap.  The encoding speed seems to be neutral or improved as reported by Blink.Canvas.ToDataURLScaledDuration.PNG and Blink.Canvas.ToBlob.TotalEncodingDelay.PNG.  OTOH, so far I have not been able to reproduce the same magnitude of the slowdown in local decoding benchmarks - see https://docs.google.com/document/d/12gj3dnGyc9ZPvsu-53gTN38WneOnF_QddJ5WvsiizXg/edit?usp=sharing

Nevertheless, I do *not* expect my CL to almost double the test time.  The PNG decoding and encoding slowdown I observed in Canary trials has been surprisingly high, but it still shouldn't cause such a dramatic increase in test time, because I expect that PNG decoding/encoding time should be a small percentage of the total test runtime (at least for most tests).

I cannot repro the timeouts locally.  For example, win-rel reported a timeout in external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html; and stdout of step 130 of the massively-failing mac-rel seems to report a timeout of virtual/scalefactor200/external/wpt/css/css-backgrounds/hidpi/simple-bg-color.html.  And I can't repro the timeout in the first test on my gWindows CloudTop (I tried the second test on my gLinux CloudTop - not quite matching the bot setup but I don't have a Mac to test with.)  I also tried to measure the test duration on gWindows CloudTop with and without enabling my feature (I used `run_web_tests.bat`, because I didn't find an equivalent of `--timing` flag in the output of `run_wpt_tests.bat --help`) - the feature doesn't seem to have a big effect on the test runtime:

With my feature the average test runtime is 0.68712s:

C:\src\chromium\src>third_party\blink\tools\run_web_tests.bat -t rel external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html --iterations=10 --timing --verbose
...

[1/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.7871s
[2/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6953s
[3/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6670s
[4/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6659s
[5/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6802s
[6/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6816s
[7/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6650s
[8/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6680s
[9/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6823s
[10/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6788s
Finally stop servers and clean up

All 10 tests ran as expected in 50.72s (49.42s in rwt, 1x).

Without my feature (misspelling the `enabled_features` entry in `fieldtrial_testing_config.json` and recompiling via `autoninja -C out\rel blink_tests`) the average runtime is 0.6703s:

C:\src\chromium\src>third_party\blink\tools\run_web_tests.bat -t rel external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html --iterations=10 --timing --verbose
...

[1/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6939s
[2/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6660s
[3/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6523s
[4/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6504s
[5/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.7513s
[6/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6651s
[7/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6514s
[8/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6489s
[9/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6636s
[10/10] external/wpt/css/geometry/DOMMatrix2DInit-validate-fixup.html passed 0.6601s
Finally stop servers and clean up

All 10 tests ran as expected in 50.43s (49.13s in rwt, 1x).

Please always feel free to reach out if you need help, :-).

Thanks for taking a look! 

[Łukasz Anforowicz]

Ooops... it seems that I've sent my reply before noticing your comment on the bug from a few minutes ago.  I'll take a look.

[Weizhong Xia]

yeah, let's continue our discussion through the bug.

[Łukasz Anforowicz]

To close the loop - thanks to the feedback (i.e. pointing out that the CL causes a broad slowdown) I was able to identify the root problem: some low-level, performance-sensitive pieces of Rust standard library were getting instrumented for code coverage - see https://crbug.com/395690207 for more details. 

Thank you for your help!

[Xianzhu Wang]

Thanks Weizhong for analyzing the bug.

Fwiw, web test results.html has a timing stats feature (in the top-right corner). You can compare the timing stats with patch and without patch locally to see if the patch causes web test performance issues, even if you can't reproduce the timeouts.