1453007 - Frequent T-P-e10s(g2) failures on Linux and OS X: Task killed because maxRunTime was exceeded / Automation Error: mozprocess timed out after 3600 seconds running / damp | webconsole/openwithcache.js: Test timed out

Status: RESOLVED WORKSFORME

(Testing :: Talos, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

See https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&filter-searchStr=t-p-e10s(g2)&fromchange=83de58ddda2057f1cb949537f6b111e3b115ea3d&tochange=a8061a09cd7064a8783ca9e67979d77fb52e001e&selectedJob=172879454

It's almost a permafail and not obvious if this is one or more issues.

There are more webconsole/openwithcache.js failures available in this central-as-beta simulation: https://treeherder.mozilla.org/#/jobs?repo=try&revision=41356ce53ff617857225cedc97b0254ebde4dd9f&group_state=expanded&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable&selectedJob=172833082

Changelog: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=83de58ddda20&tochange=a8061a09cd70

Comment 1

[Robert Wood [:rwood]]

Hmmm

08:10:02     INFO -  PID 1312 | TEST-UNEXPECTED-FAIL | damp | webconsole/openwithcache.js: Test timed out

:ochameau, as the owner of DAMP, can you please investigate? Thanks!

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

The failures start with https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=db03e2cdae9ab05482f98e3c567896234c66e226

Comment 3

[Alexandre Poirot [:ochameau]]

Note that thanks to bug 1444826, we get much better error logged into PerfHerder.
So that we can file specific bugs like this one!

Now let's see what going on with this console test...

Comment 4

[Alexandre Poirot [:ochameau]]

(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #0)
> There are more webconsole/openwithcache.js failures available in this
> central-as-beta simulation:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=41356ce53ff617857225cedc97b0254ebde4dd9f&group_state=e
> xpanded&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&filter-resultStatus=retry&filter-
> resultStatus=usercancel&filter-resultStatus=runnable&selectedJob=172833082

Is it MacOS only?
It seems to be passing on Linux, it fails later, during tps (which is run after DAMP), due to bug 1443130.

(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #2)
> The failures start with
> https://hg.mozilla.org/mozilla-central/
> pushloghtml?changeset=db03e2cdae9ab05482f98e3c567896234c66e226

Could it be that bug 1448077 breaks something only on MacOS?

Comment 5

[Robert Wood [:rwood]]

Thanks :ochameau.

Yes definitely looks like two different issues here,

1) this issue, 'TEST-UNEXPECTED-FAIL | damp | webconsole/openwithcache.js: Test timed out', which yes seems to only happen on OSX and on the talos profiling nightly job. So an issue with running g2 with --geckoProfiling on, on OSX.

Yes possibly bug 1448077 since that is also in the changeset. :julian, can you take a peak please and see if it's related to this new failure? Thanks!]

And,

2) g2 exceeding the total task run time, which is Bug 1443130, and happens in the nightly talos profiling job

Which we will resolve in that bug by extending the max task runtime, and I"ll make a patch in that bug.

Comment 6

[Julian Descottes [:jdescottes]]

For now I can't reproduce the issue locally, and I also don't understand why Bug 1448077 would make it fail.

I just added a few g2 with geckoprofile on the last try push I did before landing:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=fed11a87970988ef70ba86da3ec24238f923c91f&selectedJob=172929836

They are all green, so maybe it's something else in the changelog?  

Here is an extract from a failure log (from in https://treeherder.mozilla.org/#/jobs?repo=try&revision=41356ce53ff617857225cedc97b0254ebde4dd9f&selectedJob=172862156)

04:12:28     INFO -  PID 579 | Executing test 'webconsole/openwithcache.js'
04:12:28     INFO -  PID 579 |
[.... Removed some lines here to make it easier to read]
04:12:28     INFO -  PID 579 |
04:12:29     INFO -  PID 579 | Assertion failure
04:12:29     INFO -  PID 579 | assert@resource:///modules/AsyncTabSwitcher.jsm:447:36
04:12:29     INFO -  PID 579 | finish@resource:///modules/AsyncTabSwitcher.jsm:300:5
04:12:29     INFO -  PID 579 | postActions@resource:///modules/AsyncTabSwitcher.jsm:609:7
04:12:29     INFO -  PID 579 | onUnloadTimeout@resource:///modules/AsyncTabSwitcher.jsm:623:5
04:12:29     INFO -  PID 579 | queueUnload/this.unloadTimer<@resource:///modules/AsyncTabSwitcher.jsm:925:44
04:12:29     INFO -  PID 579 | Unable to read VR Path Registry from /Users/cltbld/Library/Application Support/OpenVR/.openvr/openvrpaths.vrpath
04:12:29     INFO -  PID 579 | 2018-04-10 04:12:29.286 plugin-container[637:11985] *** CFMessagePort: bootstrap_register(): failed 1100 (0x44c) 'Permission denied', port = 0x9237, name = 'com.apple.tsm.portname'
04:12:29     INFO -  PID 579 | See /usr/include/servers/bootstrap_defs.h for the error codes.
04:17:28     INFO -  PID 579 | TEST-UNEXPECTED-FAIL | damp | webconsole/openwithcache.js: Test timed out

It mentions AsyncTabSwitcher, which seems to have been updated in Bug 1451460, which is also in the pushlog.
And this pattern seems to repeat itself for all the failures that mention openwithcache.

Mike, do you think this failure could be linked to one of your patches?

Comment 7

[Julian Descottes [:jdescottes]]

Try after Bug 1451460 : https://treeherder.mozilla.org/#/jobs?repo=try&revision=f50dcba03c34cccc89a477a5510982a836949ceb
Try before Bug 1451460: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d153c14f7b7d2b682bef956acfafd3041e0e2bb2

So it looks like the timeouts are linked to Bug 1451460. But interestingly they all failed after a very long time, and I didn't see any of the "damp | webconsole/openwithcache.js: Test timed out" that can be found on the other runs mentioned in this bug.

Comment 8

[Intermittent Failures Robot]

23 failures in 150 pushes (0.153 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-central: 16
* try: 7

Platform breakdown:
* macosx64-nightly: 12
* linux64-nightly: 11

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-04-10&endday=2018-04-10&tree=trunk

Comment 10

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: skip tps on osx, for profiling skip tps on linux/osx

Comment 11

[Robert Wood [:rwood]]

Comment on attachment 8967442 [details] [diff] [review]
skip tps on osx, for profiling skip tps on linux/osx

Review of attachment 8967442 [details] [diff] [review]:
-----------------------------------------------------------------

R+ (with the landing of the patch in Bug 1453720 first of course)

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5e672478d592
skip tps on osx and linux/osx for profiling. r=rwood

Comment 13

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/5e672478d592

Comment 15

[Intermittent Failures Robot]

27 failures in 792 pushes (0.034 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 21
* try: 6

Platform breakdown:
* macosx64-nightly: 17
* linux64-nightly: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-04-09&endday=2018-04-15&tree=trunk

Comment 16

[Intermittent Failures Robot]

1 failures in 782 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-04-16&endday=2018-04-22&tree=trunk

Comment 17

[Intermittent Failures Robot]

1 failures in 780 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-04-23&endday=2018-04-29&tree=trunk

Comment 18

[Mike Conley (:mconley) (:⚙️)]

Sorry it's taken me so long to get to this. :(

Yeah, we're failing an assertion in the AsyncTabSwitcher, and that would definitely cause the test to time out. We should try to figure out why the assertion is failing.

Comment 19

[Mike Conley (:mconley) (:⚙️)]

ni?ing myself to see if I can get some logging in here to see what's going on.

Comment 20

[Intermittent Failures Robot]

1 failures in 408 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1

Platform breakdown:
* windows10-64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-06-11&endday=2018-06-17&tree=trunk

Comment 21

[Intermittent Failures Robot]

3 failures in 718 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 2
* mozilla-central: 1

Platform breakdown:
* windows10-64-nightly: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 22

[Intermittent Failures Robot]

1 failures in 2684 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1453007&startday=2018-09-10&endday=2018-09-16&tree=all

Comment 23

[Intermittent Failures Robot]

1 failures in 2773 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

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

Comment 24

[Intermittent Failures Robot]

1 failures in 2648 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 25

[Dave Hunt [:davehunt] [he/him] ⌚BST]

No reports for 8 months.

Comment 26

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug is a regression, but please revert this change in case of error.

Comment 27

[Mike Conley (:mconley) (:⚙️)]

Apologies - declaring needinfo bankruptcy on needinfo's greater than 2 years old.