Closed Bug 1633101 Opened 5 years ago Closed 4 years ago

Slow first startup of 64bit Firefox builds on ubuntu1804-test workers due to missing font cache

Categories

(Firefox Build System :: Task Configuration, defect)

Product:
Firefox Build System
Component:
Task Configuration
Type:
defect

Tracking

(firefox79 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla79
Tracking Flags:
Tracking Status
firefox79 --- fixed

People

(Reporter: whimboo, Assigned: egao)

References

(Blocks 1 open bug)

Details

(Keywords: perf)

Attachments

(2 files)

Bug 1633101 - consolidate pulseaudio initialization process on linux and migrate to x64 fontconfig package
47 bytes, text/x-phabricator-request
Details | Review
Bug 1633101 - update base ubuntu1804 docker image and install fontconfig:x64 instead of fontconfig:i386
47 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:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=f72c5a24723c89711131680979f5e6c795d845b5&selectedJob=299341845

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:

https://searchfox.org/mozilla-central/rev/b8fbb6ead517720daf0b0211115f407b4b951c74/toolkit/components/telemetry/app/TelemetryEnvironment.jsm#1970

Chris, can you please check what's going that horribly wrong here?

Flags: needinfo?(felash)
Flags: needinfo?(chutten)

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?

Flags: needinfo?(egao)

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:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6114b677a6796fdb5287b877d979b1fdc591d8ec&selectedJob=299374925

[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.

Indeed, I don't see anything about updating the font cache in the test-system-setup script:

https://searchfox.org/mozilla-central/source/taskcluster/docker/recipes/ubuntu1804-test-system-setup.sh

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.

Flags: needinfo?(jmaher)
Flags: needinfo?(felash)
Flags: needinfo?(chutten)

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?

Component: Telemetry → Task Configuration
Product: Toolkit → Firefox Build System

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.

Flags: needinfo?(felash)

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)

https://searchfox.org/mozilla-central/rev/5470b66539234e52e76bc2176d9bec12325fc555/toolkit/components/telemetry/TelemetryStartup.jsm#43-56

So that could only be Ci.nsICrashReporter.annotateCrashReport(). So we may need Chris to help us here.

Flags: needinfo?(felash) → needinfo?(chutten)

there are a few things here:

  1. end users will most likely not have these custom changes, so we are testing in a vacuum
  2. I agree every non standard thing should have a reason documented
  3. 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.
Flags: needinfo?(jmaher)

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:

  1. click "add new job (search)" from the dropdown
  2. check "use full job list"
  3. 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!

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?

Flags: needinfo?(chutten)

(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.

Flags: needinfo?(gsvelto)

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:

https://searchfox.org/mozilla-central/rev/158bac3df3a1890da55bdb6ffdaf9a7ffc0bfb0a/toolkit/crashreporter/nsExceptionHandler.cpp#2427-2434

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.

Flags: needinfo?(gsvelto)

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.

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.

See Also: → 1443437
Blocks: 1540367

I can also see that for Marionette and Wd jobs on Linux 64. Here an example:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299755255&repo=mozilla-central&lineNumber=1080-1081

[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.

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

(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.

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.

https://searchfox.org/mozilla-central/rev/158bac3df3a1890da55bdb6ffdaf9a7ffc0bfb0a/taskcluster/docker/recipes/ubuntu1804-test-system-setup.sh#92

I just pushed a try build to check that:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b8a5acfddea0fa213a5a2784d2b3b55ef9e3a610

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.

Flags: needinfo?(egao) → needinfo?(jmaher)
Summary: TelemetryStartup causes 11s of startup delay for Firefox on new Ubuntu 18.04 docker images for CI → Slow first startup of 64bit Firefox builds on ubuntu1804-test workers due to missing font cache

yes, we have web-platform-tests (m-c only as tier-2, also requires --full to run on try server)

Flags: needinfo?(jmaher)

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?

Blocks: linux1804-failures
Flags: needinfo?(egao)

(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.

Flags: needinfo?(egao)
Assignee: nobody → egao

(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.

Flags: needinfo?(rjesup)
Flags: needinfo?(drno)

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.

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.

Flags: needinfo?(egao)
Flags: needinfo?(egao)
Keywords: leave-open

Added a leave-open keyword to monitor the bug once both patches land.

Pushed by egao@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ce270ccc8290 remove redundant pulseaudio initializations for linux tests r=jmaher
Pushed by egao@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/fd6537bc153f remove redundant pulseaudio initializations for linux tests r=jmaher https://hg.mozilla.org/integration/autoland/rev/b85aebbd6fcc update base ubuntu1804 docker image and install fontconfig:x64 instead of fontconfig:i386 r=whimboo,jmaher

Relanding because I think the failure was caused by me landing only the first portion of the patch.

Flags: needinfo?(egao)

Ok, so looks like something else went wrong. Not sure why the try push didn't fail but autoland did. Investigating,.

Flags: needinfo?(egao)
Attachment #9147527 - Attachment description: Bug 1633101 - remove redundant pulseaudio initializations for linux tests → Bug 1633101 - consolidate pulseaudio initialization process on linux and migrate to x64 fontconfig package
Pushed by egao@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/4123014cf744 consolidate pulseaudio initialization process on linux and migrate to x64 fontconfig package r=jmaher
Flags: needinfo?(egao)

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

try push: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&resultStatus=superseded%2Cusercancel%2Cretry%2Cpending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=b9f005f1044d2bb1ce78c52142677465b490e5b7

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

Flags: needinfo?(egao)
Flags: needinfo?(rjesup) → needinfo?(dminor)

Test failure of dom/media/tests/mochitest/test_getUserMedia_basicAudio_loopback.html now has an intermittent bug filed against it, Bug 1637824.

See Also: → 1637824

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?

Flags: needinfo?(drno)
Flags: needinfo?(dminor)

(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.

Flags: needinfo?(dminor)

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.

Flags: needinfo?(dminor)

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.

(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, not debug.

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).

(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.

try push: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&resultStatus=superseded%2Cusercancel%2Cretry%2Cpending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=2afcc1a94ef92f749875fffdb7c698c31443e24a

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.

(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 installed fontconfig from i386 to x64 causes multiple tests that use pulseaudio 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.

(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 installed fontconfig from i386 to x64 causes multiple tests that use pulseaudio 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  ???

The push is here: https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&resultStatus=superseded%2Cusercancel%2Cretry%2Cpending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&classifiedState=unclassified&revision=4f1949a303bcd1ac63e65463b7f7ba1d18686c9a&selectedTaskRun=R_8d1891SwSSWSK01JFb8Q-0

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.

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

Flags: needinfo?(gsvelto)

After some more digging, I found some more possibly relevant information:

  • when installing current version of fontconfig, it also prompts to install various pulseaudio related libraries.
  • the pulseaudio libraries are currently version 1:11.1-1ubuntu7
  • the pulsaeudio libraries currently installed in the docker image used in CI is 1: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.

I've inspected the minidumps and the crashes are happening at this line (in the plugin process):

https://searchfox.org/mozilla-central/rev/3ce874dc2703831af3e5ef3a1d216ffd08057fa5/dom/media/gmp/GMPChild.cpp#506

Which means the failure was here:

https://searchfox.org/mozilla-central/rev/3ce874dc2703831af3e5ef3a1d216ffd08057fa5/dom/media/gmp/GMPChild.cpp#495

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.

Flags: needinfo?(gsvelto)

(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):

https://searchfox.org/mozilla-central/rev/3ce874dc2703831af3e5ef3a1d216ffd08057fa5/dom/media/gmp/GMPChild.cpp#506

Which means the failure was here:

https://searchfox.org/mozilla-central/rev/3ce874dc2703831af3e5ef3a1d216ffd08057fa5/dom/media/gmp/GMPChild.cpp#495

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?

Bryce could you help us here? Please see comment 49 for details. Thanks!

Flags: needinfo?(bvandyk)

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?

Flags: needinfo?(bvandyk)

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.

https://treeherder.mozilla.org/#/jobs?repo=try&group_state=expanded&revision=ca301c9a81fc5f9d8c8e8bce66ba9263135482b0

Looks like the patch I submitted in Bug 1641395 is sticking so far:

https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&revision=0db93079c806a61ae9bb226fad3ae7d291d73506

The fontconfig fix is also included in that patch, so once it lands on mozilla-central this bug can also be closed as fixed.

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.

Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox79: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla79

Thanks for checking, and sorry it took much longer than it should have.

See Also: → 1651542
See Also: → 1670290
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: