Slow first startup of 64bit Firefox builds on ubuntu1804-test workers due to missing font cache
Categories
(Firefox Build System :: Task Configuration, defect)
Tracking
(firefox79 fixed)
Tracking | Status | |
---|---|---|
firefox79 | --- | fixed |
People
(Reporter: whimboo, Assigned: egao)
References
(Blocks 2 open bugs)
Details
(Keywords: perf)
Attachments
(7 files)
(deleted),
text/x-phabricator-request
|
Details | |
(deleted),
text/x-phabricator-request
|
Details | |
41 bytes,
text/x-phabricator-request
|
dkl
:
approval-mozilla-beta?
|
Details | Review |
41 bytes,
text/x-phabricator-request
|
Details | Review | |
41 bytes,
text/x-phabricator-request
|
Details | Review | |
41 bytes,
text/x-phabricator-request
|
Details | Review | |
41 bytes,
text/x-phabricator-request
|
Details | Review |
We recently switched from the Ubuntu 16.04 to the 18.04 docker images. And by that change we weren't able yet to port our Puppeteer job over because they always caused a crash due to a 15s timeout for the CDP connection.
Yesterday I checked such a job in detail and noticed that the problem is a long startup delay of Firefox, which causes our internal websocket server to start about 24s later.
https://treeherder.allizom.org/logviewer.html#/jobs?job_id=298821603&repo=try&lineNumber=97-107
[task 2020-04-24T17:02:06.552Z] PID 99 | *** You are running in headless mode.
[task 2020-04-24T17:02:21.533Z] PID 99 |
[task 2020-04-24T17:02:21.533Z] PID 99 |
[task 2020-04-24T17:02:21.533Z] PID 99 |
[task 2020-04-24T17:02:21.534Z] PID 99 | Ran 0 of 638 test(s)
[task 2020-04-24T17:02:21.534Z] PID 99 | Finished in 15.037 seconds
[task 2020-04-24T17:02:21.534Z] PID 99 | ## CRASHED ##
[task 2020-04-24T17:02:21.535Z] PID 99 | Message:
[task 2020-04-24T17:02:21.535Z] PID 99 | puppeteer.spec.js:84:5 - Timeout Exceeded 15000ms while running "beforeAll" in suite "Firefox Browser"
[task 2020-04-24T17:02:21.535Z] PID 99 | WORKERS STATE
[task 2020-04-24T17:02:30.768Z] PID 99 | DevTools listening on ws://localhost:39737/devtools/browser/c034372d-8bdb-43cc-9f53-1c1914f22e9c
From that output it's not clear what causing this slow startup, so I created a gecko profile for a cold start of Firefox. Here the try push for details:
The gecko profile: https://perfht.ml/354vHPP
Looking at this profile it's pretty clear that something under TelemetryStartup
causes an 11s delay. Sadly the stack hasn't been fully symbolicated maybe due to the fact it's not a nightly build? Maybe Julien can help here?
But checking some frames from the profile-after-change
phase I can see that this is somewhat related to _getGFXData
:
Chris, can you please check what's going that horribly wrong here?
Reporter | ||
Comment 1•5 years ago
|
||
Actually the frames including libfreetype.so.6
as resource seem to take a very long time. Are they maybe collecting the fonts on the system to build the font cache? That reminds me on bug 1443437, where we missed to build the font cache for the 32bit architecture on a 64bit system.
Edwin, do we build the font cache when creating the docker image?
Reporter | ||
Comment 2•5 years ago
|
||
I pushed another build with two invocations of Firefox, and it's indeed the very first start of Firefox on that system, which is affected:
[task 2020-04-25T06:37:10.301Z] + /builds/worker/fetches/firefox/firefox -screenshot https://developer.mozilla.com
[task 2020-04-25T06:37:11.520Z] *** You are running in headless mode.
[task 2020-04-25T06:37:50.220Z] + /builds/worker/fetches/firefox/firefox -screenshot https://mozilla.com
[task 2020-04-25T06:37:51.202Z] *** You are running in headless mode.
[fetches 2020-04-25T06:37:59.984Z] removing /builds/worker/fetches
First screenshot is created within 39s, while the second on only in 8s. This manifests the idea of building up a cache.
Reporter | ||
Comment 3•5 years ago
|
||
Indeed, I don't see anything about updating the font cache in the test-system-setup script:
There should be:
# use fc-cache:i386 to pre-build the font cache for i386 binaries
apt-get -q -y -f install \
fontconfig:i386 \
So it seems to be exactly the same problem as what I already fixed with bug 1443437 for Ubuntu 16.04.
Edwin, this should clearly be documented. Also I wonder if we could have some basic Talos tests for new distributions which we can use to not cause performance regressions.
I will push a try with the above addition.
Reporter | ||
Comment 4•5 years ago
|
||
Hm, whereby the Puppeteer job uses a 64-bit Firefox binary and our Ubuntu 18.04 docker image is a 64-bit system. So installing fontconfig
should have automatically built-up the font cache for the same architecture. Why did that not happen here?
Reporter | ||
Comment 5•5 years ago
|
||
So this might not be caused by the font cache. Adding those lines have had no effect:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=69cd9a36dfa297524813a78a1f74ad5a4dce8bd6&selectedJob=299410501
Re-needinfo Julien for the profile symbolication whom I accidentally have been removed earlier today.
Reporter | ||
Comment 6•5 years ago
|
||
Oh, after retriggering the symbolication the stack actually shows annotateEnvironment at the top with a call into native code:
0x7f0fc82ec7ad
0x7f0fc82dfb23
annotateEnvironment
TelemetryStartup.prototype.observe
js::RunScript
0x7f0fc82e9448
0x7f0fc82e9964
0x7f0fc836292e
0x7f0fc5316b47
XPCWrappedJS method call
0x7f0fc4a2223b
0x7f0fc4a21676
0x7f0fc49f5e52
Category observer notification - profile-after-change (TelemetryStartup)
0x7f0fc822e873
0x7f0fc8222e04
0x7f0fc8223b65
XREMain::XRE_main
(root)
So that could only be Ci.nsICrashReporter.annotateCrashReport()
. So we may need Chris to help us here.
Comment 7•5 years ago
|
||
there are a few things here:
- end users will most likely not have these custom changes, so we are testing in a vacuum
- I agree every non standard thing should have a reason documented
- Our ideal solution for infrastructure changes (part of GSoC project) is to compare runtime and failure rates, just like perfherder does for finding alerts, using enough data and looking for measurable changes.
Comment 8•5 years ago
|
||
About symbolication: yeah you need to manually trigger the symbolication job for try builds.
You should be able to add it by following this flow:
- click "add new job (search)" from the dropdown
- check "use full job list"
- enter "symbols" and press enter
You should get a list of "opt-upload-symbols" and "debug-upload-symbols". You need to pick "the right one" that is for your build.
Another option is with the "old" "add new job" that will allow you to trigger the "Sym" job on the same line as your build.
Some things I don't know (Markus Stange would know better):
- does that work with artifact builds?
- does that work if there's no build at all? I mean, does that trigger a Build job automatically?
There's some documentation (probably in a bad location) in https://profiler.firefox.com/docs/#/./guide-remote-profiling (search for "Try Builds").
Hope that helps!
Comment 9•5 years ago
|
||
Seems unlikely that it'd be AnnotateCrashReport
as all it does is (do a string table search to find the enum for the JS string, and then) grab the lock and set a string value in a table. Perhaps we were stuck on the crash reporter lock waiting on something else?
Reporter | ||
Comment 10•5 years ago
|
||
(In reply to Julien Wajsberg [:julienw] from comment #8)
- does that work with artifact builds?
Thanks for your feedback. As it looks like it doesn't work with artifact builds. As such I pushed a full build. Maybe that gives us the wanted stack frames in the profile:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=14711d262befa30bd20747cbb66fbd43057c0ed7
(In reply to Chris H-C :chutten from comment #9)
Seems unlikely that it'd be
AnnotateCrashReport
as all it does is (do a string table search to find the enum for the JS string, and then) grab the lock and set a string value in a table. Perhaps we were stuck on the crash reporter lock waiting on something else?
I see. Maybe chiming in Gabriele might be helpful then.
Comment 11•5 years ago
|
||
Is this happening in the main or content process? AnnotateCrashReport()
used to be slow in content processes because it relied on IPC and it serialized all the current annotations every time you changed one but I fixed that recently (bug 1614933). On nightly it should only take a lock and stuff the string in a fixed-sized array:
The worst case would be if that happens in the main process simultaneously with a child process crash, in that case we'd grab the lock and read all the strings before allowing further calls to proceed. But even that requires walking the array and copying the strings, not something that would take longer than a few microseconds.
Reporter | ||
Comment 12•5 years ago
|
||
Sorry, for the last try build i forgot to change the puppeteer invocation to just firefox --screenshot
. Here a new try build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=40295a8c7da8089a9983997b314b63f2e81de445
Once the new profile is ready I will comment again.
Reporter | ||
Comment 13•5 years ago
|
||
Here the new profile: https://perfht.ml/2YcZEvy
And with all the frames symbolicated it's indeed clear that this is the same problem as bug 1443437. All the time is spent in gfxFcPlatformFontList::gfxFcPlatformFontList()
, which means there is no font cache available.
Reporter | ||
Comment 14•5 years ago
|
||
I can also see that for Marionette and Wd jobs on Linux 64. Here an example:
[task 2020-04-28T10:20:25.236Z] 10:20:25 INFO - DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2020-04-28T10:20:41.586Z] 10:20:41 INFO - DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
Reporter | ||
Comment 15•5 years ago
|
||
Edwin, can you please have a look at this? My investigation on the other bug starts here:
https://bugzilla.mozilla.org/show_bug.cgi?id=1443437#c9
Reporter | ||
Comment 16•5 years ago
|
||
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #14)
I can also see that for Marionette and Wd jobs on Linux 64. Here an example:
And I assume all other test jobs on that platform launching Firefox at least once are also affected. Means we loose about 20s in each of them when running the job in CI.
Reporter | ||
Comment 17•5 years ago
|
||
Oh, the problem here might be that we only install fontconfig:i386
which is for the 32 bit architecture, but not fontconfig
for 64 bit applications and as such no font cache is being built.
I just pushed a try build to check that:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b8a5acfddea0fa213a5a2784d2b3b55ef9e3a610
Reporter | ||
Comment 18•5 years ago
|
||
And that solved it: https://perfht.ml/2KFOKqf
Joel, do we still have 32-bit jobs which require Firefox? Or did we already get rid of all of them? If not I wonder if we have to install the fontconfig-i386
package at all.
Comment 19•5 years ago
|
||
yes, we have web-platform-tests (m-c only as tier-2, also requires --full to run on try server)
Reporter | ||
Comment 20•5 years ago
|
||
Given the missing Ubuntu 18.04 environment it will be hard for me to have a real patch here. Edwin, can you please take over?
Assignee | ||
Comment 21•5 years ago
|
||
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #20)
Given the missing Ubuntu 18.04 environment it will be hard for me to have a real patch here. Edwin, can you please take over?
I can take a look, a bit backlogged with some other work but should have some spare cycles to deal with this.
Assignee | ||
Updated•5 years ago
|
Assignee | ||
Comment 22•5 years ago
|
||
This is taking a bit longer than I expected.
At first I thought it would be simply replacing the installation of fontconfig:i386
with fontconfig
and regenerating the docker image.
I'm not certain why changing fontconfig
causes issues with media tests.
Reporter | ||
Comment 23•5 years ago
|
||
(In reply to Edwin Takahashi (:egao) from comment #22)
I'm not certain why changing
fontconfig
causes issues with media tests.
Randell or Nils, could one of you help with that or propose someone who could have a look? Thanks.
Assignee | ||
Comment 24•5 years ago
|
||
Any help would be appreciated. In the meantime I'm going to attempt working out a solution, but it may not be optimal as my main goal is currently smart scheduling work.
Reporter | ||
Comment 25•5 years ago
|
||
Edwin, did you try an interactive task similar to what I have described on bug 1636706 comment 9? Maybe that helps to better diagnose this problem.
Assignee | ||
Comment 26•5 years ago
|
||
Assignee | ||
Comment 27•5 years ago
|
||
Assignee | ||
Updated•5 years ago
|
Assignee | ||
Comment 28•5 years ago
|
||
Added a leave-open
keyword to monitor the bug once both patches land.
Comment 29•5 years ago
|
||
Comment 30•5 years ago
|
||
Backed out for perma failures at test_getUserMedia_basicAudio_loopback.html.
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301983170&repo=autoland&lineNumber=14990
Backout: https://hg.mozilla.org/integration/autoland/rev/86b22b1a9f7e6f903b1f194e6e51afc0d55a4381
Comment 31•5 years ago
|
||
Assignee | ||
Comment 32•5 years ago
|
||
Relanding because I think the failure was caused by me landing only the first portion of the patch.
Comment 33•5 years ago
|
||
Backed out for perma failures at test_getUserMedia_basicAudio_loopback.html.
Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302013735&repo=autoland&lineNumber=14993
Backout: https://hg.mozilla.org/integration/autoland/rev/484a76158f166b437f66832d9b975235236b5e84
Assignee | ||
Comment 34•5 years ago
|
||
Ok, so looks like something else went wrong. Not sure why the try push didn't fail but autoland did. Investigating,.
Updated•5 years ago
|
Comment 35•5 years ago
|
||
Updated•5 years ago
|
Assignee | ||
Comment 36•5 years ago
|
||
Aside from the linting failure, it looks like my changes are causing persistent failures of test_getUserMedia_basicAudio_loopback
and other media tests, but only ever for opt
builds:
[task 2020-05-13T23:20:07.504Z] 23:20:07 INFO - TEST-START | dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html
[task 2020-05-13T23:20:07.593Z] 23:20:07 INFO - GECKO(3916) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-05-13T23:20:07.594Z] 23:20:07 INFO - GECKO(3916) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-05-13T23:20:07.691Z] 23:20:07 INFO - GECKO(3916) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2020-05-13T23:20:07.692Z] 23:20:07 INFO - GECKO(3916) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2020-05-13T23:20:07.816Z] 23:20:07 INFO - GECKO(3916) | [Parent 3916, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/checkouts/gecko/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2020-05-13T23:20:07.816Z] 23:20:07 INFO - GECKO(3916) | (firefox:3916): Gtk-CRITICAL **: 23:20:07.813: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2020-05-13T23:20:07.852Z] 23:20:07 INFO - GECKO(3916) | [Parent 3916, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/checkouts/gecko/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2020-05-13T23:20:07.853Z] 23:20:07 INFO - GECKO(3916) | (firefox:3916): Gtk-CRITICAL **: 23:20:07.846: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2020-05-13T23:21:07.839Z] 23:21:07 INFO - TEST-INFO | started process screentopng
[task 2020-05-13T23:21:08.487Z] 23:21:08 INFO - TEST-INFO | screentopng: exit 0
[task 2020-05-13T23:21:08.488Z] 23:21:08 INFO - <snipped 834 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-05-13T23:21:08.489Z] 23:21:08 INFO - Buffered messages logged at 23:21:01
[task 2020-05-13T23:21:08.490Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.491Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.492Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.493Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.494Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.495Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.497Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.497Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.499Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.500Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.500Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.502Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.502Z] 23:21:08 INFO - Buffered messages logged at 23:21:02
[task 2020-05-13T23:21:08.503Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.504Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.504Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.508Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.509Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.509Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.509Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.510Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.511Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.511Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.512Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.512Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.514Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.515Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.515Z] 23:21:08 INFO - Buffered messages logged at 23:21:03
[task 2020-05-13T23:21:08.516Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.516Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.517Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.517Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.518Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.518Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.519Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.520Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.522Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.522Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.523Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.524Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.530Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.531Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.532Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.532Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.532Z] 23:21:08 INFO - Buffered messages logged at 23:21:04
[task 2020-05-13T23:21:08.533Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.534Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.534Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.535Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.536Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.537Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.537Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.538Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.538Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.539Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.540Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.540Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.540Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.540Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.541Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.541Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.541Z] 23:21:08 INFO - Buffered messages logged at 23:21:05
[task 2020-05-13T23:21:08.541Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.542Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.542Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.544Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.544Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.546Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.546Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.547Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.547Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.547Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.548Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.548Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.548Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.556Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.557Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.557Z] 23:21:08 INFO - Buffered messages logged at 23:21:06
[task 2020-05-13T23:21:08.558Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.559Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.560Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.560Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.560Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.561Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.561Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.561Z] 23:21:08 INFO - Buffered messages logged at 23:21:07
[task 2020-05-13T23:21:08.562Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.562Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.562Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.563Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.563Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.563Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.563Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.564Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.564Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.564Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.565Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.565Z] 23:21:08 INFO - Analysing audio frequency - low:target:high = 0:0:0
[task 2020-05-13T23:21:08.565Z] 23:21:08 INFO - Buffered messages finished
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html | Error executing test: Error: Audio analysis timed out waitForAnalysisSuccess@https://example.com/tests/dom/media/tests/mochitest/head.js:203:26 ... @https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html:34:20 ... async*runTestWhenReady/<@https://example.com/tests/dom/media/tests/mochitest/head.js:497:30 ... promise callback*runTestWhenReady@https://example.com/tests/dom/media/tests/mochitest/head.js:497:6 ... @https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html:18:43 ... promise callback*@https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html:18:16 ...
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:299:16
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - runTestWhenReady/<@https://example.com/tests/dom/media/tests/mochitest/head.js:499:9
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - promise callback*runTestWhenReady@https://example.com/tests/dom/media/tests/mochitest/head.js:498:6
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - @https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html:18:43
[task 2020-05-13T23:21:08.566Z] 23:21:08 INFO - promise callback*@https://example.com/tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html:18:16
[task 2020-05-13T23:21:08.567Z] 23:21:08 ERROR - [SimpleTest.finish()] this test already called finish!
[task 2020-05-13T23:21:08.567Z] 23:21:08 INFO - GECKO(3916) | MEMORY STAT | vsize 2727MB | residentFast 157MB | heapAllocated 16MB
[task 2020-05-13T23:21:08.567Z] 23:21:08 INFO - TEST-UNEXPECTED-ERROR | dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html | called finish() multiple times
[task 2020-05-13T23:21:08.568Z] 23:21:08 INFO - TEST-INFO took 60337ms
[task 2020-05-13T23:21:08.568Z] 23:21:08 INFO - TEST-OK | dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html
[task 2020-05-13T23:21:08.568Z] 23:21:08 INFO - TEST-START | dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html
:drno - why this is the case? What would cause a test that would otherwise pass on debug
builds to fail on opt
, and specifically only webrender?
Updated•5 years ago
|
Assignee | ||
Comment 37•5 years ago
|
||
Test failure of dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html
now has an intermittent bug filed against it, Bug 1637824.
Comment 38•5 years ago
|
||
It seems much more likely that the pulseaudio changes in these patches are causing problems than the fontconfig changes. The tests appear to be timing out waiting for audio. Are you certain the pulseaudio modifications are working as expected?
Assignee | ||
Comment 39•5 years ago
|
||
(In reply to Dan Minor [:dminor] from comment #39)
It seems much more likely that the pulseaudio changes in these patches are causing problems than the fontconfig changes. The tests appear to be timing out waiting for audio. Are you certain the pulseaudio modifications are working as expected?
Right, I suspect as such, however the part I cannot figure out is why the failure only occurs on opt
build types, not debug
. If the pulseaudio initialization code was the problem, I would expect this issue to be reproducible across build types.
Comment 40•5 years ago
|
||
Ok, sorry if I missed this elsewhere in the bug, but I think the next step would be a try run with just the fontconfig changes to verify those changes are causing the problem.
Comment 41•5 years ago
|
||
Opt builds should run faster than debug builds, so if there is some sort of timing issue going on, e.g. tests starting before something has fully initialized, then that might explain why opt would fail and debug would pass. I'm not sure if that is possible with these changes, just a thought.
Comment 42•5 years ago
|
||
(In reply to Edwin Takahashi (:egao) from comment #40)
(In reply to Dan Minor [:dminor] from comment #39)
It seems much more likely that the pulseaudio changes in these patches are causing problems than the fontconfig changes. The tests appear to be timing out waiting for audio. Are you certain the pulseaudio modifications are working as expected?
Right, I suspect as such, however the part I cannot figure out is why the failure only occurs on
opt
build types, notdebug
.
opt
-only failures could be a side effect of bug 1630982, especially as there are scheme = https
and scheme = http
tests in the folder of the test you care about. It's possible that on opt runs your test is using a user profile that was already used before, and didn't have a clean shutdown (I explained this situation a bit in bug 1636316 comment 7).
Assignee | ||
Comment 43•5 years ago
|
||
(In reply to Dan Minor [:dminor] from comment #42)
Opt builds should run faster than debug builds, so if there is some sort of timing issue going on, e.g. tests starting before something has fully initialized, then that might explain why opt would fail and debug would pass. I'm not sure if that is possible with these changes, just a thought.
The reason why I went down the path of modifying pulseaudio
initialization code is because changing the installed fontconfig
from i386 to x64 causes multiple tests that use pulseaudio
to inexplicably fail.
The failure location is here which is the section of code I had a hand in when I was migrating our suites to ubuntu1804. So I figured, let's clean things up a bit and make the initialization more robust. That goal was accomplished for all suites except mochitest-media, and only the om/media/tests/mochitest
tests experience failures for some reason.
Anyway, I rebased to get the latest patches that :florian landed, but the outcome is still the same. It looks like I'm going to have to dig into this never ending pulseaudio mess.
Comment 44•5 years ago
|
||
(In reply to Edwin Takahashi (:egao) from comment #44)
The reason why I went down the path of modifying
pulseaudio
initialization code is because changing the installedfontconfig
from i386 to x64 causes multiple tests that usepulseaudio
to inexplicably fail.
From comment #19, it sounded like there were still jobs that required the 32-bit packages, so wouldn't it make sense to just add the 64-bit fontconfig without removing fontconfig:i386.
Assignee | ||
Comment 45•5 years ago
|
||
(In reply to Mathew Hodson from comment #45)
(In reply to Edwin Takahashi (:egao) from comment #44)
The reason why I went down the path of modifying
pulseaudio
initialization code is because changing the installedfontconfig
from i386 to x64 causes multiple tests that usepulseaudio
to inexplicably fail.From comment #19, it sounded like there were still jobs that required the 32-bit packages, so wouldn't it make sense to just add the 64-bit fontconfig without removing fontconfig:i386.
I had to remove the 32bit binary due to conflicts reported by APT when attempting to install both x64 and i386 versions.
I do suspect the x64 version of fontconfig
is to blame for the weird crash on mochitest-media
chunks on opt
and shippable opt
builds, see below:
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::gmp::GMPChild::ProcessingError(mozilla::ipc::HasResultCodes::Result, char const*)]
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Mozilla crash reason: MOZ_CRASH(aborting because of MsgProcessingError)
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Crash dump filename: /tmp/tmpdp4Oxu.mozrunner/minidumps/63acf952-8e26-78f1-c345-9c0e5d6e9126.dmp
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Operating system: Linux
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - 0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - CPU: amd64
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - family 6 model 85 stepping 4
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - 2 CPUs
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - GPU: UNKNOWN
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Crash reason: SIGSEGV /SEGV_MAPERR
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Crash address: 0x0
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Process uptime: not available
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Thread 0 (crashed)
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - 0 libxul.so!mozilla::gmp::GMPChild::ProcessingError(mozilla::ipc::HasResultCodes::Result, char const*) [GMPChild.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 585 + 0x11]
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rax = 0x00007f9e0e2875e3 rdx = 0x00007f9dfcb47548
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rcx = 0x0000557ad00a7db8 rbx = 0x00007f9dfcb38420
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rsi = 0x0000000000000004 rdi = 0x00007f9dfcb38420
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rbp = 0x00007ffda7aed970 rsp = 0x00007ffda7aed970
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r8 = 0x0000000000000000 r9 = 0x0000000000000000
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000000
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r12 = 0x00007f9dfcb38420 r13 = 0x00007f9dfcb9d178
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r14 = 0x00007ffda7aed980 r15 = 0x00007ffda7aeda88
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rip = 0x00007f9e0a45fc98
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Found by: given as instruction pointer in context
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - 1 libxul.so!mozilla::ipc::IPCResult::Fail(mozilla::NotNull<mozilla::ipc::IProtocol*>, char const*, char const*) [ProtocolUtils.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 58 + 0xb]
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rbx = 0x00007f9dfcb38420 rbp = 0x00007ffda7aed9c0
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rsp = 0x00007ffda7aed980 r12 = 0x00007f9dfcb38420
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r13 = 0x00007f9dfcb9d178 r14 = 0x00007ffda7aed980
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r15 = 0x00007ffda7aeda88 rip = 0x00007f9e089f05f0
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - 2 libxul.so!mozilla::gmp::GMPChild::AnswerStartPlugin(nsTString<char16_t> const&) [nsTSubstring.h:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 0 + 0xf]
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rbx = 0x00007ffda7aed9e8 rbp = 0x00007ffda7aeda70
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - rsp = 0x00007ffda7aed9d0 r12 = 0x00007f9dfcb38420
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r13 = 0x00007f9dfcb9d178 r14 = 0x00007ffda7aedb10
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - r15 = 0x00007ffda7aeda88 rip = 0x00007f9e0a45f7bb
[task 2020-05-15T00:17:49.218Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - 3 libxul.so!mozilla::gmp::PGMPChild::OnCallReceived(IPC::Message const&, IPC::Message*&) [PGMPChild.cpp: : 650 + 0x8]
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rbx = 0x00007ffda7aeda98 rbp = 0x00007ffda7aedaf0
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rsp = 0x00007ffda7aeda80 r12 = 0x00007f9dfcb9d180
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r13 = 0x00007f9dfcb9d178 r14 = 0x00007ffda7aedb10
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r15 = 0x00007f9dfcb38420 rip = 0x00007f9e08b11f79
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - 4 libxul.so!mozilla::ipc::MessageChannel::DispatchInterruptMessage(mozilla::ipc::ActorLifecycleProxy*, IPC::Message&&, unsigned long) [MessageChannel.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 2218 + 0x21]
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rbx = 0x00007f9dfcb6e040 rbp = 0x00007ffda7aedb50
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rsp = 0x00007ffda7aedb00 r12 = 0x0000000000000000
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r13 = 0x00007f9dfcb38510 r14 = 0x00007f9dfcb9d178
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r15 = 0x00007f9dfcb54340 rip = 0x00007f9e089eb6e0
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - 5 libxul.so!mozilla::ipc::MessageChannel::DispatchMessage(IPC::Message&&) [MessageChannel.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 2108 + 0x7]
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rbx = 0x00007f9dfcb90120 rbp = 0x00007ffda7aedc20
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rsp = 0x00007ffda7aedb60 r12 = 0x0000000000000000
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r13 = 0x00007f9dfcb38510 r14 = 0x00007f9dfcb54340
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r15 = 0x00007f9dfcb9d178 rip = 0x00007f9e089eb37b
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - 6 libxul.so!mozilla::ipc::MessageChannel::RunMessage(mozilla::ipc::MessageChannel::MessageTask&) [MessageChannel.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 1958 + 0xb]
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rbx = 0x00007f9dfcb6e040 rbp = 0x00007ffda7aedc70
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rsp = 0x00007ffda7aedc30 r12 = 0x00007f9dfcb9d120
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r13 = 0x00007ffda7aedcc8 r14 = 0x00007f9dfcb38510
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - r15 = 0x00007f9dfcb9d178 rip = 0x00007f9e089eba07
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - 7 libxul.so!mozilla::ipc::MessageChannel::MessageTask::Run() [MessageChannel.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 1989 + 0xc]
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rbx = 0x00007f9dfcb9d120 rbp = 0x00007ffda7aedc90
[task 2020-05-15T00:17:49.219Z] 00:17:49 INFO - rsp = 0x00007ffda7aedc80 r12 = 0x00007ffda7aede78
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r13 = 0x00007ffda7aedcc8 r14 = 0x00007f9dfcb90120
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r15 = 0x00007ffda7aedcd0 rip = 0x00007f9e089ebd2e
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - 8 libxul.so!MessageLoop::DoWork() [message_loop.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 523 + 0x1c]
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - rbx = 0x00007ffda7aeddf8 rbp = 0x00007ffda7aedd10
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - rsp = 0x00007ffda7aedca0 r12 = 0x00007ffda7aede78
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r13 = 0x00007ffda7aedcc8 r14 = 0x00007f9dfcb9d120
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r15 = 0x00007ffda7aedcd0 rip = 0x00007f9e089ab434
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - 9 libxul.so!base::MessagePumpDefault::Run(base::MessagePump::Delegate*) [message_pump_default.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 35 + 0x9]
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - rbx = 0x00007ffda7aeddf8 rbp = 0x00007ffda7aedd90
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - rsp = 0x00007ffda7aedd20 r12 = 0x00007f9dfcb097e0
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r13 = 0x0000000000000001 r14 = 0x00007f9dfcb097c0
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - r15 = 0x00007ffda7aedd50 rip = 0x00007f9e089abab1
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.220Z] 00:17:49 INFO - 10 libxul.so!MessageLoop::Run() [message_loop.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 290 + 0xc]
[task 2020-05-15T00:17:49.221Z] 00:17:49 INFO - rbx = 0x00007f9dfcb38400 rbp = 0x00007ffda7aeddc0
[task 2020-05-15T00:17:49.221Z] 00:17:49 INFO - rsp = 0x00007ffda7aedda0 r12 = 0x0000000080004005
[task 2020-05-15T00:17:49.221Z] 00:17:49 INFO - r13 = 0x00007ffda7aee198 r14 = 0x00007ffda7aeddf8
[task 2020-05-15T00:17:49.221Z] 00:17:49 INFO - r15 = 0x00000000000006ec rip = 0x00007f9e089aa906
[task 2020-05-15T00:17:49.221Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.222Z] 00:17:49 INFO - 11 libxul.so!XRE_InitChildProcess(int, char**, XREChildData const*) [nsEmbedFunctions.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 740 + 0x8]
[task 2020-05-15T00:17:49.222Z] 00:17:49 INFO - rbx = 0x00007f9dfcb38400 rbp = 0x00007ffda7aee050
[task 2020-05-15T00:17:49.222Z] 00:17:49 INFO - rsp = 0x00007ffda7aeddd0 r12 = 0x0000000080004005
[task 2020-05-15T00:17:49.222Z] 00:17:49 INFO - r13 = 0x00007ffda7aee198 r14 = 0x00007ffda7aeddf8
[task 2020-05-15T00:17:49.222Z] 00:17:49 INFO - r15 = 0x00000000000006ec rip = 0x00007f9e0bccf325
[task 2020-05-15T00:17:49.223Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.223Z] 00:17:49 INFO - 12 plugin-container!main [plugin-container.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 56 + 0x13]
[task 2020-05-15T00:17:49.223Z] 00:17:49 INFO - rbx = 0x00007f9dfcb025f0 rbp = 0x00007ffda7aee0b0
[task 2020-05-15T00:17:49.223Z] 00:17:49 INFO - rsp = 0x00007ffda7aee060 r12 = 0x00007ffda7aeecb4
[task 2020-05-15T00:17:49.223Z] 00:17:49 INFO - r13 = 0x00007ffda7aee190 r14 = 0x00007ffda7aee198
[task 2020-05-15T00:17:49.224Z] 00:17:49 INFO - r15 = 0x0000000000000004 rip = 0x0000557acfff9ca3
[task 2020-05-15T00:17:49.224Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.224Z] 00:17:49 INFO - 13 libc.so.6 + 0x21b97
[task 2020-05-15T00:17:49.224Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x0000557ad008b310
[task 2020-05-15T00:17:49.224Z] 00:17:49 INFO - rsp = 0x00007ffda7aee0c0 r12 = 0x0000557acfff9a89
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - r13 = 0x00007ffda7aee190 r14 = 0x0000000000000000
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - r15 = 0x0000000000000000 rip = 0x00007f9e06b42b97
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - 14 plugin-container + 0xfc20
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - rsp = 0x00007ffda7aee0e0 rip = 0x0000557acfff9c20
[task 2020-05-15T00:17:49.225Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - 15 plugin-container!_GLOBAL__sub_I_TimeStamp.cpp [TimeStamp.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 67 + 0x1c]
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - rsp = 0x00007ffda7aee0f8 rip = 0x0000557acfff9a89
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - 16 0x7ffda7aee190
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - rbx = 0x536bf601363d1b14 rbp = 0x0000557acfff9a89
[task 2020-05-15T00:17:49.226Z] 00:17:49 INFO - rsp = 0x00007ffda7aee100 rip = 0x00007ffda7aee190
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - 17 ld-linux-x86-64.so.2 + 0x10733
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - rsp = 0x00007ffda7aee140 rip = 0x00007f9e0fbb1733
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - 18 libxul.so!_fini + 0x1fe8120
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - rsp = 0x00007ffda7aee148 rip = 0x00007f9e0f418b80
[task 2020-05-15T00:17:49.227Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - 19 libpthread.so.0 + 0x219bb0
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - rsp = 0x00007ffda7aee150 rip = 0x00007f9e0fb9bbb0
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - 20 plugin-container!_GLOBAL__sub_I_TimeStamp.cpp [TimeStamp.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 67 + 0x1c]
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - rsp = 0x00007ffda7aee170 rip = 0x0000557acfff9a89
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - 21 0x7ffda7aee190
[task 2020-05-15T00:17:49.228Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x0000557acfff9a89
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - rsp = 0x00007ffda7aee178 rip = 0x00007ffda7aee190
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - 22 plugin-container!_start + 0x29
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - rsp = 0x00007ffda7aee180 rip = 0x0000557acfff9ab2
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - 23 0x7ffda7aee188
[task 2020-05-15T00:17:49.229Z] 00:17:49 INFO - rsp = 0x00007ffda7aee188 rip = 0x00007ffda7aee188
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - Thread 1
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - 0 libc.so.6 + 0x11b839
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - rax = 0xfffffffffffffffc rdx = 0x0000000000000020
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - rcx = 0x00007f9e06c3c839 rbx = 0x00007f9dfc2fcc90
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - rsi = 0x00007f9dfcb91080 rdi = 0x0000000000000008
[task 2020-05-15T00:17:49.230Z] 00:17:49 INFO - rbp = 0x00007f9dfc2fcb40 rsp = 0x00007f9dfc2fcaf8
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - r8 = 0x00000000fffffffc r9 = 0x00007f9dfc2fcb40
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - r10 = 0x00000000ffffffff r11 = 0x0000000000000246
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - r12 = 0x00000000ffffffff r13 = 0x00007f9dfcb38c00
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - r14 = 0x00007f9dfcb38d10 r15 = 0x00007f9dfcb02720
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - rip = 0x00007f9e06c3c839
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - Found by: given as instruction pointer in context
[task 2020-05-15T00:17:49.231Z] 00:17:49 INFO - 1 libxul.so!event_base_loop [event.c:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 1947 + 0xd]
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - rbp = 0x00007f9dfc2fcbe0 rsp = 0x00007f9dfc2fcb50
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - rip = 0x00007f9e089be846
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - Found by: previous frame's frame pointer
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - 2 libxul.so!base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [message_pump_libevent.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 0 + 0xe]
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - rbx = 0x00007f9dfc2fcc90 rbp = 0x00007f9dfc2fcc40
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fcbf0 r12 = 0x00007f9dfcb90000
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - r13 = 0x0000000000000000 r14 = 0x00007f9dfcb474c0
[task 2020-05-15T00:17:49.232Z] 00:17:49 INFO - r15 = 0x00007f9dfcb474d8 rip = 0x00007f9e089ac208
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - 3 libxul.so!MessageLoop::Run() [message_loop.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 290 + 0xc]
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x00007f9dfc2fcc70
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fcc50 r12 = 0x00007f9dfcb90048
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - r13 = 0x0000000000000000 r14 = 0x00007f9dfc2fcc90
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - r15 = 0x00007f9dfcb90070 rip = 0x00007f9e089aa906
[task 2020-05-15T00:17:49.233Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - 4 libxul.so!base::Thread::ThreadMain() [thread.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 192 + 0x8]
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x00007f9dfc2fce60
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fcc80 r12 = 0x00007f9dfcb90048
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - r13 = 0x0000000000000000 r14 = 0x00007f9dfc2fcc90
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - r15 = 0x00007f9dfcb90070 rip = 0x00007f9e089b4231
[task 2020-05-15T00:17:49.234Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - 5 libxul.so!ThreadFunc(void*) [platform_thread_posix.cc:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 40 + 0x6]
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x00007f9dfc2fce70
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fce70 r12 = 0x00007f9dfc2fcf40
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - r13 = 0x0000000000000000 r14 = 0x00007f9dfcb90048
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - r15 = 0x00007ffda7aedc90 rip = 0x00007f9e089b0c4a
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.235Z] 00:17:49 INFO - 6 libpthread.so.0 + 0x76db
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - rbx = 0x0000000000000000 rbp = 0x0000000000000000
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fce80 r12 = 0x00007f9dfc2fcf40
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - r13 = 0x0000000000000000 r14 = 0x00007f9dfcb90048
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - r15 = 0x00007ffda7aedc90 rip = 0x00007f9e0f9896db
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - Found by: call frame info
[task 2020-05-15T00:17:49.236Z] 00:17:49 INFO - 7 libc.so.6 + 0x12188f
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - rsp = 0x00007f9dfc2fcf40 rip = 0x00007f9e06c4288f
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - Thread 2
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - 0 libpthread.so.0 + 0xd9f3
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - rax = 0xfffffffffffffe00 rdx = 0x0000000000000000
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - rcx = 0x00007f9e0f98f9f3 rbx = 0x00007f9dfcb48210
[task 2020-05-15T00:17:49.237Z] 00:17:49 INFO - rsi = 0x0000000000000080 rdi = 0x00007f9dfcb48238
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbc30
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - r8 = 0x0000000000000000 r9 = 0x0000000000000000
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000246
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - r12 = 0x00007f9dfcb48238 r13 = 0x0000000000000000
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - r14 = 0x00007f9dfcb481e0 r15 = 0x0000000000000002
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - rip = 0x00007f9e0f98f9f3
[task 2020-05-15T00:17:49.238Z] 00:17:49 INFO - Found by: given as instruction pointer in context
[task 2020-05-15T00:17:49.239Z] 00:17:49 INFO - 1 libpthread.so.0 + 0xd690
[task 2020-05-15T00:17:49.239Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbc78
[task 2020-05-15T00:17:49.239Z] 00:17:49 INFO - rip = 0x00007f9e0f98f690
[task 2020-05-15T00:17:49.239Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.239Z] 00:17:49 INFO - 2 libxul.so!_fini + 0x11dcde4
[task 2020-05-15T00:17:49.240Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbc88
[task 2020-05-15T00:17:49.240Z] 00:17:49 INFO - rip = 0x00007f9e0e60d844
[task 2020-05-15T00:17:49.240Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.240Z] 00:17:49 INFO - 3 plugin-container!mozilla::detail::ConditionVariableImpl::wait_for(mozilla::detail::MutexImpl&, mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> const&) [ConditionVariable_posix.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 115 + 0xb]
[task 2020-05-15T00:17:49.241Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbd00
[task 2020-05-15T00:17:49.241Z] 00:17:49 INFO - rip = 0x0000557ad004ee8c
[task 2020-05-15T00:17:49.241Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.241Z] 00:17:49 INFO - 4 libc.so.6 + 0x130ea6
[task 2020-05-15T00:17:49.241Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbd10
[task 2020-05-15T00:17:49.242Z] 00:17:49 INFO - rip = 0x00007f9e06c51ea6
[task 2020-05-15T00:17:49.242Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.242Z] 00:17:49 INFO - 5 libxul.so!mozilla::BackgroundHangManager::RunMonitorThread() [BackgroundHangMonitor.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 342 + 0x19]
[task 2020-05-15T00:17:49.242Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbd60
[task 2020-05-15T00:17:49.243Z] 00:17:49 INFO - rip = 0x00007f9e0bb3ff84
[task 2020-05-15T00:17:49.243Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.243Z] 00:17:49 INFO - 6 libxul.so!_fini + 0x1129371
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbda8
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - rip = 0x00007f9e0e559dd1
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - 7 libxul.so!mozilla::BackgroundHangManager::MonitorThread(void*) [BackgroundHangMonitor.cpp:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 80 + 0x8]
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbe00
[task 2020-05-15T00:17:49.244Z] 00:17:49 INFO - rip = 0x00007f9e0bb3fd6d
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - 8 libnspr4.so!_pt_root [ptthread.c:80ba3f3cfaf9b31341bca28e2e6aea383cec8acc : 201 + 0x8]
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbe30
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - rip = 0x00007f9e0fd70aa1
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - 9 libpthread.so.0 + 0x76db
[task 2020-05-15T00:17:49.245Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbe80
[task 2020-05-15T00:17:49.246Z] 00:17:49 INFO - rip = 0x00007f9e0f9896db
[task 2020-05-15T00:17:49.246Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.246Z] 00:17:49 INFO - 10 libc.so.6 + 0x12188f
[task 2020-05-15T00:17:49.246Z] 00:17:49 INFO - rbp = 0x00007f9dfcb48234 rsp = 0x00007f9dfc2bbf40
[task 2020-05-15T00:17:49.247Z] 00:17:49 INFO - rip = 0x00007f9e06c4288f
[task 2020-05-15T00:17:49.247Z] 00:17:49 INFO - Found by: stack scanning
[task 2020-05-15T00:17:49.247Z] 00:17:49 INFO -
[task 2020-05-15T00:17:49.247Z] 00:17:49 INFO - Loaded modules:
[task 2020-05-15T00:17:49.247Z] 00:17:49 INFO - 0x557acffea000 - 0x557ad00a7fff plugin-container ??? (main)
[task 2020-05-15T00:17:49.248Z] 00:17:49 INFO - 0x7f9dfcdad000 - 0x7f9dfcfc1fff libgpg-error.so.0 ???
[task 2020-05-15T00:17:49.248Z] 00:17:49 INFO - 0x7f9dfcfc2000 - 0x7f9dfd1f1fff libatspi.so.0 ???
[task 2020-05-15T00:17:49.249Z] 00:17:49 INFO - 0x7f9dfd1f2000 - 0x7f9dfd3f8fff libuuid.so.1 ???
[task 2020-05-15T00:17:49.249Z] 00:17:49 INFO - 0x7f9dfd3f9000 - 0x7f9dfd625fff libgraphite2.so.3 ???
[task 2020-05-15T00:17:49.249Z] 00:17:49 INFO - 0x7f9dfd626000 - 0x7f9dfd871fff libblkid.so.1 ???
[task 2020-05-15T00:17:49.249Z] 00:17:49 INFO - 0x7f9dfd873000 - 0x7f9dfda79fff libdatrie.so.1 ???
[task 2020-05-15T00:17:49.249Z] 00:17:49 INFO - 0x7f9dfda7a000 - 0x7f9dfdd94fff libgcrypt.so.20 ???
[task 2020-05-15T00:17:49.250Z] 00:17:49 INFO - 0x7f9dfdd96000 - 0x7f9dfdfb1fff liblz4.so.1 ???
[task 2020-05-15T00:17:49.250Z] 00:17:49 INFO - 0x7f9dfdfb2000 - 0x7f9dfe1d7fff liblzma.so.5 ???
[task 2020-05-15T00:17:49.250Z] 00:17:49 INFO - 0x7f9dfe1d8000 - 0x7f9dfe3ebfff libbsd.so.0 ???
[task 2020-05-15T00:17:49.251Z] 00:17:49 INFO - 0x7f9dfe3ed000 - 0x7f9dfe5fbfff libwayland-client.so.0 ???
[task 2020-05-15T00:17:49.251Z] 00:17:49 INFO - 0x7f9dfe5fc000 - 0x7f9dfe7fdfff libwayland-egl.so.1 ???
[task 2020-05-15T00:17:49.251Z] 00:17:49 INFO - 0x7f9dfe7fe000 - 0x7f9dfea05fff libwayland-cursor.so.0 ???
[task 2020-05-15T00:17:49.251Z] 00:17:49 INFO - 0x7f9dfea06000 - 0x7f9dfec44fff libxkbcommon.so.0 ???
[task 2020-05-15T00:17:49.252Z] 00:17:49 INFO - 0x7f9dfec45000 - 0x7f9dfee4ffff libXrandr.so.2 ???
[task 2020-05-15T00:17:49.252Z] 00:17:49 INFO - 0x7f9dfee50000 - 0x7f9dff052fff libXinerama.so.1 ???
[task 2020-05-15T00:17:49.252Z] 00:17:49 INFO - 0x7f9dff053000 - 0x7f9dff353fff libepoxy.so.0 ???
[task 2020-05-15T00:17:49.252Z] 00:17:49 INFO - 0x7f9dff354000 - 0x7f9dff583fff libatk-bridge-2.0.so.0 ???
[task 2020-05-15T00:17:49.253Z] 00:17:49 INFO - 0x7f9dff585000 - 0x7f9dff79cfff libICE.so.6 ???
[task 2020-05-15T00:17:49.253Z] 00:17:49 INFO - 0x7f9dff7a0000 - 0x7f9dff9a7fff libSM.so.6 ???
[task 2020-05-15T00:17:49.253Z] 00:17:49 INFO - 0x7f9dff9a8000 - 0x7f9dffc45fff libharfbuzz.so.0 ???
[task 2020-05-15T00:17:49.254Z] 00:17:49 INFO - 0x7f9dffc46000 - 0x7f9dffe98fff libmount.so.1 ???
[task 2020-05-15T00:17:49.254Z] 00:17:49 INFO - 0x7f9dffe9a000 - 0x7f9e000b2fff libresolv.so.2 ???
[task 2020-05-15T00:17:49.254Z] 00:17:49 INFO - 0x7f9e000b5000 - 0x7f9e002dafff libselinux.so.1 ???
[task 2020-05-15T00:17:49.254Z] 00:17:49 INFO - 0x7f9e002dd000 - 0x7f9e004e0fff libgmodule-2.0.so.0 ???
[task 2020-05-15T00:17:49.254Z] 00:17:49 INFO - 0x7f9e004e1000 - 0x7f9e006edfff libxcb-render.so.0 ???
[task 2020-05-15T00:17:49.255Z] 00:17:49 INFO - 0x7f9e006ee000 - 0x7f9e00992fff libpixman-1.so.0 ???
[task 2020-05-15T00:17:49.255Z] 00:17:49 INFO - 0x7f9e00993000 - 0x7f9e00b9bfff libthai.so.0 ???
[task 2020-05-15T00:17:49.255Z] 00:17:49 INFO - 0x7f9e00b9c000 - 0x7f9e00e0dfff libpcre.so.3 ???
[task 2020-05-15T00:17:49.255Z] 00:17:49 INFO - 0x7f9e00e0e000 - 0x7f9e01015fff libffi.so.6 ???
[task 2020-05-15T00:17:49.256Z] 00:17:49 INFO - 0x7f9e01016000 - 0x7f9e01298fff libsystemd.so.0 ???
[task 2020-05-15T00:17:49.256Z] 00:17:49 INFO - 0x7f9e0129a000 - 0x7f9e014cbfff libexpat.so.1 ???
[task 2020-05-15T00:17:49.256Z] 00:17:49 INFO - 0x7f9e014cc000 - 0x7f9e016e8fff libz.so.1 ???
[task 2020-05-15T00:17:49.256Z] 00:17:49 INFO - 0x7f9e016e9000 - 0x7f9e0191afff libpng16.so.16 ???
[task 2020-05-15T00:17:49.257Z] 00:17:49 INFO - 0x7f9e0191b000 - 0x7f9e01b20fff libXdmcp.so.6 ???
[task 2020-05-15T00:17:49.257Z] 00:17:49 INFO - 0x7f9e01b21000 - 0x7f9e01d24fff libXau.so.6 ???
[task 2020-05-15T00:17:49.257Z] 00:17:49 INFO - 0x7f9e01d25000 - 0x7f9e02019fff libgdk-3.so.0 ???
[task 2020-05-15T00:17:49.257Z] 00:17:49 INFO - 0x7f9e0201b000 - 0x7f9e0291dfff libgtk-3.so.0 ???
[task 2020-05-15T00:17:49.257Z] 00:17:49 INFO - 0x7f9e02923000 - 0x7f9e02b24fff libgthread-2.0.so.0 ???
[task 2020-05-15T00:17:49.258Z] 00:17:49 INFO - 0x7f9e02b25000 - 0x7f9e02d8cfff libXt.so.6 ???
[task 2020-05-15T00:17:49.258Z] 00:17:49 INFO - 0x7f9e02d8e000 - 0x7f9e02fa3fff libpangoft2-1.0.so.0 ???
[task 2020-05-15T00:17:49.258Z] 00:17:49 INFO - 0x7f9e02fa4000 - 0x7f9e031a6fff libxcb-shm.so.0 ???
[task 2020-05-15T00:17:49.258Z] 00:17:49 INFO - 0x7f9e031a7000 - 0x7f9e03543fff libgio-2.0.so.0 ???
[task 2020-05-15T00:17:49.259Z] 00:17:49 INFO - 0x7f9e03546000 - 0x7f9e03769fff libgdk_pixbuf-2.0.so.0 ???
[task 2020-05-15T00:17:49.259Z] 00:17:49 INFO - 0x7f9e0376a000 - 0x7f9e03a85fff libcairo.so.2 ???
[task 2020-05-15T00:17:49.259Z] 00:17:49 INFO - 0x7f9e03a87000 - 0x7f9e03c8ffff libcairo-gobject.so.2 ???
[task 2020-05-15T00:17:49.259Z] 00:17:49 INFO - 0x7f9e03c90000 - 0x7f9e03eb5fff libatk-1.0.so.0 ???
[task 2020-05-15T00:17:49.259Z] 00:17:49 INFO - 0x7f9e03eb6000 - 0x7f9e04102fff libpango-1.0.so.0 ???
[task 2020-05-15T00:17:49.260Z] 00:17:49 INFO - 0x7f9e04103000 - 0x7f9e0430ffff libpangocairo-1.0.so.0 ???
[task 2020-05-15T00:17:49.260Z] 00:17:49 INFO - 0x7f9e04310000 - 0x7f9e04625fff libglib-2.0.so.0 ???
[task 2020-05-15T00:17:49.260Z] 00:17:49 INFO - 0x7f9e04627000 - 0x7f9e0487afff libgobject-2.0.so.0 ???
[task 2020-05-15T00:17:49.261Z] 00:17:49 INFO - 0x7f9e0487b000 - 0x7f9e04ac7fff libdbus-1.so.3 ???
[task 2020-05-15T00:17:49.261Z] 00:17:49 INFO - 0x7f9e04ac8000 - 0x7f9e04ceefff libdbus-glib-1.so.2 ???
[task 2020-05-15T00:17:49.261Z] 00:17:49 INFO - 0x7f9e04cef000 - 0x7f9e04f33fff libfontconfig.so.1 ???
[task 2020-05-15T00:17:49.261Z] 00:17:49 INFO - 0x7f9e04f34000 - 0x7f9e051e7fff libfreetype.so.6 ???
[task 2020-05-15T00:17:49.261Z] 00:17:49 INFO - 0x7f9e051e8000 - 0x7f9e053f1fff libXrender.so.1 ???
[task 2020-05-15T00:17:49.262Z] 00:17:49 INFO - 0x7f9e053f2000 - 0x7f9e05601fff libXi.so.6 ???
[task 2020-05-15T00:17:49.262Z] 00:17:49 INFO - 0x7f9e05602000 - 0x7f9e05807fff libXfixes.so.3 ???
[task 2020-05-15T00:17:49.262Z] 00:17:49 INFO - 0x7f9e05808000 - 0x7f9e05a19fff libXext.so.6 ???
[task 2020-05-15T00:17:49.263Z] 00:17:49 INFO - 0x7f9e05a1a000 - 0x7f9e05c1cfff libXdamage.so.1 ???
[task 2020-05-15T00:17:49.263Z] 00:17:49 INFO - 0x7f9e05c1d000 - 0x7f9e05e26fff libXcursor.so.1 ???
[task 2020-05-15T00:17:49.263Z] 00:17:49 INFO - 0x7f9e05e27000 - 0x7f9e06029fff libXcomposite.so.1 ???
[task 2020-05-15T00:17:49.264Z] 00:17:49 INFO - 0x7f9e0602a000 - 0x7f9e06251fff libxcb.so.1 ???
[task 2020-05-15T00:17:49.264Z] 00:17:49 INFO - 0x7f9e06252000 - 0x7f9e06453fff libX11-xcb.so.1 ???
[task 2020-05-15T00:17:49.264Z] 00:17:49 INFO - 0x7f9e06454000 - 0x7f9e0678bfff libX11.so.6 ???
[task 2020-05-15T00:17:49.265Z] 00:17:49 INFO - 0x7f9e0678c000 - 0x7f9e067e9fff libssl3.so ???
[task 2020-05-15T00:17:49.265Z] 00:17:49 INFO - 0x7f9e067eb000 - 0x7f9e06918fff libmozsqlite3.so ???
[task 2020-05-15T00:17:49.265Z] 00:17:49 INFO - 0x7f9e06919000 - 0x7f9e06b20fff librt.so.1 ???
[task 2020-05-15T00:17:49.266Z] 00:17:49 INFO - 0x7f9e06b21000 - 0x7f9e06f0dfff libc.so.6 ??? (WARNING: No symbols, libc.so.6, BAC017B4C57C06CFD1D1BED6652CEDB90)
[task 2020-05-15T00:17:49.266Z] 00:17:49 INFO - 0x7f9e06f12000 - 0x7f9e07129fff libgcc_s.so.1 ???
[task 2020-05-15T00:17:49.266Z] 00:17:49 INFO - 0x7f9e0712a000 - 0x7f9e074c7fff libm.so.6 ???
[task 2020-05-15T00:17:49.266Z] 00:17:49 INFO - 0x7f9e074c8000 - 0x7f9e0784cfff libstdc++.so.6 ???
[task 2020-05-15T00:17:49.267Z] 00:17:49 INFO - 0x7f9e07851000 - 0x7f9e07a54fff libdl.so.2 ???
[task 2020-05-15T00:17:49.267Z] 00:17:49 INFO - 0x7f9e07a55000 - 0x7f9e0f8a0fff libxul.so ???
[task 2020-05-15T00:17:49.267Z] 00:17:49 INFO - 0x7f9e0f982000 - 0x7f9e0fb9cfff libpthread.so.0 ??? (WARNING: No symbols, libpthread.so.0, DEAAC628B2700DD41F0F3D0A1A0CAD1A0)
[task 2020-05-15T00:17:49.268Z] 00:17:49 INFO - 0x7f9e0fba1000 - 0x7f9e0fbc7fff ld-linux-x86-64.so.2 ??? (WARNING: No symbols, ld-linux-x86-64.so.2, 961BDF6428122F38E18684249ED800AB0)
[task 2020-05-15T00:17:49.268Z] 00:17:49 INFO - 0x7f9e0fc15000 - 0x7f9e0fc1afff libmozwayland.so ???
[task 2020-05-15T00:17:49.268Z] 00:17:49 INFO - 0x7f9e0fc1b000 - 0x7f9e0fc1ffff libmozgtk.so ???
[task 2020-05-15T00:17:49.269Z] 00:17:49 INFO - 0x7f9e0fc22000 - 0x7f9e0fc49fff libsmime3.so ???
[task 2020-05-15T00:17:49.269Z] 00:17:49 INFO - 0x7f9e0fc4a000 - 0x7f9e0fc7cfff libnssutil3.so ???
[task 2020-05-15T00:17:49.269Z] 00:17:49 INFO - 0x7f9e0fc7d000 - 0x7f9e0fd22fff libnss3.so ???
[task 2020-05-15T00:17:49.269Z] 00:17:49 INFO - 0x7f9e0fd23000 - 0x7f9e0fd31fff liblgpllibs.so ???
[task 2020-05-15T00:17:49.270Z] 00:17:49 INFO - 0x7f9e0fd36000 - 0x7f9e0fd3bfff libplds4.so ???
[task 2020-05-15T00:17:49.270Z] 00:17:49 INFO - 0x7f9e0fd3c000 - 0x7f9e0fd42fff libplc4.so ???
[task 2020-05-15T00:17:49.270Z] 00:17:49 INFO - 0x7f9e0fd43000 - 0x7f9e0fd7dfff libnspr4.so ???
[task 2020-05-15T00:17:49.271Z] 00:17:49 INFO - 0x7f9e0fda0000 - 0x7f9e0fdc5fff libmozsandbox.so ???
[task 2020-05-15T00:17:49.271Z] 00:17:49 INFO - 0x7ffda7bac000 - 0x7ffda7badfff linux-gate.so ???
Log: https://firefoxci.taskcluster-artifacts.net/R_8d1891SwSSWSK01JFb8Q/0/public/logs/live_backing.log
In the stack it mentions libfontconfig.so.1
. I think this explains why the problem with mochitest-media
occurs even if the only change made is to install the newest x64 binary of fontconfig
.
Assignee | ||
Comment 46•5 years ago
|
||
:gsvelto - I recall you are familiar with crashes and low-level issues. Does anything stand out from the crash dump? Any help would be appreciated!
Assignee | ||
Comment 47•5 years ago
|
||
After some more digging, I found some more possibly relevant information:
- when installing current version of
fontconfig
, it also prompts to install variouspulseaudio
related libraries. - the
pulseaudio
libraries are currently version1:11.1-1ubuntu7
- the
pulsaeudio
libraries currently installed in the docker image used in CI is1:11.1-1ubuntu5
The update from 1:11.1-1ubuntu5
to 1:11.1-1ubuntu7
occurred on 2020/05/06:
http://changelogs.ubuntu.com/changelogs/pool/main/p/pulseaudio/pulseaudio_11.1-1ubuntu7.7/changelog
APT no longer shows the older version as available.
I'm not certain if the upgraded version has anything to do with the odd crash. It seems like more than a coincidence, but relationship is unclear.
Comment 48•5 years ago
|
||
I've inspected the minidumps and the crashes are happening at this line (in the plugin process):
Which means the failure was here:
That's somewhat odd. FYI the plugin path it failed to open is: /tmp/tmpdp4Oxu.mozrunner/plugins/gmp-fakeopenh264/1.0
There are other interesting errors in the log, this one for instance:
[task 2020-05-15T00:17:03.398Z] 00:17:03 INFO - GECKO(1772) | [Child 1877: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:1640: Encountered media error! GMP Encode: Either init was aborted, or init failed to supply either a GMP Encoder or GMP host.
[task 2020-05-15T00:17:03.399Z] 00:17:03 INFO - GECKO(1772) | JavaScript error: resource://gre/modules/media/PeerConnection.jsm, line 129: TypeError: can't access property "pluginCrash", pc._pc is undefined
Maybe the real cause for the crash is the media error mentioned above? The fact that the following line fails means that the crash is probably being mishandled. I think you'll need someone familiar with the GMP plugin code to figure out what's going on here.
Assignee | ||
Comment 49•5 years ago
|
||
(In reply to Gabriele Svelto [:gsvelto] from comment #49)
I've inspected the minidumps and the crashes are happening at this line (in the plugin process):
Which means the failure was here:
That's somewhat odd. FYI the plugin path it failed to open is:
/tmp/tmpdp4Oxu.mozrunner/plugins/gmp-fakeopenh264/1.0
There are other interesting errors in the log, this one for instance:
[task 2020-05-15T00:17:03.398Z] 00:17:03 INFO - GECKO(1772) | [Child 1877: Main Thread]: E/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:1640: Encountered media error! GMP Encode: Either init was aborted, or init failed to supply either a GMP Encoder or GMP host. [task 2020-05-15T00:17:03.399Z] 00:17:03 INFO - GECKO(1772) | JavaScript error: resource://gre/modules/media/PeerConnection.jsm, line 129: TypeError: can't access property "pluginCrash", pc._pc is undefined
Maybe the real cause for the crash is the media error mentioned above? The fact that the following line fails means that the crash is probably being mishandled. I think you'll need someone familiar with the GMP plugin code to figure out what's going on here.
Thanks for taking a look, appreciate it.
I am not familiar with anyone in that might know about GMP plugins. Who could I needinfo for some assistance?
Reporter | ||
Comment 50•5 years ago
|
||
Bryce could you help us here? Please see comment 49 for details. Thanks!
fakeopenh264 is part of our tests and is used to simulate openh264 in the test env. I haven't touched it much. Looks like the source is here. Seems like it produces some h264 data, but doesn't do real enocding. It advertises the ability to encode and decode h264, so imagine it's loaded by the tests if we need an h264 encode/decode GMP.
We have some gtests that appear to use it. Looks like it's also used in various mochitests.
Based on the error above, I wonder if we're not getting the file in the location on disk as expected by the tests. I checked the build log and didn't see any immediately obvious failures around the fake plugin. Is it possible to debug further the build and test runners to see if the fake plugin file is making it to the destination dir, and if not, where it's being lost?
Assignee | ||
Comment 52•5 years ago
|
||
With :ajones and :bryce's help I ran the failing mochitest-media
chunk with MOZ_DISABLE_GMP_SANDBOX: '1'
environment variable, to see if the sandbox was playing a part.
Run: https://firefox-ci-tc.services.mozilla.com/tasks/VIcx2qvNSTCvwMajpzdguQ#artifacts
Log: https://firefoxci.taskcluster-artifacts.net/VIcx2qvNSTCvwMajpzdguQ/0/public/logs/live_backing.log
The same crash still occurs and it looks like it is due to the file not being on disk where expected, similar to what was said in comment 49 and comment 52.
I've pushed a new, non-artifact push to try.
Assignee | ||
Comment 53•4 years ago
|
||
Looks like the patch I submitted in Bug 1641395 is sticking so far:
The fontconfig
fix is also included in that patch, so once it lands on mozilla-central this bug can also be closed as fixed.
Reporter | ||
Comment 54•4 years ago
|
||
This is great to hear Edwin! Thanks a lot.
Given that this bug reached mozilla-central now I had a look at various Marionette related test jobs and it looks fantastic now. Instead of a ~15s delay for the first start of Firefox it's started up within ~3s now.
Assignee | ||
Comment 55•4 years ago
|
||
Thanks for checking, and sorry it took much longer than it should have.
Updated•4 years ago
|
Reporter | ||
Updated•4 years ago
|
Reporter | ||
Updated•4 years ago
|
Comment 56•8 months ago
|
||
Original Revision: https://phabricator-dev.allizom.org/D3509
Comment 57•6 months ago
|
||
m-c Uplift Approval Request
- User impact if declined: sdfasdf
- Code covered by automated testing: yes
- Fix verified in Nightly: yes
- Needs manual QE test: yes
- Steps to reproduce for manual QE testing: fasdf
- Risk associated with taking this patch: fasd
- Explanation of risk level: asdfasdf
- String changes made/needed: asdfasdf
- Is Android affected?: yes
Comment 58•6 months ago
|
||
Comment on attachment 9356719 [details]
Bug 1633101: make a small change r?phab-email-qa-author
Beta/Release Uplift Approval Request
- User impact if declined:
- Is this code covered by automated tests?: Yes
- Has the fix been verified in Nightly?: Yes
- Needs manual test from QE?: Yes
- If yes, steps to reproduce:
- List of other uplifts needed: None
- Risk to taking this patch: Low
- Why is the change risky/not risky? (and alternatives if risky):
- String changes made/needed:
- Is Android affected?: Yes
Comment 59•6 months ago
|
||
Original Revision: https://phabricator-dev.allizom.org/D3509
Comment 60•6 months ago
|
||
m-c Uplift Approval Request
- User impact if declined: Test
- Code covered by automated testing: yes
- Fix verified in Nightly: yes
- Needs manual QE test: yes
- Steps to reproduce for manual QE testing: Test
- Risk associated with taking this patch: Test
- Explanation of risk level: Test
- String changes made/needed: Test
- Is Android affected?: yes
Comment 61•6 months ago
|
||
Testing 123
Original Revision: https://phabricator-dev.allizom.org/D3554
Comment 62•6 months ago
|
||
Original Revision: https://phabricator-dev.allizom.org/D3509
Comment 63•6 months ago
|
||
m-c Uplift Approval Request
- User impact if declined: Test
- Code covered by automated testing: yes
- Fix verified in Nightly: yes
- Needs manual QE test: yes
- Steps to reproduce for manual QE testing: Test
- Risk associated with taking this patch: Test
- Explanation of risk level: Test
- String changes made/needed: Test
- Is Android affected?: yes
Comment 64•6 months ago
|
||
Testing 123
Original Revision: https://phabricator-dev.allizom.org/D3554
Description
•