1568501 - talos regression on perf-reftest-singletons/bidi-resolution-1.html or (on ARM64 Windows) Perma [tier2] console.error: "You should not call finishTest without having first initted the Profiler" (from perf-reftest-singleton suite timing out)

Status: RESOLVED FIXED

(Core :: Layout: Text and Fonts, defect, P2)

Description

[Alexandru Michis [:malexandru]]

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=258042228&repo=mozilla-central&lineNumber=960

05:32:37 INFO - PID 1414 | Cycle 1(14): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/nth-index-2.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html)
05:32:38 INFO - PID 1414 | Waiting for idle-callback
05:32:39 INFO - PID 1414 | Cycle 1(15): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/nth-index-2.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html)
05:33:10 INFO - PID 1414 | __WARNTimeout (1/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__WARN
05:33:24 INFO - PID 1414 | Cycle 1(0): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:33:24 INFO - PID 1414 | Waiting for idle-callback
05:34:07 INFO - PID 1414 | Cycle 1(0): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:34:38 INFO - PID 1414 | __WARNTimeout (2/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__WARN
05:34:54 INFO - PID 1414 | Cycle 1(1): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:34:55 INFO - PID 1414 | Waiting for idle-callback
05:35:40 INFO - PID 1414 | Cycle 1(1): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:36:11 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:36:11 INFO - PID 1414 | __FAILTimeout (3/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:36:11 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:36:27 INFO - PID 1414 | Cycle 1(3): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:36:27 INFO - PID 1414 | Waiting for idle-callback
05:37:12 INFO - PID 1414 | Cycle 1(3): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:37:42 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:37:42 INFO - PID 1414 | __FAILTimeout (4/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:37:42 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:37:59 INFO - PID 1414 | Cycle 1(5): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:38:29 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:38:29 INFO - PID 1414 | __FAILTimeout (5/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:38:29 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:38:45 INFO - PID 1414 | Cycle 1(6): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:38:45 INFO - PID 1414 | Waiting for idle-callback
05:39:15 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:39:15 INFO - PID 1414 | __FAILTimeout (6/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:39:15 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:39:32 INFO - PID 1414 | Cycle 1(7): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:39:32 INFO - PID 1414 | Waiting for idle-callback
05:40:03 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:40:03 INFO - PID 1414 | __FAILTimeout (7/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:40:03 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:40:17 INFO - PID 1414 | Cycle 1(8): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:40:17 INFO - PID 1414 | Waiting for idle-callback
05:40:48 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:40:48 INFO - PID 1414 | __FAILTimeout (8/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:40:48 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:41:05 INFO - PID 1414 | Cycle 1(9): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:41:35 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL
05:41:35 INFO - PID 1414 | __FAILTimeout (9/3) exceeded on http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html__FAIL
05:41:35 INFO - PID 1414 | console.error: "You should not call finishTest without having first initted the Profiler"
05:41:50 INFO - PID 1414 | Cycle 1(10): loaded http://127.0.0.1:50086/tests/perf-reftest-singletons/bidi-resolution-1.html (next: http://127.0.0.1:50086/tests/perf-reftest-singletons/id-getter-1.html)
05:42:21 INFO - PID 1414 | __FAILTimeout in perf-reftest-singletons__FAIL

Comment 1

[Daniel Varga [:dvarga]]

:dbaron can you please take a look at this?
It seems it started after https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=258131649&searchStr=windows%2C10%2Caarch64%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-windows10-aarch64%2Fopt-talos-perf-reftest-singletons-e10s%2Ct%28ps%29&revision=57c43ac551e8a2c1f32951a3ecdddc48efac9931 got landed.

Comment 2

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

This seems like some sort of a hang in perf-reftest-singletons/bidi-resolution-1.html. Seems like a plausible regression from this patch -- though could easily be related to some existing problem in the code.

Any idea how to get access to an ARM64 windows machine (preferably one with a development environment already set up) to debug this? Who owns ARM64 Windows and would know about this?

Comment 3

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Then again, it looks like this test got a lot slower on other platforms:
https://treeherder.mozilla.org/perf.html#/graphs?series=mozilla-central,1646989,1,1&series=mozilla-central,1649907,1,1&series=mozilla-central,1649913,1,1
so presumably this is just a misreporting of a performance regression.

Comment 4

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Here's a graph of the perf regression on x86-64 Windows autoland which gives this regression range.

Comment 5

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

So this bug should also cover https://treeherder.mozilla.org/perf.html#/alerts?id=22088 -- except I can't mark it as such since I'm not a sheriff.

Comment 6

[Emilio Cobos Álvarez (:emilio)]

(In reply to David Baron :dbaron: 🏴󠁵󠁳󠁣󠁡󠁿 ⌚UTC-7 from comment #2)

Any idea how to get access to an ARM64 windows machine (preferably one with a development environment already set up) to debug this? Who owns ARM64 Windows and would know about this?

Nathan, maybe? Though if it regressed on other platforms too chances are you can just investigate the regression on your regular machine, and hopefully the fix should be cross-platform again.

Comment 7

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Yeah, it's really cross-platform; it's just that it's only orange on ARM64, so this bug got filed for that.

Comment 8

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Here's a profile.

Comment 9

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

This testcase deals with a single line that's very large. I think it's showing two hotspots where we're searching lines from the beginning rather than the end. I think one of them is this one which was something I thought about doing differently when working on bug 1566945; I don't see the other one based on looking at the profile so I'll have to drop into gdb to figure it out.

Comment 10

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

OK, the second problem is that we're nulling out mPrevFrame between every pair of calls to AdvanceToFrame. I'm actually not sure how much of that nulling out is necessary given the two-iterator setup, so I should look and see what can be eliminated.

Comment 11

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Here's a try run with what I think should fix both problems.

Comment 12

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: Bug 1568501 - Invalidate FastLineIterator::mPrevFrame only when lines actually split.

Comment 13

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Attachment: Bug 1568501 - Search from the end of the line rather than the start, like this code did before bug 1566945.

Comment 14

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

The talos run on autoland just before my push had:

[#15] bidi-resolution-1.html  Cycles:15  Average:399.23  Median:399.74  stddev:3.41 (0.9%)  stddev-sans-first:3.24
Values: 394.3  399.7  395.1  396.5  400.6  395.5  399.3  401.3  401.4  398.1  400.2  405.4  404.3  395.1  401.6

A run of the same job on try with my fixes has:

[#15] bidi-resolution-1.html  Cycles:15  Average:389.25  Median:388.14  stddev:3.79 (1.0%)  stddev-sans-first:3.92
Values: 388.1  394.0  389.5  389.9  387.3  386.9  399.3  385.4  390.9  386.6  385.6  392.4  386.6  390.0  386.1

So maybe even a little faster after all the patches? I think that's plausible.

Comment 15

[Andreea Pavel [:apavel]]

This is occurring now on integration branches on tier1:

-> Perma-fail on mozilla-central osx 10.14 on https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&resultStatus=testfailed%2Cbusted%2Cexception&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-macosx1014-64-shippable%2Fopt-talos-perf-reftest-singletons-e10s%2Ct%28ps%29

-> intermittent inbound on Linux x64 QuantumRender Shippable opt https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception&searchStr=linux%2Cx64%2Cquantumrender%2Cshippable%2Copt%2Ctalos%2Cperformance%2Ctests%2Ctest-linux64-shippable-qr%2Fopt-talos-perf-reftest-singletons-e10s%2Ct%28ps%29&group_state=expanded (bug 1568739)

-> no occurences so far on autoland.

Comment 16

[Nathan Froyd [:froydnj]]

(In reply to David Baron :dbaron: 🏴󠁵󠁳󠁣󠁡󠁿 ⌚UTC-7 from comment #2)

This seems like some sort of a hang in perf-reftest-singletons/bidi-resolution-1.html. Seems like a plausible regression from this patch -- though could easily be related to some existing problem in the code.

Any idea how to get access to an ARM64 windows machine (preferably one with a development environment already set up) to debug this? Who owns ARM64 Windows and would know about this?

The best way we have to get an ARM64 windows machine right now is "order one and expense it". You then have to set up a cross-compilation environment from your Windows desktop (which implies copying over packages, etc. to the ARM64 machine); we don't support compiling on the machines themselves. Visual Studio does install onto the ARM64 laptops, so once you've copied things over, you should be able to debug more-or-less like you would on any "normal" Windows machine.

But it sounds like the problem has been resolved in the interim anyway...?

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8b24c854efca
Invalidate FastLineIterator::mPrevFrame only when lines actually split. r=jfkthame
https://hg.mozilla.org/integration/autoland/rev/be7e1bce40d8
Search from the end of the line rather than the start, like this code did before bug 1566945. r=dholbert

Comment 18

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Here's one talos graph showing that the regression is fixed.

Comment 19

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/8b24c854efca
https://hg.mozilla.org/mozilla-central/rev/be7e1bce40d8

Comment 20

[Intermittent Failures Robot]

31 failures in 4608 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 31

Platform breakdown:

• macosx1014-64-shippable: 16
• windows10-aarch64: 15

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1568501&startday=2019-07-22&endday=2019-07-28&tree=all

Comment 21

[Ionuț Goldan [:igoldan]]

Confirming the performance fix:

== Change summary for alert #22160 (as of Fri, 26 Jul 2019 13:38:38 GMT) ==

Improvements:

100% perf_reftest bidi-resolution-1.html linux64-shippable opt e10s stylo 15,558.26 -> 12.21
98% perf_reftest_singletons bidi-resolution-1.html linux64-shippable-qr opt e10s stylo 17,668.92 -> 432.96
98% perf_reftest_singletons bidi-resolution-1.html linux64-shippable opt e10s stylo 15,946.01 -> 392.86
43% perf_reftest linux64-shippable opt e10s stylo 2.74 -> 1.56
14% perf_reftest_singletons linux64-shippable-qr opt e10s stylo 56.08 -> 48.13
14% perf_reftest_singletons linux64-shippable opt e10s stylo 53.39 -> 45.83

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=22160