Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=1826827&repo=autoland https://archive.mozilla.org/pub/firefox/tinderbox-builds/autoland-macosx64-debug/1471016717/autoland_yosemite_r7-debug_test-mochitest-other-bm106-tests1-macosx-build226.txt.gz

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.

From https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=84373661&lineNumber=14323 : Job OS X 10.10 debug Mochitest Mochitest Chrome M(c1) Machine t-yosemite-r7-0219 Start Thu Mar 16, 10:17:05 End Thu Mar 16, 10:38:18 Revision 004684088f591ff1ae6116c2c9de97bf300d170f The leaks were: 10:27:31 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| 10:27:31 INFO - | | Per-Inst Leaked| Total Rem| 10:27:31 INFO - 0 |TOTAL | 20 1776|30038327 14| 10:27:31 INFO - 93 |CancelableRunnable | 48 48| 22411 1| 10:27:31 INFO - 437 |Mutex | 32 96| 10150 3| 10:27:31 INFO - 526 |PollableEvent | 24 24| 1 1| 10:27:31 INFO - 568 |ReentrantMonitor | 40 40| 2067 1| 10:27:31 INFO - 585 |Runnable | 40 40| 65014 1| 10:27:31 INFO - 855 |nsAStreamCopier | 176 176| 693 1| 10:27:31 INFO - 1227 |nsPipe | 208 208| 865 1| 10:27:31 INFO - 1228 |nsPipeInputStream | 136 136| 865 1| 10:27:31 INFO - 1296 |nsSocketTransport | 736 736| 22 1| 10:27:31 INFO - 1297 |nsSocketTransportService | 256 256| 1 1| 10:27:31 INFO - 1311 |nsStringBuffer | 8 8| 491932 1| 10:27:31 INFO - 1356 |nsTArray_base | 8 8| 6584956 1|

this has been becoming more frequent over the weeks, 37 failures in the last week. These leaks appear to be in: devtools/server/tests/mochitest, there are 73 tests: https://dxr.mozilla.org/mozilla-central/source/devtools/server/tests/mochitest/chrome.ini :Mavericks, can you work on bisecting this leak to find the test that is leaking?

I did a bisection and narrowed it down to 2 test cases: https://treeherder.mozilla.org/#/jobs?repo=try&revision=767ba2b9270d032424f7901f3d2edcbd8f50dbf7&filter-searchStr=chrome-1 then when looking at each of the 2 tests, I got full green results: https://treeherder.mozilla.org/#/jobs?repo=try&author=jmaher@mozilla.com&filter-searchStr=chrome-1&fromchange=767ba2b9270d032424f7901f3d2edcbd8f50dbf7&tochange=55ab5a9bc0a09eb02a0cc5a1b04d7a496d2b0141 the top push on that link is with those 2 tests removed. I suspect there is something like a compounding effect between both of these test cases. test_unsafeDereference.html: https://dxr.mozilla.org/mozilla-central/source/devtools/server/tests/mochitest/test_unsafeDereference.html?q=path%3Atest_unsafeDereference.html&redirect_type=single and test_websocket-server.html: https://dxr.mozilla.org/mozilla-central/source/devtools/server/tests/mochitest/test_websocket-server.html?q=path%3Atest_websocket-server.html&redirect_type=single as a note, some of the linux references here are not for mochitest-chrome, but instead in devtools-chrome, so likely related as well. I would like to see if there is some way to find the root cause here, worse case scenario we skip those two tests on osx/debug, and determine what is going on for linux64-debug in the regular dt tests. :jryans, would you have time in the next week or so to take a look here and weigh in?

all of the linux issues are related to: devtools/client/framework/test/browser_toolbox_options_disable_buttons.js we see stuff like: [task 2017-03-26T19:58:07.185473Z] 19:58:07 INFO - GECKO(2168) | Assertion failure: JS::ObjectIsNotGray(obj), at /home/worker/workspace/build/src/js/src/jscntxtinlines.h:71 [task 2017-03-26T19:58:07.189210Z] 19:58:07 INFO - GECKO(2168) | ExceptionHandler::GenerateDump cloned child ExceptionHandler::WaitForContinueSignal waiting for continue signal... [task 2017-03-26T19:58:07.189888Z] 19:58:07 INFO - GECKO(2168) | 2503 [task 2017-03-26T19:58:07.190510Z] 19:58:07 INFO - GECKO(2168) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child [task 2017-03-26T19:58:07.373057Z] 19:58:07 INFO - GECKO(2168) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown [task 2017-03-26T19:58:07.374673Z] 19:58:07 INFO - GECKO(2168) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown [task 2017-03-26T19:58:07.375681Z] 19:58:07 INFO - GECKO(2168) | Hit MOZ_CRASH(Aborting on channel error.) at /home/worker/workspace/build/src/ipc/glue/MessageChannel.cpp:2277 [task 2017-03-26T19:58:07.376400Z] 19:58:07 INFO - GECKO(2168) | #01: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xef911c] [task 2017-03-26T19:58:07.377234Z] 19:58:07 INFO - GECKO(2168) | #02: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xedd155] [task 2017-03-26T19:58:07.377943Z] 19:58:07 INFO - GECKO(2168) | #03: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xeca12c] [task 2017-03-26T19:58:07.379147Z] 19:58:07 INFO - GECKO(2168) | #04: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xecb3bb] [task 2017-03-26T19:58:07.380909Z] 19:58:07 INFO - GECKO(2168) | #05: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xecb3e2] [task 2017-03-26T19:58:07.382115Z] 19:58:07 INFO - GECKO(2168) | #06: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xed5465] [task 2017-03-26T19:58:07.383311Z] 19:58:07 INFO - GECKO(2168) | #07: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xec77eb] [task 2017-03-26T19:58:07.388148Z] 19:58:07 INFO - GECKO(2168) | #08: ???[/lib/x86_64-linux-gnu/libpthread.so.0 +0x7e9a] [task 2017-03-26T19:58:07.395613Z] 19:58:07 INFO - GECKO(2168) | #09: clone[/lib/x86_64-linux-gnu/libc.so.6 +0xf336d] [task 2017-03-26T19:58:07.397435Z] 19:58:07 INFO - GECKO(2168) | [GFX1-]: Receive IPC close with reason=AbnormalShutdown [task 2017-03-26T19:58:07.397543Z] 19:58:07 INFO - GECKO(2168) | Hit MOZ_CRASH(Aborting on channel error.) at /home/worker/workspace/build/src/ipc/glue/MessageChannel.cpp:2277 [task 2017-03-26T19:58:07.433499Z] 19:58:07 INFO - GECKO(2168) | #01: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xef911c] [task 2017-03-26T19:58:07.449509Z] 19:58:07 INFO - GECKO(2168) | #02: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xedd155] [task 2017-03-26T19:58:07.449940Z] 19:58:07 INFO - GECKO(2168) | #03: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xeca12c] [task 2017-03-26T19:58:07.473057Z] 19:58:07 INFO - GECKO(2168) | #04: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xecb3bb] [task 2017-03-26T19:58:07.482095Z] 19:58:07 INFO - GECKO(2168) | #05: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xecb3e2] [task 2017-03-26T19:58:07.482543Z] 19:58:07 INFO - GECKO(2168) | #06: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xed5465] [task 2017-03-26T19:58:07.489508Z] 19:58:07 INFO - GECKO(2168) | #07: ???[/home/worker/workspace/build/application/firefox/libxul.so +0xec77eb] [task 2017-03-26T19:58:07.501461Z] 19:58:07 INFO - GECKO(2168) | #08: ???[/lib/x86_64-linux-gnu/libpthread.so.0 +0x7e9a] [task 2017-03-26T19:58:07.501878Z] 19:58:07 INFO - GECKO(2168) | #09: clone[/lib/x86_64-linux-gnu/libc.so.6 +0xf336d] [task 2017-03-26T19:58:07.521725Z] 19:58:07 INFO - GECKO(2168) | [Child 2431] WARNING: pipe error (3): Connection reset by peer: file /home/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 346 [task 2017-03-26T19:58:07.537618Z] 19:58:07 INFO - GECKO(2168) | Hit MOZ_CRASH(Aborting on channel error.) at /home/worker/workspace/build/src/ipc/glue/MessageChannel.cpp:2277 sounds like the assertion is causing problems, not sure if this is related to anything else, it started on March 23rd around here: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=74edf47a8ccdbca87eb78dc4645c3953c1f78815 my take is lets fix the osx issue and then work on tracking the linux issue as it has an assertion/crash, not necessarily a leak (I believe the leak is a side effect of the crash)

I'll see what I can find here.

as a note, this has reduced in frequency a bit, still up there, but a trend is going down.

This seems like it has gone back down again. I haven't had much luck reproducing so far, but I can try again if it climbs back up.

Bulk priority update of open intermittent test failure bugs. P3 => P5 https://bugzilla.mozilla.org/show_bug.cgi?id=1381960

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #24) > This seems like it has gone back down again. I haven't had much luck > reproducing so far, but I can try again if it climbs back up. It's back! (Higher frequency failures the last 4 weeks.)

I can occasionally trigger this on macOS debug builds locally, but it's intermittent, and so a bit tricky to force. When running `./mach mochitest devtools/server/tests/mochitest/test_websocket-server.html`, I sometimes get a leak report like: == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 49338 |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| | | Per-Inst Leaked| Total Rem| 0 |TOTAL | 34 2204| 1126627 14| 87 |CancelableRunnable | 48 48| 1921 1| 391 |Mutex | 96 288| 1551 3| 468 |PollableEvent | 24 24| 1 1| 508 |ReentrantMonitor | 40 40| 275 1| 526 |Runnable | 40 40| 13327 1| 817 |nsAStreamCopier | 240 240| 149 1| 1151 |nsPipe | 208 208| 175 1| 1152 |nsPipeInputStream | 136 136| 175 1| 1208 |nsSocketTransport | 832 832| 10 1| 1209 |nsSocketTransportService | 328 328| 1 1| 1223 |nsStringBuffer | 12 12| 89293 1| 1267 |nsTArray_base | 8 8| 343588 1| The test appears to wait for the client and server to shutdown correctly. The leaked objects make it seem like the issue is related to copying data at some stage. :mcmanus, do you have any tips for investigating issues like this?

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from comment #52) > The test appears to wait for the client and server to shutdown correctly. > The leaked objects make it seem like the issue is related to copying data at > some stage. > > :mcmanus, do you have any tips for investigating issues like this? You should probably try to find out what nsAStreamCopier is leaked. I tried to run the test and most of the stream copiers are created by file channels and jar channels, but I don't expect those to be leaked. There are 4 stream copiers associated to socket transports created from JS: http://searchfox.org/mozilla-central/rev/423b2522c48e1d654e30ffc337164d677f934ec3/testing/marionette/server.js#401 http://searchfox.org/mozilla-central/rev/423b2522c48e1d654e30ffc337164d677f934ec3/testing/marionette/server.js#402 http://searchfox.org/mozilla-central/rev/aa1343961fca52e8c7dab16788530da31aab7c8d/devtools/server/tests/mochitest/test_websocket-server.html#30 http://searchfox.org/mozilla-central/rev/aa1343961fca52e8c7dab16788530da31aab7c8d/devtools/server/tests/mochitest/test_websocket-server.html#31 If the leaked stream copier is the one passed to websocket channel, I would expect the channel to be leaked too, so my guess is that copier from marionette server is leaked.

In the last 7 days, there were 48 failures. They occur on macosx64-stylo-disabled and OS X 10.10. The affected build type is debug. Here is a recent log example: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=143678291&lineNumber=9779 :pbro, can you please take a look?

This will need more investigation time than I can spend, so I'm going to have to forward this to somebody else on the team. I'm thinking of Alex because he has experience investigating leaks as I recall. Alex, if you have too many in-flight perf improvements now, feel free to forward again to someone else.

This isn't the type of leak I'm used to chase. I'm used to look for document leaks, which are is 99% of the case, pure javascript. Here we have a C++ leak: 04:54:43 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| 04:54:43 INFO - | | Per-Inst Leaked| Total Rem| 04:54:43 INFO - 0 |TOTAL | 22 2200|30969177 14| 04:54:43 INFO - 98 |CancelableRunnable | 48 48| 32667 1| 04:54:43 INFO - 470 |Mutex | 96 288| 13604 3| 04:54:43 INFO - 564 |PollableEvent | 24 24| 1 1| 04:54:43 INFO - 609 |ReentrantMonitor | 40 40| 1008 1| 04:54:43 INFO - 628 |Runnable | 40 40| 83676 1| 04:54:43 INFO - 945 |nsAStreamCopier | 240 240| 654 1| 04:54:43 INFO - 1308 |nsPipe | 208 208| 834 1| 04:54:43 INFO - 1309 |nsPipeInputStream | 136 136| 834 1| 04:54:43 INFO - 1370 |nsSocketTransport | 832 832| 20 1| 04:54:43 INFO - 1371 |nsSocketTransportService | 328 328| 1 1| 04:54:43 INFO - 1385 |nsStringBuffer | 8 8| 561166 1| 04:54:43 INFO - 1430 |nsTArray_base | 8 8| 6857800 1| So, for some reason C++ is leaking all of these objects. This isn't something I know how to debug. The only thing these logs tells me is that there is only one nsSocketTransportService and PollableEvent. So, may be one of these two objects are leaked by our JS codebase and then report a C++ leak at the end??

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #17) > test_unsafeDereference.html: > https://dxr.mozilla.org/mozilla-central/source/devtools/server/tests/ > mochitest/test_unsafeDereference.html?q=path%3Atest_unsafeDereference. > html&redirect_type=single > > and test_websocket-server.html: > https://dxr.mozilla.org/mozilla-central/source/devtools/server/tests/ > mochitest/test_websocket-server.html?q=path%3Atest_websocket-server. > html&redirect_type=single About that, it looks like these two tests are mixed up: TEST-START | devtools/server/tests/mochitest/test_websocket-server.html | --DOCSHELL 0x1192c6800 == 14 [pid = 860] [id = {6470ae79-991c-df47-8bcd-187dd08e0966}] | --DOCSHELL 0x11c2b8000 == 13 [pid = 860] [id = {eee18304-cbd9-db45-87ce-593491d7f514}]| --DOCSHELL 0x12621d800 == 12 [pid = 860] [id = {dca9170f-7bb6-f548-ac61-fe4d20d942b7}] | --DOCSHELL 0x12571e000 == 11 [pid = 860] [id = {c345891f-4049-bf48-ad11-31cf3d52e1d7}] | --DOCSHELL 0x124120000 == 10 [pid = 860] [id = {b9f42f6e-3be1-3f40-bb01-deb757154c2e}] | --DOCSHELL 0x126619800 == 9 [pid = 860] [id = {b891f2e4-eb6d-ae42-a385-c6561990d4c0}] | --DOCSHELL 0x118861000 == 8 [pid = 860] [id = {869c4891-4fec-0742-b50e-4702584904b0}] | --DOCSHELL 0x124117800 == 7 [pid = 860] [id = {e1d764c3-185a-6b45-b3f8-e207a199956b}] | --DOMWINDOW == 91 (0x12661a800) [pid = 860] [serial = 607] [outer = 0x0] [url = http://mochi.test:8888/chrome/devtools/server/tests/mochitest/nonchrome_unsafeDereference.html] | --DOMWINDOW == 90 (0x1192c0000) [pid = 860] [serial = 566] [outer = 0x0] [url = about:blank] | --DOMWINDOW == 89 (0x12411a800) [pid = 860] [serial = 571] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | --DOMWINDOW == 88 (0x12621a800) [pid = 860] [serial = 589] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | --DOMWINDOW == 87 (0x125720800) [pid = 860] [serial = 583] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | --DOMWINDOW == 86 (0x126468000) [pid = 860] [serial = 601] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | --DOMWINDOW == 85 (0x124110800) [pid = 860] [serial = 595] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | --DOMWINDOW == 84 (0x119837000) [pid = 860] [serial = 577] [outer = 0x0] [url = chrome://mochitests/content/chrome/devtools/server/tests/mochitest/inspector-styles-data.html] | ++DOMWINDOW == 85 (0x1192c0000) [pid = 860] [serial = 617] [outer = 0x12e4eb000] | MEMORY STAT | vsize 4747MB | residentFast 692MB | heapAllocated 112MB TEST-OK | devtools/server/tests/mochitest/test_websocket-server.html | took 7471ms nonchrome_unsafeDereference.html document, loaded in an iframe from test_unsafeDereference.html ends up being unloaded during the websocket test.

This bug has failed 42 times in the last 7 days. Most of the fails are on OSX and a few of them are on Windows64 and macosx64. The build type is debug. Here is a recent fail log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=146561423&lineNumber=8627 And here is part of the log: INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 902 13:28:20 INFO - 13:28:20 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| 13:28:20 INFO - | | Per-Inst Leaked| Total Rem| 13:28:20 INFO - 0 |TOTAL | 22 2204|31316109 14| 13:28:20 INFO - 98 |CancelableRunnable | 48 48| 32829 1| 13:28:20 INFO - 469 |Mutex | 96 288| 13534 3| 13:28:20 INFO - 564 |PollableEvent | 24 24| 1 1| 13:28:20 INFO - 608 |ReentrantMonitor | 40 40| 1004 1| 13:28:20 INFO - 627 |Runnable | 40 40| 84254 1| 13:28:20 INFO - 943 |nsAStreamCopier | 240 240| 654 1| 13:28:20 INFO - 1307 |nsPipe | 208 208| 835 1| 13:28:20 INFO - 1308 |nsPipeInputStream | 136 136| 835 1| 13:28:20 INFO - 1370 |nsSocketTransport | 832 832| 20 1| 13:28:20 INFO - 1371 |nsSocketTransportService | 328 328| 1 1| 13:28:20 INFO - 1385 |nsStringBuffer | 12 12| 561777 1| 13:28:20 INFO - 1430 |nsTArray_base | 8 8| 6901931 1| 13:28:20 INFO - 13:28:20 INFO - nsTraceRefcnt::DumpStatistics: 1549 entries 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 CancelableRunnable 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 3 Mutex 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 PollableEvent 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 ReentrantMonitor 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 Runnable 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsAStreamCopier 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsPipe 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsPipeInputStream 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsSocketTransport 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsSocketTransportService 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsStringBuffer 13:28:20 INFO - TEST-INFO | leakcheck | default process: leaked 1 nsTArray_base 13:28:20 ERROR - TEST-UNEXPECTED-FAIL | leakcheck | default process: 2204 bytes leaked (CancelableRunnable, Mutex, PollableEvent, ReentrantMonitor, Runnable, ...) 13:28:20 INFO - 13:28:20 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 909 13:28:20 INFO - 13:28:20 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| 13:28:20 INFO - | | Per-Inst Leaked| Total Rem| 13:28:20 INFO - 0 |TOTAL | 51 0| 45114 0| Hi :pbro: Can you please take a look at this bug. It failed a lot in the last days.

Following up on comment 17 and comparing https://treeherder.mozilla.org/#/jobs?repo=try&revision=8781443831a66e8296b57e0cce96fcc760d0e074 https://treeherder.mozilla.org/#/jobs?repo=try&revision=ce3623ad1bde91fbdb37ddef866d37b814f0b8c9 it appears that skipping test_websocket-server.html and test_unsafeDereference.html effectively avoids the leak on osx. I see no correlation between the change log of test_unsafeDeference.html and this bug. However, failures in this bug started just days after test_websocket-server.html was added by bug 1286281 -- let's have a closer look at that...

Still no leaks if only test_websocket-server.html is skipped: https://treeherder.mozilla.org/#/jobs?repo=try&revision=53e10bdf435c5d440478c20a0610357edba4caec I'm going to go ahead and skip that test on osx. Hopefully this will provide a useful clue to the source of the leak and we can get that fixed and re-enabled soon. I'm going to switch the ni to :ochameau since it is unclear to me if he is still investigating.

Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/488a046d894d Skip test_websocket-server.html on osx, to avoid intermittent leaks; r=me, a=test-only

This is going to be fixed by bug 1426906. The reports left are going to be specific to older branch that don't have comment 66 disabling.