1691128 - Early content process startup missing in profiles

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P2)

Description

[Markus Stange [:mstange]]

Example profile: https://share.firefox.dev/3cIqN0H
We're missing all the interesting bits during content process startup. This makes it hard to investigate slow process startup.

The problem does not occur when the profiler is started with the MOZ_PROFILER_STARTUP environment variable.

When the problem appears, it looks like the SamplerThread is stopped once mozilla::dom::ContentChild::RecvInitProfiler runs in the content process. Then, a new SamplerThread is started.

Comment 1

[Markus Stange [:mstange]]

This is a regression from bug 1590706. I'm surprised it took us this long to catch it. We need to add a test for this, but I'm not sure what the test could look like.

When the connection to the parent process is established, we restart the profiler because the active browsing context ID changed. It changes from zero to the tab that the profiler was started on. It starts out zero because we're missing code to propagate it via MOZ_PROFILER_STARTUP_* environment variables to the child process.

Comment 2

[Markus Stange [:mstange]]

Attachment: Bug 1691128 - Propagate active browsing context ID to subprocesses via env vars so that early process startup samples aren't discarded when the real value is sent via ProfilerInitParams in the EnsureProfilerStarted IPC message. r=gerald

Comment 3

[Markus Stange [:mstange]]

Profile with fix: https://share.firefox.dev/3trVVaZ

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4cdbb5e25ce5
Propagate active browsing context ID to subprocesses via env vars so that early process startup samples aren't discarded when the real value is sent via ProfilerInitParams in the EnsureProfilerStarted IPC message. r=gerald

Comment 5

[Bogdan Tara[:bogdan_tara | bogdant]]

Backed out changeset 4cdbb5e25ce5 (bug 1691128) for browser_startup_content_mainthreadio.js.

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&fromchange=5a9070caf537427a458768bd36587005df9a623e&test_paths=browser%2Fbase%2Fcontent%2Ftest%2Fperformance&selectedTaskRun=dZgPUMkbRlivICasslekiQ.0&tochange=81f61341e5096c50bcedae1dde4def22e5d0a558

Backout link: https://hg.mozilla.org/integration/autoland/rev/81f61341e5096c50bcedae1dde4def22e5d0a558

Failure log: https://treeherder.mozilla.org/logviewer?job_id=329239241&repo=autoland&lineNumber=2406

[task 2021-02-08T15:56:01.652Z] 15:56:01     INFO - TEST-START | browser/base/content/test/performance/browser_startup_content_mainthreadio.js
[task 2021-02-08T15:56:01.660Z] 15:56:01     INFO - TEST-INFO | started process screentopng
[task 2021-02-08T15:56:02.230Z] 15:56:02     INFO - TEST-INFO | screentopng: exit 0
[task 2021-02-08T15:56:02.230Z] 15:56:02     INFO - Buffered messages logged at 15:56:01
[task 2021-02-08T15:56:02.231Z] 15:56:02     INFO - Entering test bound 
[task 2021-02-08T15:56:02.231Z] 15:56:02     INFO - known main thread IO paths for Web Content process:
[task 2021-02-08T15:56:02.231Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1, listedPath: GreD:omni.ja
[task 2021-02-08T15:56:02.232Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1, listedPath: XCurProcD:omni.ja
[task 2021-02-08T15:56:02.232Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/browser/features/[e-mail] - ignoreIfUnused: true, stat: 1, listedPath: XREAppFeat:[e-mail]
[task 2021-02-08T15:56:02.232Z] 15:56:02     INFO - Buffered messages finished
[task 2021-02-08T15:56:02.233Z] 15:56:02     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Found profile for Web Content process - 
[task 2021-02-08T15:56:02.233Z] 15:56:02     INFO - Stack trace:
[task 2021-02-08T15:56:02.234Z] 15:56:02     INFO - chrome://mochikit/content/browser-test.js:test_ok:1323
[task 2021-02-08T15:56:02.234Z] 15:56:02     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content_mainthreadio.js:null:305
[task 2021-02-08T15:56:02.235Z] 15:56:02     INFO - known main thread IO paths for Privileged Content process:
[task 2021-02-08T15:56:02.235Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1, listedPath: GreD:omni.ja
[task 2021-02-08T15:56:02.235Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1, listedPath: XCurProcD:omni.ja
[task 2021-02-08T15:56:02.237Z] 15:56:02     INFO - TEST-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | profile for Privileged Content process not found - 
[task 2021-02-08T15:56:02.238Z] 15:56:02     INFO - known main thread IO paths for WebExtensions process:
[task 2021-02-08T15:56:02.238Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/omni.ja - stat: 1, listedPath: GreD:omni.ja
[task 2021-02-08T15:56:02.239Z] 15:56:02     INFO -   /builds/worker/workspace/build/application/firefox/browser/omni.ja - stat: 1, listedPath: XCurProcD:omni.ja
[task 2021-02-08T15:56:02.239Z] 15:56:02     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-08T15:56:02.239Z] 15:56:02     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | Found profile for WebExtensions process - 
[task 2021-02-08T15:56:02.240Z] 15:56:02     INFO - Stack trace:
[task 2021-02-08T15:56:02.240Z] 15:56:02     INFO - chrome://mochikit/content/browser-test.js:test_ok:1323
[task 2021-02-08T15:56:02.241Z] 15:56:02     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_content_mainthreadio.js:null:305
[task 2021-02-08T15:56:02.242Z] 15:56:02     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | No unexpected main thread I/O during startup - 
[task 2021-02-08T15:56:02.242Z] 15:56:02     INFO - Leaving test bound 
[task 2021-02-08T15:56:02.243Z] 15:56:02     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'MarionetteEvents'"]
[task 2021-02-08T15:56:02.244Z] 15:56:02     INFO - GECKO(1534) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-02-08T15:56:02.244Z] 15:56:02     INFO - GECKO(1534) | MEMORY STAT | vsize 2956MB | residentFast 347MB | heapAllocated 154MB
[task 2021-02-08T15:56:02.247Z] 15:56:02     INFO - TEST-OK | browser/base/content/test/performance/browser_startup_content_mainthreadio.js | took 55ms

Comment 6

[Bogdan Tara[:bogdan_tara | bogdant]]

Also seeing the following starting with the backed out changes: https://treeherder.mozilla.org/logviewer?job_id=329244617&repo=autoland&lineNumber=3663

Comment 7

[Markus Stange [:mstange]]

I think the bug was that I had an unintended != 0 check in the startup env var parsing, which was crashing content processes that were launched while the profiler was running with an "active browsing context ID" of zero.

Better attempt:
https://treeherder.mozilla.org/jobs?repo=try&revision=2b3650fc83a7e5742df2ac2697908c33c38b98e0

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/40211fea2814
Propagate active browsing context ID to subprocesses via env vars so that early process startup samples aren't discarded when the real value is sent via ProfilerInitParams in the EnsureProfilerStarted IPC message. r=gerald

Comment 9

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/40211fea2814