Closed Bug 1596532 Opened 6 years ago Closed 5 years ago

Intermittent leakcheck | tab 394428 bytes leaked (APZEventState, AbstractThread, ActiveElementManager, AsyncFreeSnowWhite, AtomSet, ...)

Categories

(Core :: DOM: Core & HTML, defect, P2)

defect

Tracking

()

RESOLVED FIXED
Fission Milestone M6

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Attachments

(1 file)

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


[task 2019-11-14T18:55:34.642Z] 18:55:34 INFO - TEST-START | dom/media/test/test_multiple_mediastreamtracks.html
[task 2019-11-14T18:55:34.657Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-14T18:55:34.698Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-14T18:55:34.734Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: NS_ENSURE_TRUE(aCSP) failed: file /builds/worker/workspace/build/src/dom/security/FramingChecker.cpp, line 176
[task 2019-11-14T18:55:34.754Z] 18:55:34 INFO - GECKO(5718) | ++DOMWINDOW == 18 (0x7ff36a926800) [pid = 5796] [serial = 113] [outer = 0x7ff3761d8e20]
[task 2019-11-14T18:55:34.837Z] 18:55:34 INFO - GECKO(5718) | ++DOCSHELL 0x7ff36851e800 == 8 [pid = 5796] [id = {d4a6b552-1939-4839-ae23-fc7ffd63536f}]
[task 2019-11-14T18:55:34.837Z] 18:55:34 INFO - GECKO(5718) | ++DOMWINDOW == 19 (0x7ff36a999d40) [pid = 5796] [serial = 114] [outer = (nil)]
[task 2019-11-14T18:55:34.864Z] 18:55:34 INFO - GECKO(5718) | ++DOMWINDOW == 20 (0x7ff36a92c400) [pid = 5796] [serial = 115] [outer = 0x7ff36a999d40]
[task 2019-11-14T18:55:34.928Z] 18:55:34 INFO - GECKO(5718) | ++DOCSHELL 0x7fcf6a367000 == 7 [pid = 5718] [id = {507c29df-ff21-49d8-a5e8-8a8fe5fecba5}]
[task 2019-11-14T18:55:34.929Z] 18:55:34 INFO - GECKO(5718) | ++DOMWINDOW == 17 (0x7fcf66cf62e0) [pid = 5718] [serial = 24] [outer = (nil)]
[task 2019-11-14T18:55:34.930Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-11-14T18:55:34.931Z] 18:55:34 INFO - GECKO(5718) | (firefox:5718): Gtk-CRITICAL **: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-11-14T18:55:34.932Z] 18:55:34 INFO - GECKO(5718) | ++DOMWINDOW == 18 (0x7fcf66dbcc00) [pid = 5718] [serial = 25] [outer = 0x7fcf66cf62e0]
[task 2019-11-14T18:55:34.952Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-14T18:55:34.960Z] 18:55:34 INFO - GECKO(5718) | [Parent 5718, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-11-14T18:55:34.961Z] 18:55:34 INFO - GECKO(5718) | (firefox:5718): Gtk-CRITICAL **: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed

[task 2019-11-14T18:56:01.589Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsStyleUIReset
[task 2019-11-14T18:56:01.590Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsStyleVisibility
[task 2019-11-14T18:56:01.590Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsStyleXUL
[task 2019-11-14T18:56:01.591Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 2 nsSupportsCString
[task 2019-11-14T18:56:01.591Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 692 nsTArray_base
[task 2019-11-14T18:56:01.592Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 66 nsTextFragment
[task 2019-11-14T18:56:01.592Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 65 nsTextNode
[task 2019-11-14T18:56:01.593Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 2 nsThread
[task 2019-11-14T18:56:01.593Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsThreadPool
[task 2019-11-14T18:56:01.594Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsTimer
[task 2019-11-14T18:56:01.595Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsTimerImpl
[task 2019-11-14T18:56:01.595Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 2 nsURIHashKey
[task 2019-11-14T18:56:01.596Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsUUIDGenerator
[task 2019-11-14T18:56:01.596Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 6 nsVariant
[task 2019-11-14T18:56:01.597Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 29 nsWeakReference
[task 2019-11-14T18:56:01.597Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsWebBrowser
[task 2019-11-14T18:56:01.598Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsWindowMediator
[task 2019-11-14T18:56:01.598Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsWindowWatcher
[task 2019-11-14T18:56:01.599Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponents
[task 2019-11-14T18:56:01.599Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponentsBase
[task 2019-11-14T18:56:01.600Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponents_Classes
[task 2019-11-14T18:56:01.600Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents_Constructor
[task 2019-11-14T18:56:01.601Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPCComponents_ID
[task 2019-11-14T18:56:01.601Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponents_Interfaces
[task 2019-11-14T18:56:01.602Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponents_Results
[task 2019-11-14T18:56:01.602Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 3 nsXPCComponents_Utils
[task 2019-11-14T18:56:01.602Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 7 nsXPCWrappedJS
[task 2019-11-14T18:56:01.603Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPConnect
[task 2019-11-14T18:56:01.603Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXULPopupManager
[task 2019-11-14T18:56:01.604Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXULPrototypeCache
[task 2019-11-14T18:56:01.604Z] 18:56:01 INFO - TEST-INFO | leakcheck | tab leaked 5 xpc::CompartmentPrivate
[task 2019-11-14T18:56:01.605Z] 18:56:01 INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab 394428 bytes leaked (APZEventState, AbstractThread, ActiveElementManager, AsyncFreeSnowWhite, AtomSet, ...)
[task 2019-11-14T18:56:01.605Z] 18:56:01 INFO -
[task 2019-11-14T18:56:01.606Z] 18:56:01 INFO - leakcheck | Processing leak log file /tmp/tmp09mRoG.mozrunner/runtests_leaks_gmplugin_pid6111.log
[task 2019-11-14T18:56:01.606Z] 18:56:01 INFO - TEST-INFO | leakcheck | gmplugin ignoring missing output line for total leaks
[task 2019-11-14T18:56:01.607Z] 18:56:01 INFO - leakcheck | Processing leak log file /tmp/tmp09mRoG.mozrunner/runtests_leaks_gmplugin_pid5910.log
[task 2019-11-14T18:56:01.607Z] 18:56:01 INFO - TEST-INFO | leakcheck | gmplugin ignoring missing output line for total leaks
[task 2019-11-14T18:56:01.608Z] 18:56:01 INFO - leakcheck | Processing leak log file /tmp/tmp09mRoG.mozrunner/runtests_leaks_socket_pid5740.log
[task 2019-11-14T18:56:01.608Z] 18:56:01 INFO -
[task 2019-11-14T18:56:01.609Z] 18:56:01 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, socket process 5740
[task 2019-11-14T18:56:01.609Z] 18:56:01 INFO -
[task 2019-11-14T18:56:01.609Z] 18:56:01 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2019-11-14T18:56:01.610Z] 18:56:01 INFO - | | Per-Inst Leaked| Total Rem|
[task 2019-11-14T18:56:01.610Z] 18:56:01 INFO - 0 |TOTAL | 37 0| 1731 0|

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE

There are 39 failures present on this bug over the last 7 days. These happen only on linux1804-64-qr.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=291939338&repo=autoland&lineNumber=17294

Bryce can you assign someone to take a look?

Flags: needinfo?(bvandyk)
Whiteboard: [stockwell needswork:owner]

Judging from one log, this content process is created while running tests in /webvtt/parsing/cue-text-parsing/tests/. It also looks like it is Fission-only. This is a big leak, including windows.

Alastor, given the test that's failing here, is this something you could look into?

Flags: needinfo?(bvandyk) → needinfo?(alwu)

There are 84 total failures in the last 7 days on linux1804-64-qr debug.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=292678049&repo=autoland&lineNumber=15518

[task 2020-03-11T14:41:52.016Z] 14:41:52 INFO - TEST-START | /webvtt/parsing/cue-text-parsing/tests/tree-building.html
[task 2020-03-11T14:41:52.020Z] 14:41:52 INFO - Closing window 8589934603
[task 2020-03-11T14:41:52.675Z] 14:41:52 INFO - PID 28707 | [Parent 28707, Main Thread] WARNING: '!mName', file /builds/worker/checkouts/gecko/editor/libeditor/EditAggregateTransaction.cpp, line 91
[task 2020-03-11T14:41:53.921Z] 14:41:53 INFO - .........
[task 2020-03-11T14:41:53.921Z] 14:41:53 INFO - TEST-OK | /webvtt/parsing/cue-text-parsing/tests/tree-building.html | took 1899ms
[task 2020-03-11T14:41:53.990Z] 14:41:53 INFO - PID 28707 | 1583937713980 Marionette INFO Stopped listening on port 40768
[task 2020-03-11T14:41:54.695Z] 14:41:54 INFO - PID 28707 | [GPU 28818, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp, line 428
[task 2020-03-11T14:41:54.825Z] 14:41:54 INFO - PID 28707 | [2020-03-11T14:41:54Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-03-11T14:41:54.826Z] 14:41:54 INFO - PID 28707 | [2020-03-11T14:41:54Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-03-11T14:41:55.210Z] 14:41:55 INFO - PID 28707 | [Child 28873, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3352

[task 2020-03-11T14:41:58.449Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleTableBorder
[task 2020-03-11T14:41:58.449Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleText
[task 2020-03-11T14:41:58.450Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleTextReset
[task 2020-03-11T14:41:58.450Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleUI
[task 2020-03-11T14:41:58.451Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleUIReset
[task 2020-03-11T14:41:58.451Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleVisibility
[task 2020-03-11T14:41:58.451Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsStyleXUL
[task 2020-03-11T14:41:58.452Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsSystemInfo
[task 2020-03-11T14:41:58.452Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 374 nsTArray_base
[task 2020-03-11T14:41:58.453Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 14 nsTextFragment
[task 2020-03-11T14:41:58.453Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 13 nsTextNode
[task 2020-03-11T14:41:58.454Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsThread
[task 2020-03-11T14:41:58.454Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsThreadPool
[task 2020-03-11T14:41:58.455Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 5 nsTimer
[task 2020-03-11T14:41:58.455Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 5 nsTimerImpl
[task 2020-03-11T14:41:58.456Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsUUIDGenerator
[task 2020-03-11T14:41:58.456Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 33 nsVariant
[task 2020-03-11T14:41:58.457Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 18 nsWeakReference
[task 2020-03-11T14:41:58.458Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsWebBrowser
[task 2020-03-11T14:41:58.458Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsWindowWatcher
[task 2020-03-11T14:41:58.459Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents
[task 2020-03-11T14:41:58.459Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents_Classes
[task 2020-03-11T14:41:58.459Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPCComponents_Constructor
[task 2020-03-11T14:41:58.460Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPCComponents_ID
[task 2020-03-11T14:41:58.460Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents_Interfaces
[task 2020-03-11T14:41:58.460Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents_Results
[task 2020-03-11T14:41:58.460Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 2 nsXPCComponents_Utils
[task 2020-03-11T14:41:58.462Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPCComponents_utils_Sandbox
[task 2020-03-11T14:41:58.463Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 4 nsXPCWrappedJS
[task 2020-03-11T14:41:58.465Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXPConnect
[task 2020-03-11T14:41:58.467Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXULPopupManager
[task 2020-03-11T14:41:58.468Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 1 nsXULPrototypeCache
[task 2020-03-11T14:41:58.468Z] 14:41:58 INFO - TEST-INFO | leakcheck | tab leaked 4 xpc::CompartmentPrivate
[task 2020-03-11T14:41:58.472Z] 14:41:58 INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab 211046 bytes leaked (APZEventState, AbstractThread, ActiveElementManager, AsyncFreeSnowWhite, AtomSet, ...)
[task 2020-03-11T14:41:58.473Z] 14:41:58 INFO -
[task 2020-03-11T14:41:58.474Z] 14:41:58 INFO - leakcheck | Processing leak log file /tmp/tmpRVYUvP/runtests_leaks_974_tab_pid29193.log
[task 2020-03-11T14:41:58.475Z] 14:41:58 INFO -
[task 2020-03-11T14:41:58.476Z] 14:41:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 29193
[task 2020-03-11T14:41:58.478Z] 14:41:58 INFO -
[task 2020-03-11T14:41:58.479Z] 14:41:58 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-03-11T14:41:58.480Z] 14:41:58 INFO - | | Per-Inst Leaked| Total Rem|
[task 2020-03-11T14:41:58.482Z] 14:41:58 INFO - 0 |TOTAL | 34 0| 215023 0|
[task 2020-03-11T14:41:58.482Z] 14:41:58 INFO -
[task 2020-03-11T14:41:58.483Z] 14:41:58 INFO - nsTraceRefcnt::DumpStatistics: 989 entries
[task 2020-03-11T14:41:58.488Z] 14:41:58 INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-03-11T14:41:58.489Z] 14:41:58 INFO - leakcheck | Processing leak log file /tmp/tmpRVYUvP/runtests_leaks_974_tab_pid28873.log
[task 2020-03-11T14:41:58.489Z] 14:41:58 INFO -
[task 2020-03-11T14:41:58.491Z] 14:41:58 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 28873

Alastor any updates here?

Flags: needinfo?(alwu)
Flags: needinfo?(alwu)

Sorry I was working on other high priority bugs this week, I will start to check this bug on Monday. Keep NI.

Assignee: nobody → alwu

Emilio, based on above retrigger results, last this this showed up was on Bug 1610171, can you take a look if it's from there?

Flags: needinfo?(emilio)

(So no, I don't think it's from bug 1610171)

Yes, that's correct. there was no failure when I posted this.

I'll continue retriggers. Sorry for bothering and thanks!

It looks that the DocumentFragment created from getCueAsHTML() leaked and based on comment15 it seems only happening when we enable Fission, but now I'm not sure why it would leak. We haven't changed this part of code for a very long while.

[1] https://w3c.github.io/webvtt/#dom-vttcue-getcueashtml

From the log [1], you can see tab leaked 13 FragmentOrElement after finishing running tests under the folder /webvtt/parsing/cue-text-parsing/tests/, and those tests would use getCueAsHTML() to create DocumentFragment[2]. However, for what I understand is, those fragments would be destroyed automatically when we destroy the JS contenxt in that window. So I couldn't understand why this leak would happen.

I wonder if there is any recent change in DOM which would affect the behavior of FragmentOrElement, so I'm going to move this bug to DOM compoment to see if anyone from DOM team can provide us different insight.

[1] https://firefoxci.taskcluster-artifacts.net/e0fK0kQ1QwKAeklsUUEgvw/0/public/logs/live_backing.log
[2] https://searchfox.org/mozilla-central/rev/d69ec052bed8700af7a283e37b60b4af22734930/testing/web-platform/tests/webvtt/parsing/cue-text-parsing/common.js#179

Assignee: alwu → nobody
Component: Audio/Video: Playback → DOM: Core & HTML
Flags: needinfo?(alwu)

Hsin-Yi can you assign someone to take over here?

Flags: needinfo?(htsai)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

(In reply to Andrew McCreight [:mccr8] from comment #35)

I did notice that TextTrackCue::mWatchManager isn't being traversed. Maybe that'll help.

But WatchManager didn't keep a strong reference to TextTrackCue, that shouldn't suppose to cause any leak.

(In reply to Andrew McCreight [:mccr8] from comment #40)

(In reply to Alastor Wu [:alwu] from comment #39)

But WatchManager didn't keep a strong reference to TextTrackCue, that shouldn't suppose to cause any leak.

mWatchManager is also a TextTrackCue, right? So they're both exposed to JS, and user JS could create a strong reference from one to the other via an expando.

Sorry, I don't get the point, what do you mean mWatchManager is also a TextTrackCue?

mWatchManager is a WatchManager [1] that won't be exposed to JS, so whenever the TextTrackCue destroys, the mWatchManager would also get detroied.

[1] https://searchfox.org/mozilla-central/rev/61f224ec08ddc6f9a93ac45c8c3c5f7159be7c2a/xpcom/threads/StateWatching.h#175

Oh, sorry, I wasn't looking at the code closely enough. I saw WatchManager<TextTrackCue> mWatchManager; and I somehow read the type as RefPtr<TextTrackCue>.

Fission Milestone: --- → ?
Flags: needinfo?(htsai)

(In reply to Alastor Wu [:alwu] from comment #34)

From the log [1], you can see tab leaked 13 FragmentOrElement after finishing running tests under the folder /webvtt/parsing/cue-text-parsing/tests/, and those tests would use getCueAsHTML() to create DocumentFragment[2]. However, for what I understand is, those fragments would be destroyed automatically when we destroy the JS contenxt in that window. So I couldn't understand why this leak would happen.

Nothing is destroyed automatically. If there are cycles which cycle collector doesn't know about, we leak.

I wonder if there is any recent change in DOM which would affect the behavior of FragmentOrElement, so I'm going to move this bug to DOM compoment to see if anyone from DOM team can provide us different insight.

I'm not aware of relevant changes to DOM.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Alastor are you the assignee here?

Flags: needinfo?(alwu)

I'll see if I can narrow this down a bit.

Assignee: nobody → continuation
Flags: needinfo?(alwu)

I haven't been able to reproduce this locally, so I hacked up some patches to save GC/CC logs on TreeHerder if there are any window leaks.

The leaking inner windows are being held alive via the nsNodeInfoManager like so:

0x7f960ec44760 [nsNodeInfoManager]
--[mDocument]--> 0x7f960e23d000 [Document normal (xhtml) http://web-platform.test:8000/webvtt/parsing/cue-text-parsing/tests/tags.html]
--[Preserved wrapper]--> 0x2e40cb4ef100 [JS Object (HTMLDocument)]
--[group_global]--> 0x2e40cb4df060 [JS Object (Window)]
--[UnwrapDOMObject(obj)]--> 0x7f960e24f000 [nsGlobalWindowInner # 10737418247 inner http://web-platform.test:8000/webvtt/parsing/cue-text-parsing/tests/tags.html]

I assume this means there's some kind of node floating around out there (without a preserved wrapper) that is leaking. I might be able to come up with a guess for what kind of node it is by looking at the known edges to the node info manager, and comparing it to the leaked node objects in the leak log.

Whiteboard: [stockwell disable-recommended]
Blocks: WPT-Fis
No longer blocks: fission-mochitests

These failures are in a single directory of WPT, when Fission is enabled.

Priority: -- → P2

I checked about 20 failures and the leaks occur in webvtt/parsing/cue-text-parsing/tests/tree-building.html, made a disabling patch for that.

Pushed by rmaries@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/08ae58fc28da disable tree-building.html on linux18.04 webrender fission r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]

Tracking for Fission Nightly milestone (M6)

Fission Milestone: ? → M6
Whiteboard: [stockwell disabled] → [stockwell disabled][retriggered]

I don't see how Bug 1625145 could be related to this. As far as I can tell, it's not running the same test suite, and it was a test-only change.

Flags: needinfo?(gtatum)

I see an instance of the leak failure a few pushes earlier, in f2f8ac87d5178d1703c6ac3b967e7238668528a0

This leak is happening in /webvtt/parsing/cue-text-parsing/tests/, which is the same thing I noted in comment 15, from March 8. So this is not a recent regression. I'll try taking another look at this, but disabling more tests in this directory is probably the way to go until I figure something out.

I noticed some CustomElementReactionsStack in the leak log, so I was wondering if that could be causing the leak. There is going to be a cycle of strong references that pass through the stack that is not visible to the cycle collector. However, I added some assertions to check that the stack is empty at shutdown, and they passed, even in the leaking case, so that can't be the issue.

In the leak log I captured before, things were being held alive by a nsNodeInfoManager, which almost certainly means that one kind of node isn't being visited. My guess is that it is a video element.

There is some peculiar behavior when I look at the logs for video elements in a non-leaking run. There are a bunch of orphan video elements, from a number of different tests. For two of them that I checked, in the first shutdown CC they are marked as garbage, then in the second shutdown CC they are still present, but now with an unknown edge. Then in the third shutdown CC they are no longer present, suggesting that they are actually collected. In normal circumstances, it only takes two shutdown CCs to finish collecting things.

I used refcounting to figure out what was going on with one of these video elements, in the non-leaking case. What happens is we run the first CC, which identifies the video element as garbage, and it is unlinked. This removes all of the existing references to the video element, as expected. However, while we're in the process of unlinking the video element, we call into UnbindFromTree. Part of what this does is creates a new runnable with a strong reference to the video element, so the element doesn't go away. Then we run the CC twice more, but of course this does not free the element. Then we finish nsCycleCollector::Shutdown() and return to nsCycleCollector_shutdown(), where ProcessStableStateQueue() and PerformMicroTaskCheckPoint() are called, and the runnable is finally dealt with, so the video element goes away.

If I do that task processing in after each shutdown CC in ShutdownCollect(), then the video element goes away immediately after the first CC as expected. I'm not sure how this would explain the intermittent leak, unfortunately. The only things getting stuck into the queue in this way should be unlinked things, so they shouldn't require further help from the CC to get destroyed.

I guess you could have a situation like this A <-> B -> C <-> D where A and B are in a cycle, as are C and D. Also, B has a strong reference to C that it hasn't told the CC about (but it should!). This can be broken down by two CCs, but if B is a media element then the queue has to be emptied in between the two CCs. Maybe there's some kind of race where we usually run a CC before shutdown, but occasionally it waits until shutdown, and so things aren't collected.

I can try processing the queue after every shutdown CC and see if that helps.

Since 30th of March when it starting to fail for /webvtt/parsing/cue-text-parsing/tests/timestamps.html there are 23 failures.
All the failures are on linux1804-64-qr platform, debug build type. The failure rate has decreased relative to previous test that was failing before.

Andrew, thank you for investigating, please let us know if a disable patch is needed.

Depends on: 1630254

This hasn't happened since I landed bug 1630254, but it also hadn't happened for a few days before I landed my patch. The volume this month has been low, aside from a big spike on the 9th and 10th, so we should wait a few weeks before declaring victory here. My patch might fix up some other random shutdown leaks we have.

apavel, could you please back out the patch here when you have a chance? This leak hasn't happened since bug 1630254 landed, so hopefully we can reenable that test. I reenabled the that test in my try runs for bug 1630254 and the leak didn't show up in 16 or so retriggers, so hopefully it won't come back. Thanks.

Flags: needinfo?(apavel)
Flags: needinfo?(apavel)
Whiteboard: [stockwell disabled][retriggered] → [retriggered]

I'll be optimistic and mark it fixed.

Status: REOPENED → RESOLVED
Closed: 6 years ago5 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: