nsIncrementalDownload causes a lot of jank with main thread I/O while downloading updates in the background
Categories
(Core :: Networking: HTTP, defect, P2)
Tracking
()
Tracking | Status | |
---|---|---|
firefox128 | --- | fixed |
People
(Reporter: florian, Assigned: acreskey, NeedInfo)
References
(Depends on 1 open bug, Blocks 1 open bug)
Details
(Keywords: perf, perf:responsiveness, Whiteboard: [necko-triaged][bhr:nsIncrementalDownload][necko-priority-queue])
Attachments
(1 file)
Updated•6 years ago
|
Comment 1•6 years ago
|
||
Reporter | ||
Comment 2•6 years ago
|
||
Comment 3•6 years ago
|
||
Reporter | ||
Comment 4•6 years ago
|
||
Comment 5•6 years ago
|
||
Comment 6•6 years ago
|
||
Comment 7•6 years ago
|
||
Reporter | ||
Comment 8•6 years ago
|
||
I find the jank in this startup profile even more impressive: https://perfht.ml/2Ezid1L Probably because I was using the fast internet connexion on a machine with slow I/O, so the main thread I/O blocked the whole time.
Comment 9•6 years ago
|
||
This could be nicely fixed with bug 1528285. Looking more into the code, observer is only an nsIRequestObserver which we can easily dispatch to the main thread. Then there is mProgressSink, for which we can do the same.
Adding dep, should it significantly delay, I can move only the writes/flushes to a bck thread.
Updated•4 years ago
|
Updated•4 years ago
|
Reporter | ||
Updated•4 years ago
|
Updated•3 years ago
|
Updated•3 years ago
|
Updated•3 years ago
|
Updated•2 years ago
|
Assignee | ||
Comment 11•2 years ago
|
||
Can this still be reproduced?
We have omt-networking in the content-process scheduled for H1, 2023, fwiw.
Comment 12•2 years ago
|
||
(In reply to Andrew Creskey [:acreskey] from comment #11)
Can this still be reproduced?
I'm not sure. Florian, do you have cycles + a machine to check this on? It may be worth trying release vs. nightly here given the work on socket process etc.
Reporter | ||
Comment 13•2 years ago
|
||
(In reply to Andrew Creskey [:acreskey] from comment #11)
Can this still be reproduced?
I haven't tried recently, but it's still visible on BHR: https://fqueze.github.io/hang-stats/#date=20230222&row=0&filter=nsIncrementalDownload
It's possible we no longer see it on Windows if updates are downloaded by a background service there.
Comment 14•2 years ago
|
||
I think comment 6 still holds.
I think we can improve things at least a little by retargetting onDataAvailable to a background thread. We'd still have MT IO with onStart/onStop, but that's just 2 calls out of many.
Implementing nsIThreadRetargetableRequest, handling onData off-main-thread and dispatching progress notifications back to the main thread should be fairly straightforward.
Updated•7 months ago
|
Comment 15•6 months ago
|
||
It does sound plausible that this bug https://bugzilla.mozilla.org/show_bug.cgi?id=1878502 is caused by Bug 1510262. In case that helps prioritize fixing it faster.
Updated•5 months ago
|
Assignee | ||
Updated•5 months ago
|
Assignee | ||
Comment 16•4 months ago
|
||
If anyone knows of a way to trigger an update download, please let me know. Would be helpful in testing.
Comment 17•4 months ago
|
||
AppUpdater.check seems to be the main entry point
I think you can use nsIUpdateService.addDownloadListener to see when downloads are happening.
Note that this part of the code needs to be hit for the IncrementalDownloader to be used - which I believe is only Linux & Mac.
Assignee | ||
Comment 18•4 months ago
|
||
Retargeting OnDataAvailable to STS to avoid main thread jank during downloads.
Reporter | ||
Comment 19•4 months ago
|
||
(In reply to Florian Quèze [:florian] from comment #13)
(In reply to Andrew Creskey [:acreskey] from comment #11)
Can this still be reproduced?
I haven't tried recently, but it's still visible on BHR: https://fqueze.github.io/hang-stats/#date=20230222&row=0&filter=nsIncrementalDownload
It's possible we no longer see it on Windows if updates are downloaded by a background service there.
I almost wrote the same comment again, it's still visible on Mac on BHR: https://fqueze.github.io/hang-stats/#date=20240518&row=0&filter=nsIncrementalDownload
A few days after the fix lands, this stack should disappear from BHR.
Comment 20•4 months ago
|
||
Comment 21•4 months ago
|
||
Backed out for causing build bustages @ nsIncrementalDownload.cpp
Backout link: https://hg.mozilla.org/integration/autoland/rev/4aaa185f94caf4e9ecaeb63ca050cea1f77d5903
Comment 22•4 months ago
|
||
Comment 23•4 months ago
|
||
Backed out for causing failures on browser_aboutPrefs_fc_patch_partialBadSize_complete.js.
[task 2024-05-25T05:11:16.474Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | Sanity check: Expected download status text should be non-empty - "0 bytes of 13.9 KB" == true -
[task 2024-05-25T05:11:16.474Z] 05:11:16 INFO - Buffered messages finished
[task 2024-05-25T05:11:16.484Z] 05:11:16 INFO - TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | Download status text should end as expected: {"actualText":"Downloading update — 1.4 of 1.4 KB","expectedSuffix":"0 bytes of 13.9 KB"} - false == true - {"filename":"chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js","name":"runAboutPrefsUpdateTest/processAboutPrefsStep/<","sourceId":2185,"lineNumber":1155,"columnNumber":20,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js","name":"processAboutPrefsStep","sourceId":2185,"lineNumber":1236,"columnNumber":7,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js","name":"runAboutPrefsUpdateTest/<","sourceId":2185,"lineNumber":1313,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js","name":"runAboutPrefsUpdateTest","sourceId":2185,"lineNumber":1315,"columnNumber":5,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js","name":"aboutPrefs_foregroundCheck_partialBadSize_complete","sourceId":2192,"lineNumber":20,"columnNumber":9,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":571,"lineNumber":1139,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":571,"lineNumber":1211,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":571,"lineNumber":1353,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":571,"lineNumber":1128,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":598,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"aboutPrefs_foregroundCheck_partialBadSize_complete@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:20:9\nhandleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*runAboutPrefsUpdateTest@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1315:5\naboutPrefs_foregroundCheck_partialBadSize_complete@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:20:9\nhandleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"runAboutPrefsUpdateTest/<@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1313:13\nasync*runAboutPrefsUpdateTest@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1315:5\naboutPrefs_foregroundCheck_partialBadSize_complete@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:20:9\nhandleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*processAboutPrefsStep@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1236:7\nrunAboutPrefsUpdateTest/<@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1313:13\nasync*runAboutPrefsUpdateTest@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1315:5\naboutPrefs_foregroundCheck_partialBadSize_complete@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:20:9\nhandleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"runAboutPrefsUpdateTest/processAboutPrefsStep/<@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1155:20\nasync*processAboutPrefsStep@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1236:7\nrunAboutPrefsUpdateTest/<@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1313:13\nasync*runAboutPrefsUpdateTest@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:1315:5\naboutPrefs_foregroundCheck_partialBadSize_complete@chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:20:9\nhandleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2024-05-25T05:11:16.485Z] 05:11:16 INFO - Stack trace:
[task 2024-05-25T05:11:16.486Z] 05:11:16 INFO - chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:runAboutPrefsUpdateTest/processAboutPrefsStep/<:1155
[task 2024-05-25T05:11:16.486Z] 05:11:16 INFO - chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:processAboutPrefsStep:1236
[task 2024-05-25T05:11:16.487Z] 05:11:16 INFO - chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:runAboutPrefsUpdateTest/<:1313
[task 2024-05-25T05:11:16.487Z] 05:11:16 INFO - chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/head.js:runAboutPrefsUpdateTest:1315
[task 2024-05-25T05:11:16.488Z] 05:11:16 INFO - chrome://mochitests/content/browser/toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js:aboutPrefs_foregroundCheck_partialBadSize_complete:20
[task 2024-05-25T05:11:16.488Z] 05:11:16 INFO - chrome://mochikit/content/browser-test.js:handleTask:1139
[task 2024-05-25T05:11:16.488Z] 05:11:16 INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1211
[task 2024-05-25T05:11:16.489Z] 05:11:16 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1353
[task 2024-05-25T05:11:16.489Z] 05:11:16 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1128
[task 2024-05-25T05:11:16.490Z] 05:11:16 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2024-05-25T05:11:16.491Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | The panel ID should equal apply - "apply" == "apply" -
[task 2024-05-25T05:11:16.492Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | The current update state should be "STATE_PENDING". Actual: "STATE_PENDING" -
[task 2024-05-25T05:11:16.493Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | There should be an active update -
[task 2024-05-25T05:11:16.493Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | The active update state should equal pending -
[task 2024-05-25T05:11:16.494Z] 05:11:16 INFO - TEST-PASS | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | The button should be enabled - true == true -
[task 2024-05-25T05:11:16.495Z] 05:11:16 INFO - Leaving test bound aboutPrefs_foregroundCheck_partialBadSize_complete
[task 2024-05-25T05:11:16.541Z] 05:11:16 INFO - GECKO(5025) | [Parent 5025, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2024-05-25T05:11:16.542Z] 05:11:16 INFO - GECKO(5025) | [Parent 5025, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2024-05-25T05:11:16.991Z] 05:11:16 INFO - GECKO(5025) | MEMORY STAT | vsize 11863MB | residentFast 679MB | heapAllocated 328MB
[task 2024-05-25T05:11:16.992Z] 05:11:16 INFO - TEST-OK | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_complete.js | took 2975ms
[task 2024-05-25T05:11:17.001Z] 05:11:17 INFO - GECKO(5025) | [Child 5149: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7fc1a256e000 == 2 [pid = 5149] [id = 27]
[task 2024-05-25T05:11:17.002Z] 05:11:17 INFO - GECKO(5025) | [Child 5149: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (7fc1a2a6d3e0) [pid = 5149] [serial = 57] [outer = 0]
[task 2024-05-25T05:11:17.004Z] 05:11:17 INFO - GECKO(5025) | [Child 5149: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 5 (7fc1a256e400) [pid = 5149] [serial = 58] [outer = 7fc1a2a6d3e0]
[task 2024-05-25T05:11:17.056Z] 05:11:17 INFO - checking window state
[task 2024-05-25T05:11:17.089Z] 05:11:17 INFO - TEST-START | toolkit/mozapps/update/tests/browser/browser_aboutPrefs_fc_patch_partialBadSize_completeBadSize.js
Updated•4 months ago
|
Assignee | ||
Comment 24•4 months ago
|
||
Kershaw, as far as I can tell this change (retarget OnDataAvailable for nsIncrementalDownload.cpp) was backed out because it fails with the socket process enabled.
Test group - Mochitest browser-chrome run with networking on socket process enabled.
If this is indeed the reason for the failure, is it reasonable to skip the retargeting of nsIncrementalDownload if the socketProcess is running?
i.e. nsIOService::UseSocketProcess()
Comment 25•4 months ago
|
||
(In reply to Andrew Creskey [:acreskey] from comment #24)
Kershaw, as far as I can tell this change (retarget OnDataAvailable for nsIncrementalDownload.cpp) was backed out because it fails with the socket process enabled.
Test group - Mochitest browser-chrome run with networking on socket process enabled.
If this is indeed the reason for the failure, is it reasonable to skip the retargeting of nsIncrementalDownload if the socketProcess is running?
i.e.nsIOService::UseSocketProcess()
Yeah, it's reasonable to me.
Or we can just skip running that test with socket process by adding skip-if = ["socketprocess_networking"]
.
Up to you. :)
Comment 26•4 months ago
|
||
Comment 27•4 months ago
|
||
bugherder |
Assignee | ||
Comment 29•3 months ago
|
||
With the fix landed I no longer see nsIncrementalDownload::OnDataAvailable()
in the hang report.
Looking back from the start of the year, I calculated that nsIncrementalDownload::OnDataAvailable
made up ~80% of the time spent janked due to nsIncrementalDownload:
https://fqueze.github.io/hang-stats/#date=20240101&row=9&filter=nsIncrementalDownload
The remainder comes from nsIncrementalDownload::CallOnStopRequest()
, which we can still traces of:
https://fqueze.github.io/hang-stats/#date=20240610&row=1&filter=nsIncrementalDownload
Florian, it's not clear to me how serious the nsIncrementalDownload::CallOnStopRequest()
hangs are, relative to other hangs.
We have a new API to allow for OnStopRequest OMT (OnDataFinished), so we could consider moving that in a new bug, if you think it could be worth it.
Also is there a way to see top 100 or top 200 hangs?
https://fqueze.github.io/hang-stats/#date=20240610&row=0&filter=
Description
•