1559761 - Intermittent devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js | Test timed out -

Status: RESOLVED FIXED

(DevTools :: Debugger, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=252155714&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/UkWheGB5T9a8JRztL2od1g/runs/0/artifacts/public/logs/live_backing.log

---

08:56:29 INFO - GECKO(1080) | [Child 3104, Main Thread] WARNING: NS_ENSURE_SUCCESS(mStatus, *this) failed with result 0x80004005: file z:/build/build/src/obj-firefox/dist/include\nsIURIMutator.h, line 489
08:56:29 INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js
08:56:29 INFO - GECKO(1080) | ++DOCSHELL 07A85400 == 3 [pid = 3464] [id = {077e8545-6492-48a0-b413-87631bf4d015}]
08:56:29 INFO - GECKO(1080) | ++DOMWINDOW == 7 (07B18280) [pid = 3464] [serial = 249] [outer = 00000000]
08:56:29 INFO - GECKO(1080) | [Child 3464, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
08:56:29 INFO - GECKO(1080) | ++DOMWINDOW == 8 (07A88400) [pid = 3464] [serial = 250] [outer = 07B18280]
08:56:29 INFO - [1084, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
08:56:30 INFO - GECKO(1080) | ++DOMWINDOW == 9 (0AC9D800) [pid = 3464] [serial = 251] [outer = 07B18280]
08:56:30 INFO - GECKO(1080) | ++DOCSHELL 0F00F000 == 10 [pid = 1716] [id = {ed3b6d90-35b8-435d-9888-1bb94c873256}]
<...>
08:57:59 INFO - Console message: [JavaScript Warning: "Removed unsafe attribute. Element: svg. Attribute: xmlns." {file: "resource://devtools/client/debugger/src/components/Editor/ColumnBreakpoint.js" line: 27}]
08:57:59 INFO - Buffered messages logged at 08:56:34
08:57:59 INFO - Toolbox opened and focused
08:57:59 INFO - Waiting on sources: simple-worker.js
08:57:59 INFO - Waiting for state change: source simple-worker.js exists
08:57:59 INFO - Finished waiting for state change: source simple-worker.js exists
08:57:59 INFO - Finished waiting on sources: simple-worker.js
08:57:59 INFO - Buffered messages logged at 08:56:35
08:57:59 INFO - Waiting for state change: selected source
08:57:59 INFO - Finished waiting for state change: selected source
08:57:59 INFO - Waiting for state change: selected source
08:57:59 INFO - Finished waiting for state change: selected source
08:57:59 INFO - Buffered messages finished
08:57:59 INFO - TEST-UNEXPECTED-FAIL | devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js | Test timed out -
08:58:00 INFO - Removing tab.
08:58:00 INFO - Waiting for event: 'TabClose' on [object XULElement].
08:58:00 INFO - Got event: 'TabClose' on [object XULElement].
08:58:00 INFO - GECKO(1080) | [Child 3104, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
08:58:00 INFO - Tab removed and finished closing
08:58:00 INFO - GECKO(1080) | --DOCSHELL 0F013000 == 8 [pid = 1716] [id = {9664e348-b26b-42eb-823e-e07a9371f5ad}] [url = chrome://devtools/content/debugger/index.html]
08:58:00 INFO - GECKO(1080) | --DOCSHELL 0F00F000 == 7 [pid = 1716] [id = {ed3b6d90-35b8-435d-9888-1bb94c873256}] [url = about:devtools-toolbox]
08:58:00 INFO - GECKO(1080) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 110: uncaught exception: Object
08:58:00 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 110}]
08:58:00 INFO - TEST-FAIL | devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js | Assertion count 1 is greater than expected range 0-0 assertions. -
08:58:01 INFO - GECKO(1080) | MEMORY STAT | vsize 1096MB | vsizeMaxContiguous 293MB | residentFast 422MB | heapAllocated 103MB
08:58:01 INFO - TEST-OK | devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js | took 91157ms
08:58:01 INFO - GECKO(1080) | ++DOCSHELL 00969400 == 2 [pid = 3464] [id = {6c156ff3-772c-45b1-b29d-219e7cdf3f02}]
08:58:01 INFO - GECKO(1080) | ++DOMWINDOW == 3 (07B18700) [pid = 3464] [serial = 252] [outer = 00000000]
08:58:01 INFO - GECKO(1080) | [Child 3464, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
08:58:01 INFO - GECKO(1080) | [Child 3464, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
08:58:01 INFO - checking window state
08:58:01 INFO - GECKO(1080) | ++DOMWINDOW == 4 (07A82C00) [pid = 3464] [serial = 253] [outer = 07B18700]
08:58:01 INFO - TEST-START | devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers.js

Comment 1

[Cosmin Sabou [:CosminS]]

Retriggers: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=windows%2C7%2Cdebug%2Cmochitests%2Ctest-windows7-32%2Fdebug-mochitest-devtools-chrome-e10s-2%2Cm%28dt2%29&tochange=82daf65cbe5e55ddefa27e293dfcbfe27af23062&fromchange=7b70a9ccdc17a6b06662f7760334363493071017&group_state=expanded&selectedJob=252306430

Comment 2

[Gabriele Svelto [:gsvelto]]

We're hitting an assertion in the layout code here. I can't be sure but it looks like a memory-pressure event has just been sent so I wonder if it might have triggered some odd race in the layout code.

Daniel, is it possible that the memory-pressure observer in the presentation shell here triggered the assertion in the log?

Comment 3

[Daniel Holbert [:dholbert]]

This bug is filed on the timeout, not the assertion. The assertion is a red herring -- it happens even in successful testruns, e.g. this one:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=252155713&repo=autoland&lineNumber=52841

So, you want to be looking into why we're timing out, not why we're asserting.

Comment 4

[Daniel Holbert [:dholbert]]

(The assertion may be a sign of something subtly wrong, but it's likely unrelated to the test timeout. We actually hit it 220 times in the successful log that I linked in comment 3.)

Comment 5

[Gabriele Svelto [:gsvelto]]

Thanks a lot for clearing that up Daniel! Time for more digging, I'll leave the NI? open

Comment 6

[Gabriele Svelto [:gsvelto]]

The test seems to be getting stuck here:

https://searchfox.org/mozilla-central/rev/8ed8474757695cdae047150a0eaf94a5f1c96dbe/devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js#19

The previous line executes correctly but we don't get past this line:

https://searchfox.org/mozilla-central/rev/8ed8474757695cdae047150a0eaf94a5f1c96dbe/devtools/client/debugger/test/mochitest/helpers.js#808

So the issue is happening somewhere when adding the breakpoint. I'm now running the test using rr chaos mode to see if it's a race and I can trigger it locally. Note that it might not be a race per se, it might be possible that the memory-pressure event reclaims some weakly held object that the test is relying upon.

Comment 7

[Gabriele Svelto [:gsvelto]]

I managed to reproduce the issue on my machine using rr's chaos mode so it's definitely a race and a fairly narrow one because it required over 25 iterations to hit it. Apparently the memory-pressure event here is coming just at the right time to cause the code to hit the race. Unfortunately having little knowledge of how the debugger works I can't guess why adding a breakpoint in this manner can cause the test to get stuck.

Comment 8

[Andreea Pavel [:apavel]]

Daniel can you assign someone else here?

Comment 9

[Daniel Holbert [:dholbert]]

Sure - I think gsvelto is already investigating this, so he probably makes sense as the assignee. gsvelto, I hope you don't mind me setting it as assigned to you.

Comment 10

[Gabriele Svelto [:gsvelto]]

I think someone from devtools would be able to fix this faster than me since I have very little knowledge of the debugger's internals. What's happening here is that my patch in bug 1558554 affected the timing of this test and caused a race to be triggered in the code setting a breakpoint. This can be reproduced by running the test with rr in chaos mode so it's a timing race; I could rule out that this was caused by the GC/CC running at the same time as the test. I can have a look to try and identify the race but it would mean digging in code I'm unfamiliar with so it might take a while.

FYI this is the full command to reproduce the issue on Linux (it can take a few minutes and you can speed it up by using xvfb-run to run it headless):

env MOZ_QUIET=1 ./mach mochitest --run-until-failure --debugger=rr --debugger-args="record --chaos" devtools/client/debugger/test/mochitest/browser_dbg-windowless-workers-early-breakpoint.js

Comment 11

[Gabriele Svelto [:gsvelto]]

Attachment: Second race

While testing with rr I also run into another race that causes the test to fail, this time after a breakpoint is removed. I've attached the stacktrace.

Comment 12

[Daniel Holbert [:dholbert]]

(In reply to Gabriele Svelto [:gsvelto] from comment #10)

I think someone from devtools would be able to fix this faster than me since I have very little knowledge of the debugger's internals.

Perhaps yulia or jlast, both of whom have worked on this test before?

(I have zero knowledge of the debugger's internals, too.)

Comment 13

[Intermittent Failures Robot]

17 failures in 515 pushes (0.033 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-inbound: 1
• autoland: 6
• mozilla-central: 10

Platform breakdown:

• windows7-32: 17

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1559761&startday=2019-06-21&endday=2019-06-21&tree=all

Comment 14

[Intermittent Failures Robot]

57 failures in 2581 pushes (0.022 failures/push) were associated with this bug in the last 7 days.

This is the #34 most frequent failure this week.

** 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:

• autoland: 33
• mozilla-inbound: 10
• mozilla-central: 12
• try: 2

Platform breakdown:

• windows7-32: 56
• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1559761&startday=2019-06-17&endday=2019-06-23&tree=all

Comment 15

[Jason Laster [:jlast]]

Yulia, this looks like it began when the thread client refactor landed. Would you mind helping investigate?

The test tests worker breakpoint registration which is something that was designed to happen before code would execute. It looks like it is almost exclusively win32-debug, which is likely a slow platform. My guess is that the thread refactoring removed the startup invariant, which prevented races like this.

Comment 16

[Intermittent Failures Robot]

23 failures in 625 pushes (0.037 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 4
• try: 11
• mozilla-central: 5
• mozilla-inbound: 3

Platform breakdown:

• windows7-32: 14
• linux64: 5
• macosx1010-64: 1
• macosx1014-64-shippable: 1
• macosx1014-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1559761&startday=2019-06-24&endday=2019-06-24&tree=all

Comment 17

[Yulia Startsev [:yulia]]

It looks like this may have largely been resolved: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b763cbbd30ec9c6f058266a40608dff2ccec9b32

Potentially by brian's fixes to rr functionality https://bugzilla.mozilla.org/show_bug.cgi?id=1484818.

Comment 18

[Intermittent Failures Robot]

52 failures in 4409 pushes (0.012 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:

• autoland: 4
• try: 38
• mozilla-inbound: 5
• mozilla-central: 5

Platform breakdown:

• windows7-32: 26
• linux64: 7
• macosx1010-64: 1
• macosx1014-64-shippable: 5
• macosx1014-64: 6
• linux64-qr: 4
• windows10-64: 2
• macosx1010-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1559761&startday=2019-06-24&endday=2019-06-30&tree=all

Comment 19

[Intermittent Failures Robot]

44 failures in 1024 pushes (0.043 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• autoland: 40
• mozilla-inbound: 4

Platform breakdown:

• windows7-32: 44

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

Comment 20

[Intermittent Failures Robot]

65 failures in 893 pushes (0.073 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 56
• mozilla-central: 5
• mozilla-inbound: 4

Platform breakdown:

• windows7-32: 65

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

Comment 21

[Daniel Varga [:dvarga]]

In the last 7 days there were 125 failures associated with this bug: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-05&endday=2019-07-12&tree=trunk&bug=1559761
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=256149492&repo=autoland&lineNumber=48150
Occurs on windows7-32 debug build type.

Comment 22

[Andreea Pavel [:apavel]]

Recent occurrences here should be fixed by https://hg.mozilla.org/integration/autoland/rev/956e97b8354d666aa441eef42c21c88f2fbf775d

Comment 23

[Intermittent Failures Robot]

17 failures in 837 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 16
• mozilla-central: 1

Platform breakdown:

• windows7-32: 17

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

Comment 24

[Intermittent Failures Robot]

127 failures in 4710 pushes (0.027 failures/push) were associated with this bug in the last 7 days.

This is the #9 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 112
• mozilla-inbound: 8
• mozilla-central: 6
• try: 1

Platform breakdown:

• windows7-32: 127

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