Closed Bug 1630208 Opened 5 years ago Closed 4 years ago

Intermittent leakcheck | default 296 bytes leaked (xpcAccessibleDocument, xpcAccessibleGeneric, xpcAccessibleHyperText)

Categories

(Core :: Disability Access APIs, defect, P5)

Product:
Core
Component:
Disability Access APIs
Type:
defect

Tracking

()

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

People

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

References

(Blocks 2 open bugs, Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell disabled][stockwell needswork:owner])

Attachments

(6 files)

Bug 1630208 - disable browser_test_zoom_text.js on linux 64 fission for frequent failures r=#intermittent-reviewers
(deleted), text/x-phabricator-request
Details
allocation stack of leaking object
(deleted), text/plain
Details
Bug 1630208 part 1: Assert that we don't add a shut down DocAccessibleParent to the remote XPC cache in DocManager::GetXPCDocument.
(deleted), text/x-phabricator-request
Details
Bug 1630208 part 2: Drop events for DocAccessibleParents which are already shut down.
(deleted), text/x-phabricator-request
Details
Bug 1630208 part 3: Clean up the remote XPC document accessible cache on shutdown.
(deleted), text/x-phabricator-request
Details
Bug 1630208 part 4: Re-enable accessible/tests/browser/hittest/browser_test_zoom_text.js.
(deleted), text/x-phabricator-request
Details

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=297702975&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/C8_4kK8aQnSVRFt-8zaXVQ/runs/0/artifacts/public/logs/live_backing.log

[task 2020-04-15T09:25:43.396Z] 09:25:43 INFO - TEST-START | accessible/tests/browser/hittest/browser_test_zoom_text.js
[task 2020-04-15T09:25:43.420Z] 09:25:43 INFO - GECKO(1225) | [Child 1313: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f912876a000 == 2 [pid = 1313] [id = {9eb63a55-6e5c-4702-aae3-4fb01b91d089}]
[task 2020-04-15T09:25:43.420Z] 09:25:43 INFO - GECKO(1225) | [Child 1313: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (0x7f912f7a33c0) [pid = 1313] [serial = 21] [outer = (nil)]
[task 2020-04-15T09:25:43.420Z] 09:25:43 INFO - GECKO(1225) | [Child 1313: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 12 (0x7f912876a400) [pid = 1313] [serial = 22] [outer = 0x7f912f7a33c0]
[task 2020-04-15T09:25:43.460Z] 09:25:43 INFO - GECKO(1225) | [Child 1727: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7fa4fb3d8000 == 0 [pid = 1727] [id = {4eb0e1b2-6a3e-4fc9-9d9b-d7b480b936fd}] [url = http://example.net/document-builder.sjs?html=%3Chtml%3E%0A++++++++++%3Chead%3E%0A++++++++++++%3Cmeta+charset%3D%22utf-8%22%2F%3E%0A++++++++++++%3Ctitle%3EAccessibility+Fission+Test%3C%2Ftitle%3E%0A++++++++++%3C%2Fhead%3E%0A++++++++++%3Cbody+id%3D%22default-iframe-body-id%22%3E%3Cp+id%3D%22p1%22%3Epara+1%3C%2Fp%3E%3Cp+id%3D%22p2%22%3Epara+2%3C%2Fp%3E%3C%2Fbody%3E%0A++++++++%3C%2Fhtml%3E]
[task 2020-04-15T09:25:43.464Z] 09:25:43 INFO - GECKO(1225) | [Parent 1225, Main Thread] WARNING: '!mName', file /builds/worker/checkouts/gecko/editor/libeditor/EditAggregateTransaction.cpp, line 92
[task 2020-04-15T09:25:43.464Z] 09:25:43 INFO - GECKO(1225) | [Parent 1225, Main Thread] WARNING: EditAggregationTransaction::GetName() failed: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/editor/libeditor/PlaceholderTransaction.cpp, line 217
[task 2020-04-15T09:25:43.465Z] 09:25:43 INFO - GECKO(1225) | [Parent 1225, Main Thread] WARNING: nsIAbsorbingTransaction::GetTxnName() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /builds/worker/checkouts/gecko/editor/libeditor/PlaceholderTransaction.cpp, line 188
[task 2020-04-15T09:25:43.513Z] 09:25:43 INFO - GECKO(1225) | [Child 1727: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7fa510765c80) [pid = 1727] [serial = 1] [outer = (nil)] [url = http://example.net/document-builder.sjs?html=%3Chtml%3E%0A++++++++++%3Chead%3E%0A++++++++++++%3Cmeta+charset%3D%22utf-8%22%2F%3E%0A++++++++++++%3Ctitle%3EAccessibility+Fission+Test%3C%2Ftitle%3E%0A++++++++++%3C%2Fhead%3E%0A++++++++++%3Cbody+id%3D%22default-iframe-body-id%22%3E%3Cp+id%3D%22p1%22%3Epara+1%3C%2Fp%3E%3Cp+id%3D%22p2%22%3Epara+2%3C%2Fp%3E%3C%2Fbody%3E%0A++++++++%3C%2Fhtml%3E]
[task 2020-04-15T09:25:43.513Z] 09:25:43 INFO - GECKO(1225) | [Child 1727: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7fa4f542c000) [pid = 1727] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-04-15T09:25:43.514Z] 09:25:43 INFO - GECKO(1225) | [Child 1727: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7fa4f5435000) [pid = 1727] [serial = 3] [outer = (nil)] [url = http://example.net/document-builder.sjs?html=%3Chtml%3E%0A++++++++++%3Chead%3E%0A++++++++++++%3Cmeta+charset%3D%22utf-8%22%2F%3E%0A++++++++++++%3Ctitle%3EAccessibility+Fission+Test%3C%2Ftitle%3E%0A++++++++++%3C%2Fhead%3E%0A++++++++++%3Cbody+id%3D%22default-iframe-body-id%22%3E%3Cp+id%3D%22p1%22%3Epara+1%3C%2Fp%3E%3Cp+id%3D%22p2%22%3Epara+2%3C%2Fp%3E%3C%2Fbody%3E%0A++++++++%3C%2Fhtml%3E]
[task 2020-04-15T09:25:43.514Z] 09:25:43 INFO - GECKO(1225) | [Child 1727, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/netwerk/base/nsNetUtil.cpp, line 2307
[task 2020-04-15T09:25:43.514Z] 09:25:43 INFO - GECKO(1225) | [Child 1727, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 398
[task 2020-04-15T09:25:43.514Z] 09:25:43 INFO - GECKO(1225) | [Child 1727, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/caps/ContentPrincipal.cpp, line 423
[task 2020-04-15T09:25:43.531Z] 09:25:43 INFO - GECKO(1225) | [Child 1727, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3352
[task 2020-04-15T09:25:43.676Z] 09:25:43 INFO - GECKO(1225) | [Child 1313: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 13 (0x7f9128772800) [pid = 1313] [serial = 23] [outer = 0x7f912f7a33c0

[task 2020-04-15T09:25:59.293Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.293Z] 09:25:59 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1516
[task 2020-04-15T09:25:59.294Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.294Z] 09:25:59 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-04-15T09:25:59.294Z] 09:25:59 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-04-15T09:25:59.295Z] 09:25:59 INFO - 0 |TOTAL | 40 0| 32083 0|
[task 2020-04-15T09:25:59.297Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.297Z] 09:25:59 INFO - nsTraceRefcnt::DumpStatistics: 805 entries
[task 2020-04-15T09:25:59.298Z] 09:25:59 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-04-15T09:25:59.298Z] 09:25:59 INFO - leakcheck | Processing leak log file /tmp/tmpwr6hPD.mozrunner/runtests_leaks.log
[task 2020-04-15T09:25:59.298Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.299Z] 09:25:59 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 1225
[task 2020-04-15T09:25:59.299Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.299Z] 09:25:59 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-04-15T09:25:59.300Z] 09:25:59 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-04-15T09:25:59.300Z] 09:25:59 INFO - 0 |TOTAL | 35 296| 9912318 3|
[task 2020-04-15T09:25:59.308Z] 09:25:59 INFO - 2057 |xpcAccessibleDocument | 144 144| 60 1|
[task 2020-04-15T09:25:59.309Z] 09:25:59 INFO - 2058 |xpcAccessibleGeneric | 64 64| 422 1|
[task 2020-04-15T09:25:59.311Z] 09:25:59 INFO - 2059 |xpcAccessibleHyperText | 88 88| 161 1|
[task 2020-04-15T09:25:59.311Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.312Z] 09:25:59 INFO - nsTraceRefcnt::DumpStatistics: 2061 entries
[task 2020-04-15T09:25:59.312Z] 09:25:59 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleDocument
[task 2020-04-15T09:25:59.313Z] 09:25:59 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleGeneric
[task 2020-04-15T09:25:59.313Z] 09:25:59 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleHyperText
[task 2020-04-15T09:25:59.314Z] 09:25:59 INFO - TEST-UNEXPECTED-FAIL | leakcheck | default 296 bytes leaked (xpcAccessibleDocument, xpcAccessibleGeneric, xpcAccessibleHyperText)
[task 2020-04-15T09:25:59.314Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.315Z] 09:25:59 INFO - leakcheck | Processing leak log file /tmp/tmpwr6hPD.mozrunner/runtests_leaks_tab_pid1489.log
[task 2020-04-15T09:25:59.315Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.316Z] 09:25:59 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1489
[task 2020-04-15T09:25:59.316Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.317Z] 09:25:59 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-04-15T09:25:59.317Z] 09:25:59 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-04-15T09:25:59.318Z] 09:25:59 INFO - 0 |TOTAL | 38 0| 46882 0|
[task 2020-04-15T09:25:59.318Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.319Z] 09:25:59 INFO - nsTraceRefcnt::DumpStatistics: 884 entries
[task 2020-04-15T09:25:59.319Z] 09:25:59 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-04-15T09:25:59.320Z] 09:25:59 INFO - leakcheck | Processing leak log file /tmp/tmpwr6hPD.mozrunner/runtests_leaks_tab_pid1600.log
[task 2020-04-15T09:25:59.320Z] 09:25:59 INFO -
[task 2020-04-15T09:25:59.321Z] 09:25:59 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1600

Has Regression Range: --- → yes
Keywords: regression

ill try to resolve it next week.

Assignee: nobody → yzenevich
Status: NEW → ASSIGNED
Flags: needinfo?(yzenevich)

It might take me a little longer. this is only happening on linux. Is this an intermittent or a permafail?

Flags: needinfo?(ccoroiu)

Hi Yura,

This is still intermittent, affecting linux1804-64 platform, debug build type. Already has 57 failures since 14th of April.

Flags: needinfo?(ccoroiu)

The three classes being leaked are all related by inheritance, so I think this is really the leak of a single xpcAccessibleDocument.

Whiteboard: [retriggered] → [retriggered][stockwell needswork:owner]

It is very peculiar to leak a single refcounted object and nothing else. It looks like we don't have leakchecking for hashtables, so it is possible that sRemoteXPCDocumentCache is also leaking, like maybe something gets put in that hashtable but never removed for some reason.

Yura, Andrew, any updates here? This is now on disable recommended bug list with 157 total failures since it was filed on 15th Apr: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-04-04&endday=2020-05-04&tree=trunk&bug=1630208
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=300599619&repo=autoland&lineNumber=2278
It only fails on linux1804-64 debug with fission. Could the bump of leak threshold on fission be a temporary "fix" until an actual fix is in place?

Flags: needinfo?(yura.zenevich)
Flags: needinfo?(continuation)
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell needswork:owner]

I guess we can disable this for now, I just don't have the time to look at it this/next week.

Flags: needinfo?(yura.zenevich)

I don't understand how this code works so I'm not sure how to fix this.

Leak thresholds apply to an entire test suite, and I really don't want to increase it just for one leak in one test directory.

Flags: needinfo?(continuation)

When does the leak check actually happen? Is it immediately after the test file runs?

I'm wondering whether the PDocAccessible IPC actor is still alive for a short while even after the "tab" has closed. In that case, we won't have received the IPC message to shut down the DocAccessibleParent (and thus remove the xpcAccessibleDocument). Do we necessarily wait for an OOP iframe document to be fully destroyed before we consider the tab closed? But if this were the problem, I'd expect a bunch of other stuff to be considered "leaked".

Blocks: a11y-fission

(In reply to James Teh [:Jamie] from comment #17)

When does the leak check actually happen? Is it immediately after the test file runs?

This check happens extremely late in XPCOM shutdown. IPDL is gone, threads are gone, the JS engine is gone, etc.

This is still in the [stockwell disable-recommended] list for more than 10 days.
I have checked the logs for the recent 20 failures, and it is still failing for accessible/tests/browser/hittest/browser_test_zoom_text.js test.
I'll create a disable patch for linux1804-64.

Keywords: leave-open
Whiteboard: [retriggered][stockwell disable-recommended] → [retriggered][stockwell disabled]
Pushed by ccoroiu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d69e32a6f3b0 disable browser_test_zoom_text.js on linux 64 fission for frequent failures r=jmaher

Yura, can you look into this? It has had 100 failures last week.

Flags: needinfo?(yzenevich)

There are 42 failures in the last 7 days on linux1804-64 debug.

Log link: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305277036&repo=autoland&lineNumber=2376

TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1937.log
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1937
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - 0 |TOTAL | 35 0| 16352 0|
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 397 entries
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1533.log
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1533
[task 2020-06-05T22:58:58.594Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.596Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.596Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.597Z] 22:58:58 INFO - 0 |TOTAL | 36 0| 156160 0|
[task 2020-06-05T22:58:58.601Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.602Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 1019 entries
[task 2020-06-05T22:58:58.602Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.603Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1909.log
[task 2020-06-05T22:58:58.603Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1909
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - 0 |TOTAL | 35 0| 16432 0|
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 399 entries
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1653.log
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.605Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1653
[task 2020-06-05T22:58:58.606Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.606Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.607Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.607Z] 22:58:58 INFO - 0 |TOTAL | 36 0| 34435 0|
[task 2020-06-05T22:58:58.609Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.610Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 802 entries
[task 2020-06-05T22:58:58.610Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.611Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1422.log
[task 2020-06-05T22:58:58.611Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.612Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1422
[task 2020-06-05T22:58:58.612Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.613Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.613Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.614Z] 22:58:58 INFO - 0 |TOTAL | 37 0| 129829 0|
[task 2020-06-05T22:58:58.616Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.616Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 936 entries
[task 2020-06-05T22:58:58.617Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.617Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks_tab_pid1539.log
[task 2020-06-05T22:58:58.618Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.618Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 1539
[task 2020-06-05T22:58:58.619Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.619Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.620Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.620Z] 22:58:58 INFO - 0 |TOTAL | 38 0| 159392 0|
[task 2020-06-05T22:58:58.623Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.623Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 1018 entries
[task 2020-06-05T22:58:58.624Z] 22:58:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-06-05T22:58:58.624Z] 22:58:58 INFO - leakcheck | Processing leak log file /tmp/tmpQGZNez.mozrunner/runtests_leaks.log
[task 2020-06-05T22:58:58.625Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.625Z] 22:58:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 1241
[task 2020-06-05T22:58:58.626Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.626Z] 22:58:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-06-05T22:58:58.627Z] 22:58:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-06-05T22:58:58.627Z] 22:58:58 INFO - 0 |TOTAL | 36 296| 5719477 3|
[task 2020-06-05T22:58:58.631Z] 22:58:58 INFO - 2047 |xpcAccessibleDocument | 144 144| 51 1|
[task 2020-06-05T22:58:58.632Z] 22:58:58 INFO - 2048 |xpcAccessibleGeneric | 64 64| 391 1|
[task 2020-06-05T22:58:58.632Z] 22:58:58 INFO - 2049 |xpcAccessibleHyperText | 88 88| 155 1|
[task 2020-06-05T22:58:58.634Z] 22:58:58 INFO -
[task 2020-06-05T22:58:58.634Z] 22:58:58 INFO - nsTraceRefcnt::DumpStatistics: 2051 entries
[task 2020-06-05T22:58:58.635Z] 22:58:58 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleDocument
[task 2020-06-05T22:58:58.635Z] 22:58:58 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleGeneric
[task 2020-06-05T22:58:58.635Z] 22:58:58 INFO - TEST-INFO | leakcheck | default leaked 1 xpcAccessibleHyperText

Flags: needinfo?(yzenevich)
Flags: needinfo?(yzenevich)
Whiteboard: [retriggered][stockwell disabled] → [retriggered][stockwell disabled][stockwell needswork:owner]

If I understand correctly, this got disabled in the commit in comment 24. So why are we still seeing failures here?

One test got disabled but one or more others are leaking - leaks are detected on shutdown after the folder with tests got executed.

(In reply to James Teh [:Jamie] from comment #33)

If I understand correctly, this got disabled in the commit in comment 24. So why are we still seeing failures here?

What often happens is that the leaks are reported at the end of the run, and the sheriffs look at the logs and disable the last test, but the leak is actually in another test. Maybe running --verify on each individual test could help figure out which test is leaking. There's exactly one object being leaked, so it does feel like there must be just one test that is leaking.

Attached file allocation stack of leaking object (deleted) —

I don't know how useful this is, but I've attached a file containing the allocation stack of the instance of xpcAccessibleDocument that leaked in a try run.

I got this by adding the option "--setenv=XPCOM_MEM_LOG_CLASSES=xpcAccessibleDocument" to the mochitest options in testing/mozharness/configs/unittests/linux_unittest.py and pushing to try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b437e6afa3ec7211cce9b3e5b6699a384091e2b8

A second failure is also inside mozilla::a11y::DocAccessibleParent::RecvScrollingEvent().

Two more failures with the same stack in a separate try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=87ac315497484da5beeb5b7d6fe036548b3287b2

In that try run, I added some asserts around the tables being recreated after they were shut down, but those did not hit.

I looked at the code that runs in RecvScrollingEvent, and I couldn't find anything wrong. xpcAccessibleDocument::Release is a little concerning. It treats one strong reference like a weak reference, and one weak reference like a strong reference. Also, as far as I can tell, we just always leak sRemoteXPCDocumentCache.

Aha! Finally worked out what's going on here.
(Try run: https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=ZGjE9oWKShG8Wd5b5FaPaA.0&revision=654685996f7c4c63a843f592288ff063a3caf026 )

A scrolling event is received after the DocAccessibleParent is shut down, which can happen if the BrowserParent is in the process of being destroyed (probably the tab closed) but there are still events in the IPC queue. Most Recv*Event methods in BrowserParent check mShutdown, but a few don't, including RecvScrollingEvent. This event is for the document, so we successfully get and cache an xpcAccessibleDocument for it. However, that xpcAccessibleDocument will never be removed from the cache because it's already shut down, so NotifyOfRemoteDocShutdown (which would normally remove it from the XPC cache) won't get called.

Assignee: yzenevich → jteh

We really want to know about this because the document will never be removed from the cache, since NotifyOfRemoteDocShutdown (which would normally remove it from the XPC cache) won't get called.

We can receive IPC events after a DocAccessibleParent is shut down if the BrowserParent is in the process of being destroyed (probably the tab closed) but there are still events in the IPC queue.
Most RecvEvent methods in BrowserParent check mShutdown, but a few don't.
For the events that don't, if the event is for a document, we'll successfully fire the platform event, and then successfully get and cache an xpcAccessibleDocument.
However, that xpcAccessibleDocument will never be removed from the cache because it's already shut down, so NotifyOfRemoteDocShutdown (which would normally remove it from the XPC cache) won't get called.
This results in a leaked object.
Thus, it's important that all RecvEvent methods drop the event if mShutdown is true.
This patch adds that check to the methods which didn't have it already.

The cache should already be empty by this point unless there's a bug, but we should still clean up regardless.
Also, the hashtable itself was previously never cleaned up even if it was empty.

The intermittent leak has been fixed, so we can now re-enable this.

Pushed by jteh@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/085812b8255e part 1: Assert that we don't add a shut down DocAccessibleParent to the remote XPC cache in DocManager::GetXPCDocument. r=yzen https://hg.mozilla.org/integration/autoland/rev/ff44409be764 part 2: Drop events for DocAccessibleParents which are already shut down. r=yzen https://hg.mozilla.org/integration/autoland/rev/11f1206f7506 part 3: Clean up the remote XPC document accessible cache on shutdown. r=yzen https://hg.mozilla.org/integration/autoland/rev/7ba87dd39ebb part 4: Re-enable accessible/tests/browser/hittest/browser_test_zoom_text.js. r=yzen
Blocks: 1646437
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
status-firefox79: --- → fixed
Target Milestone: --- → mozilla79
Flags: needinfo?(yzenevich)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: