Closed Bug 1489745 Opened 7 years ago Closed 7 years ago

Intermittent devtools/client/performance/test/browser_perf-recording-selected-04.js | Test timed out -

Categories

(DevTools :: Performance Tools (Profiler/Timeline), defect, P2)

Product:
DevTools
Component:
Performance Tools (Profiler/Timeline)
Type:
defect

Tracking

(firefox65 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 65
Tracking Flags:
Tracking Status
firefox65 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: julienw)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell needswork])

Attachments

(3 files)

Bug 1489745 - reduce overhead of the performance test that also selects the memory
46 bytes, text/x-phabricator-request
Details | Review
Bug 1489745 - Reduce the buffer size for all tests
46 bytes, text/x-phabricator-request
Details | Review
Bug 1489745 - Convert the preference sample-frequency-khz to hz
46 bytes, text/x-phabricator-request
Details | Review
Filed by: ccoroiu [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=198211201&repo=mozilla-central https://queue.taskcluster.net/v1/task/fJ-_m4QaQo2cyusXXrOVow/runs/0/artifacts/public/logs/live_backing.log 07:32:09 INFO - TEST-START | devtools/client/performance/test/browser_perf-recording-selected-04.js 07:32:09 INFO - GECKO(8328) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#2725348839496649. 07:32:10 INFO - GECKO(8328) | ++DOCSHELL 0000024B94AD2800 == 2 [pid = 1744] [id = {2afdb4c6-03b2-400e-b219-a1facf073901}] 07:32:10 INFO - GECKO(8328) | ++DOMWINDOW == 3 (0000024B95029A00) [pid = 1744] [serial = 181] [outer = 0000000000000000] 07:32:10 INFO - GECKO(8328) | ++DOMWINDOW == 4 (0000024B928A8800) [pid = 1744] [serial = 182] [outer = 0000024B95029A00] 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 19 (000001E4C4027400) [pid = 8328] [serial = 729] [outer = 0000000000000000] [url = about:blank] 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 18 (000001E4D38ED200) [pid = 8328] [serial = 734] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 17 (000001E4D488D200) [pid = 8328] [serial = 736] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 16 (000001E4CF4DBA00) [pid = 8328] [serial = 732] [outer = 0000000000000000] [url = chrome://devtools/content/performance/index.xul] 07:32:10 INFO - GECKO(8328) | ++DOMWINDOW == 5 (0000024B94AAA400) [pid = 1744] [serial = 183] [outer = 0000024B95029A00] 07:32:10 INFO - GECKO(8328) | Initializing a performance panel. 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 15 (000001E4CE65DC00) [pid = 8328] [serial = 735] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 07:32:10 INFO - GECKO(8328) | --DOMWINDOW == 14 (000001E4CEAEFC00) [pid = 8328] [serial = 737] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 07:32:11 INFO - GECKO(8328) | ++DOCSHELL 000001E4C40EC800 == 7 [pid = 8328] [id = {1daec200-5caa-40bc-b216-6c7dcc2aba67}] 07:32:11 INFO - GECKO(8328) | ++DOMWINDOW == 15 (000001E4CF4EC600) [pid = 8328] [serial = 739] [outer = 0000000000000000] 07:32:11 INFO - GECKO(8328) | ++DOMWINDOW == 16 (000001E4CE63E400) [pid = 8328] [serial = 740] [outer = 000001E4CF4EC600] 07:32:11 INFO - GECKO(8328) | ++DOMWINDOW == 17 (000001E4CE640000) [pid = 8328] [serial = 741] [outer = 000001E4CF4EC600] 07:32:12 INFO - GECKO(8328) | ++DOCSHELL 000001E4CE9D1000 == 8 [pid = 8328] [id = {d8de9c88-7036-4fa6-be85-4fc6b6046ac0}] 07:32:12 INFO - GECKO(8328) | ++DOMWINDOW == 18 (000001E4CF4ECC00) [pid = 8328] [serial = 742] [outer = 0000000000000000] 07:32:12 INFO - GECKO(8328) | ++DOMWINDOW == 19 (000001E4CE64A400) [pid = 8328] [serial = 743] [outer = 000001E4CF4ECC00] 07:32:12 INFO - GECKO(8328) | [Parent 8328, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 1125 07:32:14 INFO - GECKO(8328) | Waiting for event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] for 1 time(s). 07:32:14 INFO - GECKO(8328) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-started"]. 07:32:14 INFO - GECKO(8328) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: [{}]. 07:32:14 INFO - GECKO(8328) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [100]. 07:32:15 INFO - GECKO(8328) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received. 07:32:15 INFO - GECKO(8328) | ++DOCSHELL 000001E4CDFE3000 == 9 [pid = 8328] [id = {a1ebc882-31c0-448a-a23b-4e1c569d43b9}] 07:32:15 INFO - GECKO(8328) | ++DOMWINDOW == 20 (000001E4CF4EE200) [pid = 8328] [serial = 744] [outer = 0000000000000000] 07:32:15 INFO - GECKO(8328) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received. 07:32:15 INFO - GECKO(8328) | --DOCSHELL 0000024B94AD0000 == 1 [pid = 1744] [id = {6133eacc-d36d-43f1-942f-15fb1aa02363}] 07:32:15 INFO - GECKO(8328) | Event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] received. 07:32:16 INFO - GECKO(8328) | ++DOMWINDOW == 21 (000001E4CEAEFC00) [pid = 8328] [serial = 745] [outer = 000001E4CF4EE200] 07:32:16 INFO - GECKO(8328) | ++DOCSHELL 000001E4D2B9D800 == 10 [pid = 8328] [id = {8201f957-6dd7-4fe9-9cbd-a2d185167879}] 07:32:16 INFO - GECKO(8328) | ++DOMWINDOW == 22 (000001E4D488D600) [pid = 8328] [serial = 746] [outer = 0000000000000000] 07:32:17 INFO - GECKO(8328) | ++DOMWINDOW == 23 (000001E4CEAF0C00) [pid = 8328] [serial = 747] [outer = 000001E4D488D600] 07:32:18 INFO - GECKO(8328) | --DOCSHELL 000001BCABA71000 == 0 [pid = 6960] [id = {dae8b73d-155a-44e9-b57d-ec1a4d12ed57}] 07:32:18 INFO - GECKO(8328) | --DOMWINDOW == 3 (0000016393903800) [pid = 8876] [serial = 104] [outer = 0000000000000000] [url = about:blank] 07:32:23 INFO - GECKO(8328) | --DOMWINDOW == 2 (00000163911A7000) [pid = 8876] [serial = 106] [outer = 0000000000000000] [url = about:blank] 07:32:34 INFO - GECKO(8328) | --DOMWINDOW == 1 (000001BCB1BEDC00) [pid = 6960] [serial = 103] [outer = 0000000000000000] [url = about:blank] 07:32:38 INFO - GECKO(8328) | --DOMWINDOW == 0 (000001BCABAC7000) [pid = 6960] [serial = 104] [outer = 0000000000000000] [url = about:blank] 07:32:44 INFO - GECKO(8328) | ++DOCSHELL 000001E4D390E000 == 11 [pid = 8328] [id = {cfe7a354-33fa-4da7-80dc-7db11f353687}] 07:32:44 INFO - GECKO(8328) | ++DOMWINDOW == 24 (000001E4D374FC00) [pid = 8328] [serial = 748] [outer = 0000000000000000] 07:33:58 INFO - GECKO(8328) | ++DOMWINDOW == 25 (000001E4DF29CC00) [pid = 8328] [serial = 749] [outer = 000001E4D374FC00] 07:35:17 INFO - JavaScript error: jar:file:///Z:/task_1536388479/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 762: TypeError: this._db is undefined, can't access property "createAsyncStatement" of it 07:36:20 INFO - GECKO(8328) | --DOMWINDOW == 4 (0000024B95029600) [pid = 1744] [serial = 178] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#5433823887604086] 07:36:25 INFO - GECKO(8328) | --DOMWINDOW == 3 (0000024B94AA8800) [pid = 1744] [serial = 180] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#5433823887604086] 07:42:15 INFO - TEST-INFO | started process screenshot 07:42:15 INFO - TEST-INFO | screenshot: exit 0 07:42:15 INFO - Buffered messages logged at 07:32:09 07:42:15 INFO - Entering test bound 07:42:15 INFO - Buffered messages logged at 07:34:42 07:42:15 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2 07:42:15 INFO - Buffered messages logged at 07:38:10 07:42:15 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1 07:42:15 INFO - Buffered messages finished 07:42:15 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-selected-04.js | Test timed out - 07:42:15 INFO - finish() was called, cleaning up... 07:44:17 INFO - JavaScript error: jar:file:///Z:/task_1536388479/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 762: TypeError: this._db is undefined, can't access property "createAsyncStatement" of it 07:45:42 INFO - GECKO(8328) | MEMORY STAT | vsize 8778MB | vsizeMaxContiguous 132189035MB | residentFast 646MB | heapAllocated 260MB 07:45:42 INFO - TEST-OK | devtools/client/performance/test/browser_perf-recording-selected-04.js | took 812918ms 07:45:42 INFO - Not taking screenshot here: see the one that was previously logged 07:45:42 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-selected-04.js | Found a tab after previous test timed out: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#2725348839496649 - 07:45:43 INFO - GECKO(8328) | ++DOCSHELL 000001BCABA71000 == 1 [pid = 6960] [id = {a96e4ec5-0f36-463d-acfe-8a971edecccd}] 07:45:43 INFO - GECKO(8328) | ++DOMWINDOW == 1 (000001BCB1BEDC00) [pid = 6960] [serial = 105] [outer = 0000000000000000] 07:45:43 INFO - GECKO(8328) | ++DOMWINDOW == 2 (000001BCABAC7000) [pid = 6960] [serial = 106] [outer = 000001BCB1BEDC00] 07:45:43 INFO - checking window state 07:45:43 INFO - GECKO(8328) | console.error: "Tried to send a 'tabDetached' event on an already destroyed actor 'frameTarget'" 07:45:43 INFO - GECKO(8328) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/common.js, line 471: Error: Wrong state while getting allocations:Expected 'attached', but current state is 'detached'. 07:45:45 INFO - TEST-START | devtools/client/performance/test/browser_perf-recordings-clear-01.js 07:45:45 INFO - GECKO(8328) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#5372510833444604. 07:45:45 INFO - GECKO(8328) | ++DOCSHELL 000001CDED171800 == 2 [pid = 2472] [id = {4c8a456d-395e-4236-afc1-5cb51feec57c}] 07:45:45 INFO - GECKO(8328) | ++DOMWINDOW == 3 (000001CDED12E600) [pid = 2472] [serial = 8] [outer = 0000000000000000] 07:45:45 INFO - GECKO(8328) | ++DOMWINDOW == 4 (000001CDF10A7000) [pid = 2472] [serial = 9] [outer = 000001CDED12E600] 07:45:45 INFO - GECKO(8328) | [Child 2472, Main Thread] WARNING: site security information will not be persisted: file z:/build/build/src/security/manager/ssl/nsSiteSecurityService.cpp, line 553 07:45:45 INFO - GECKO(8328) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/common.js, line 471: Error: Wrong state while getting allocations:Expected 'attached', but current state is 'detached'. 07:45:46 INFO - GECKO(8328) | ++DOMWINDOW == 5 (000001CDF36A7C00) [pid = 2472] [serial = 10] [outer = 000001CDED12E600] 07:45:46 INFO - GECKO(8328) | Initializing a performance panel. 07:45:47 INFO - GECKO(8328) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/common.js, line 471: Error: Wrong state while getting allocations:Expected 'attached', but current state is 'detached'. 07:45:50 INFO - GECKO(8328) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/common.js, line 471: Error: Wrong state while getting allocations:Expected 'attached', but current state is 'detached'. 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001E4CE9D1000 == 10 [pid = 8328] [id = {d8de9c88-7036-4fa6-be85-4fc6b6046ac0}] 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001E4C40EC800 == 9 [pid = 8328] [id = {1daec200-5caa-40bc-b216-6c7dcc2aba67}] 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001E4D2B9D800 == 8 [pid = 8328] [id = {8201f957-6dd7-4fe9-9cbd-a2d185167879}] 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001E4D390E000 == 7 [pid = 8328] [id = {cfe7a354-33fa-4da7-80dc-7db11f353687}] 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001E4CDFE3000 == 6 [pid = 8328] [id = {a1ebc882-31c0-448a-a23b-4e1c569d43b9}] 07:45:51 INFO - GECKO(8328) | ++DOCSHELL 000001E4C40DD800 == 7 [pid = 8328] [id = {12606829-8544-49e9-921d-8da221c4e0e4}] 07:45:51 INFO - GECKO(8328) | ++DOMWINDOW == 26 (000001E4C4025400) [pid = 8328] [serial = 750] [outer = 0000000000000000] 07:45:51 INFO - GECKO(8328) | ++DOMWINDOW == 27 (000001E4CD75AC00) [pid = 8328] [serial = 751] [outer = 000001E4C4025400] 07:45:51 INFO - GECKO(8328) | ++DOMWINDOW == 28 (000001E4CE65B800) [pid = 8328] [serial = 752] [outer = 000001E4C4025400] 07:45:51 INFO - GECKO(8328) | --DOCSHELL 000001638D270800 == 0 [pid = 8876] [id = {67c4c540-0c87-426c-b7be-0cdbf7d4c1b5}] 07:45:51 INFO - GECKO(8328) | JavaScript error: resource://devtools/shared/base-loader.js -> resource://devtools/server/actors/common.js, line 471: Error: Wrong state while getting allocations:Expected 'attached', but current state is 'detached'. 07:45:52 INFO - GECKO(8328) | ++DOCSHELL 000001E4D1E83800 == 8 [pid = 8328] [id = {f45eaef8-5482-41d6-b2fe-583c885380bf}] 07:45:52 INFO - GECKO(8328) | ++DOMWINDOW == 29 (000001E4D2105000) [pid = 8328] [serial = 753] [outer = 0000000000000000] 07:45:52 INFO - GECKO(8328) | ++DOMWINDOW == 30 (000001E4CE998000) [pid = 8328] [serial = 754] [outer = 000001E4D2105000] 07:45:52 INFO - GECKO(8328) | --DOCSHELL 0000024B94AD2800 == 0 [pid = 1744] [id = {2afdb4c6-03b2-400e-b219-a1facf073901}]
This looks new and "quite" frequent => bumping up the priority. This seems to happen in ccov builds only, maybe the runs are a lot slower and so they expose a race.
Priority: P5 → P2
In the screenshot for the failure, we see recording is still happening. So my guess is that these 2 lines happen too fast: https://searchfox.org/mozilla-central/rev/bdc89dfd7869e418d788b28eb60ab8d94e708a15/devtools/client/performance/test/browser_perf-recording-selected-04.js#43-44 Although the call to `startRecording` should already wait that the rerender is done, maybe there's some more waiting to do.
There have been 45 failures within the last 7 days, all of them on windows 10 x64 ccov. Example failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=201295831&repo=mozilla-central&lineNumber=8399 23:53:27 INFO - TEST-START | devtools/client/performance/test/browser_perf-recording-selected-04.js 23:53:27 INFO - GECKO(3628) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#5922574523770062. 23:53:27 INFO - GECKO(3628) | ++DOCSHELL 00000224BD473000 == 2 [pid = 2836] [id = {3c1bb262-3cf7-4240-ac31-5af444cc9f4f}] 23:53:27 INFO - GECKO(3628) | ++DOMWINDOW == 3 (00000224C3B10800) [pid = 2836] [serial = 187] [outer = 0000000000000000] 23:53:27 INFO - GECKO(3628) | ++DOMWINDOW == 4 (00000224BD4E2800) [pid = 2836] [serial = 188] [outer = 00000224C3B10800] 23:53:27 INFO - GECKO(3628) | --DOMWINDOW == 19 (000001F94D095A00) [pid = 3628] [serial = 729] [outer = 0000000000000000] [url = about:blank] 23:53:27 INFO - GECKO(3628) | --DOMWINDOW == 18 (000001F95256A200) [pid = 3628] [serial = 734] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 23:53:27 INFO - GECKO(3628) | --DOMWINDOW == 17 (000001F94FAE4200) [pid = 3628] [serial = 736] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 23:53:27 INFO - GECKO(3628) | --DOMWINDOW == 16 (000001F94FAE1400) [pid = 3628] [serial = 732] [outer = 0000000000000000] [url = chrome://devtools/content/performance/index.xul] 23:53:27 INFO - GECKO(3628) | ++DOMWINDOW == 5 (00000224C35AC000) [pid = 2836] [serial = 189] [outer = 00000224C3B10800] 23:53:28 INFO - GECKO(3628) | --DOMWINDOW == 15 (000001F94B8C8C00) [pid = 3628] [serial = 735] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 23:53:28 INFO - GECKO(3628) | --DOMWINDOW == 14 (000001F94C252C00) [pid = 3628] [serial = 737] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml] 23:53:28 INFO - GECKO(3628) | Initializing a performance panel. 23:53:28 INFO - GECKO(3628) | ++DOCSHELL 000001F941CE2800 == 7 [pid = 3628] [id = {6c32c285-1a80-4a32-a300-d9ebef4792af}] 23:53:28 INFO - GECKO(3628) | ++DOMWINDOW == 15 (000001F94FAE2000) [pid = 3628] [serial = 739] [outer = 0000000000000000] 23:53:28 INFO - GECKO(3628) | ++DOMWINDOW == 16 (000001F94AB2F000) [pid = 3628] [serial = 740] [outer = 000001F94FAE2000] 23:53:28 INFO - GECKO(3628) | ++DOMWINDOW == 17 (000001F94AB26C00) [pid = 3628] [serial = 741] [outer = 000001F94FAE2000] 23:53:29 INFO - GECKO(3628) | ++DOCSHELL 000001F941CF8000 == 8 [pid = 3628] [id = {8952924a-f478-48ce-9a6e-d4194cbd1783}] 23:53:29 INFO - GECKO(3628) | ++DOMWINDOW == 18 (000001F94FAE0800) [pid = 3628] [serial = 742] [outer = 0000000000000000] 23:53:29 INFO - GECKO(3628) | ++DOMWINDOW == 19 (000001F94AB33800) [pid = 3628] [serial = 743] [outer = 000001F94FAE0800] 23:53:30 INFO - GECKO(3628) | [Parent 3628, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 1125 23:53:32 INFO - GECKO(3628) | Waiting for event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] for 1 time(s). 23:53:32 INFO - GECKO(3628) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-started"]. 23:53:32 INFO - GECKO(3628) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: [{}]. 23:53:32 INFO - GECKO(3628) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [100]. 23:53:32 INFO - GECKO(3628) | --DOCSHELL 00000224C35D3000 == 1 [pid = 2836] [id = {b0ae9329-cbf7-4d74-8f18-59f0251dc36c}] 23:53:32 INFO - GECKO(3628) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received. 23:53:32 INFO - GECKO(3628) | ++DOCSHELL 000001F94C47E000 == 9 [pid = 3628] [id = {8d7dbf83-24d7-4a62-a831-030b432559ee}] 23:53:32 INFO - GECKO(3628) | ++DOMWINDOW == 20 (000001F94FAE1C00) [pid = 3628] [serial = 744] [outer = 0000000000000000] 23:53:32 INFO - GECKO(3628) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received. 23:53:33 INFO - GECKO(3628) | Event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] received. 23:53:33 INFO - GECKO(3628) | ++DOMWINDOW == 21 (000001F94B8C0C00) [pid = 3628] [serial = 745] [outer = 000001F94FAE1C00] 23:53:34 INFO - GECKO(3628) | ++DOCSHELL 000001F94FFC3000 == 10 [pid = 3628] [id = {7488192a-fad7-4651-9b0f-7c2e1901a5e1}] 23:53:34 INFO - GECKO(3628) | ++DOMWINDOW == 22 (000001F953017200) [pid = 3628] [serial = 746] [outer = 0000000000000000] 23:53:34 INFO - GECKO(3628) | --DOCSHELL 00000279B086F800 == 0 [pid = 3172] [id = {ae633495-cc97-4dbb-b55a-38b5545b4055}] 23:53:34 INFO - GECKO(3628) | ++DOMWINDOW == 23 (000001F94C251400) [pid = 3628] [serial = 747] [outer = 000001F953017200] 23:53:47 INFO - GECKO(3628) | --DOMWINDOW == 2 (0000026F32ED0400) [pid = 5752] [serial = 97] [outer = 0000000000000000] [url = about:blank] 23:53:52 INFO - GECKO(3628) | ++DOCSHELL 000001F950005800 == 11 [pid = 3628] [id = {9a5457b2-4937-40d6-ad61-78d6da8a4786}] 23:53:52 INFO - GECKO(3628) | ++DOMWINDOW == 24 (000001F94D095200) [pid = 3628] [serial = 748] [outer = 0000000000000000] 23:54:41 INFO - GECKO(3628) | ++DOMWINDOW == 25 (000001F95D3C0000) [pid = 3628] [serial = 749] [outer = 000001F94D095200] 23:55:02 INFO - JavaScript error: jar:file:///Z:/task_1537830416/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 762: TypeError: this._db is undefined; can't access its "createAsyncStatement" property 23:58:02 INFO - GECKO(3628) | --DOMWINDOW == 4 (00000224C3B0F000) [pid = 2836] [serial = 184] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#7373546888591669] 23:58:07 INFO - GECKO(3628) | --DOMWINDOW == 3 (00000224C35A7000) [pid = 2836] [serial = 186] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#7373546888591669] 00:02:21 INFO - TEST-INFO | started process screenshot 00:02:21 INFO - TEST-INFO | screenshot: exit 0 00:02:21 INFO - Buffered messages logged at 23:53:27 00:02:21 INFO - Entering test bound 00:02:21 INFO - Buffered messages logged at 23:55:54 00:02:21 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2 00:02:21 INFO - Buffered messages logged at 23:59:00 00:02:21 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1 00:02:21 INFO - Buffered messages finished 00:02:21 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-selected-04.js | Test timed out - 00:02:21 INFO - finish() was called, cleaning up... 00:03:21 INFO - GECKO(3628) | MEMORY STAT | vsize 8485MB | vsizeMaxContiguous 130063332MB | residentFast 598MB | heapAllocated 232MB 00:03:21 INFO - TEST-OK | devtools/client/performance/test/browser_perf-recording-selected-04.js | took 594897ms 00:03:22 INFO - Not taking screenshot here: see the one that was previously logged 00:03:22 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-selected-04.js | Found a tab after previous test timed out: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#5922574523770062 - 00:03:22 INFO - GECKO(3628) | ++DOCSHELL 00000279B0871000 == 1 [pid = 3172] [id = {fa1f638a-726c-47af-b9d1-5d28da55fd15}] 00:03:22 INFO - GECKO(3628) | ++DOMWINDOW == 3 (00000279B474CC00) [pid = 3172] [serial = 96] [outer = 0000000000000000] 00:03:22 INFO - GECKO(3628) | ++DOMWINDOW == 4 (00000279B47A5800) [pid = 3172] [serial = 97] [outer = 00000279B474CC00] 00:03:22 INFO - checking window state 00:03:22 INFO - GECKO(3628) | ++DOMWINDOW == 5 (00000279B69CAC00) [pid = 3172] [serial = 98] [outer = 00000279B474CC00] 00:03:23 INFO - GECKO(3628) | console.error: "Tried to send a 'tabDetached' event on an already destroyed actor 'frameTarget'"
Whiteboard: [stockwell needswork]
I'll look at it this week.
Assignee: nobody → felash
julienw: Hi, Do you have any updates on this? Thank you! There are 37 failures in the last 7 days. They occur on windows10-64-ccov debug.
Flags: needinfo?(felash)
Hey Eliza, I started looking at this but couldn't get a debug or a ccov build that lets me run the tests yet, so I'm a bit stuck. I'll look at it again next week as I'll be away most of the rest of this week. The fact that this happens only in ccov builds is very weird but this makes it easy to disable in this environment only if this is necessary.
Flags: needinfo?(felash)
Looks like I can run the tets with a build from a current central now, so I'll be able to look at this issue next week.
Because of the significant overhead of turning on the memory capture options, the test fails in very slow builds, eg ccov builds. This patch reduces the overhead of the capture itself by reducing the buffer size.
We reduce the profiler's buffer size for all tests, to reduce the memory pressure and the overhead. This may fix some OOM intermittent crashes.
The int preference profiler.sample-frequency-khz didn't make it possible to reduce the overhead in tests, because we could have intervals bigger than 1ms. With this change we can now do it. Depends on D8547
try in ccov: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9ef47bb013b59386800027b3e0e80cce268a4de3 For this specific test, this runs took 49 sec, while it took 60 sec on the last on mozilla-central. I don't know if that's so meaningful because I expect there's some variance, but this doesn't look bad. try in debug and opt: https://treeherder.mozilla.org/#/jobs?repo=try&revision=50b7c5310b1d49fd47b4a6a6ace8cb29faa228a5
Respinning the try build didn't trigger the right tests, I filed bug 1501213 for this, but I'll land the patch now, and observe if we still have these issues.
Actually we don't see this intermittent at all for some days now... Something else might have fixed it. I'll still land this because I think this can make the tests run master and reduce the overhead for some tests.
Pushed by jwajsberg@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/3312d8b04ebd Reduce the buffer size for all tests r=gregtatum https://hg.mozilla.org/integration/autoland/rev/2485564ba1b4 Convert the preference sample-frequency-khz to hz r=ochameau,mstange https://hg.mozilla.org/integration/autoland/rev/33b1c05d92a7 reduce overhead of the performance test that also selects the memory r=gregtatum
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: