Closed Bug 1756696 Opened 7 months ago Closed 7 months ago

Intermittent leakcheck | tab 2072 bytes leaked (CondVar, CopyOnWriteValue, LabellingEventTarget, Mutex, ObserverTable, ...)

Categories

(Core :: Graphics: ImageLib, defect, P5)

defect

Tracking

()

RESOLVED FIXED
99 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox97 --- unaffected
firefox98 --- unaffected
firefox99 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

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


[task 2022-02-22T19:48:01.754Z] 19:48:01     INFO - TEST-START | netwerk/test/browser/browser_test_favicon.js
<...>
[task 2022-02-22T19:48:14.300Z] 19:48:14     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 5008
[task 2022-02-22T19:48:14.300Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.301Z] 19:48:14     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2022-02-22T19:48:14.302Z] 19:48:14     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2022-02-22T19:48:14.303Z] 19:48:14     INFO -    0 |TOTAL                                 |       52     2072|   32922       19|
[task 2022-02-22T19:48:14.303Z] 19:48:14     INFO -   63 |CondVar                               |       80       80|      50        1|
[task 2022-02-22T19:48:14.304Z] 19:48:14     INFO -   70 |CopyOnWriteValue                      |       40       40|       3        1|
[task 2022-02-22T19:48:14.305Z] 19:48:14     INFO -  202 |LabellingEventTarget                  |       56       56|       2        1|
[task 2022-02-22T19:48:14.305Z] 19:48:14     INFO -  230 |Mutex                                 |       72      288|     474        4|
[task 2022-02-22T19:48:14.306Z] 19:48:14     INFO -  244 |ObserverTable                         |       56       56|       3        1|
[task 2022-02-22T19:48:14.307Z] 19:48:14     INFO -  360 |PerformanceCounter                    |       88       88|       2        1|
[task 2022-02-22T19:48:14.307Z] 19:48:14     INFO -  385 |ProgressTracker                       |      144      144|       3        1|
[task 2022-02-22T19:48:14.308Z] 19:48:14     INFO -  394 |RasterImage                           |      256      256|       3        1|
[task 2022-02-22T19:48:14.309Z] 19:48:14     INFO -  482 |ThreadEventTarget                     |       64       64|      14        1|
[task 2022-02-22T19:48:14.309Z] 19:48:14     INFO -  486 |ThreadTargetSink                      |       16       16|      14        1|
[task 2022-02-22T19:48:14.310Z] 19:48:14     INFO -  562 |image::SourceBuffer                   |      144      144|       3        1|
[task 2022-02-22T19:48:14.311Z] 19:48:14     INFO -  588 |nsAuthURLParser                       |       24       24|       2        1|
[task 2022-02-22T19:48:14.311Z] 19:48:14     INFO -  788 |nsStandardURL                         |      336      336|     519        1|
[task 2022-02-22T19:48:14.312Z] 19:48:14     INFO -  793 |nsStringBuffer                        |        8       16|    9213        2|
[task 2022-02-22T19:48:14.313Z] 19:48:14     INFO -  828 |nsThread                              |      464      464|      21        1|
[task 2022-02-22T19:48:14.313Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.314Z] 19:48:14     INFO - nsTraceRefcnt::DumpStatistics: 866 entries
[task 2022-02-22T19:48:14.315Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 CondVar
[task 2022-02-22T19:48:14.315Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 CopyOnWriteValue
[task 2022-02-22T19:48:14.316Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 LabellingEventTarget
[task 2022-02-22T19:48:14.316Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 4 Mutex
[task 2022-02-22T19:48:14.317Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 ObserverTable
[task 2022-02-22T19:48:14.318Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 PerformanceCounter
[task 2022-02-22T19:48:14.318Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 ProgressTracker
[task 2022-02-22T19:48:14.319Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 RasterImage
[task 2022-02-22T19:48:14.319Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 ThreadEventTarget
[task 2022-02-22T19:48:14.320Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 ThreadTargetSink
[task 2022-02-22T19:48:14.320Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 image::SourceBuffer
[task 2022-02-22T19:48:14.321Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 nsAuthURLParser
[task 2022-02-22T19:48:14.321Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 nsStandardURL
[task 2022-02-22T19:48:14.322Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 2 nsStringBuffer
[task 2022-02-22T19:48:14.323Z] 19:48:14     INFO - TEST-INFO | leakcheck | tab leaked 1 nsThread
[task 2022-02-22T19:48:14.323Z] 19:48:14     INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab 2072 bytes leaked (CondVar, CopyOnWriteValue, LabellingEventTarget, Mutex, ObserverTable, ...)
[task 2022-02-22T19:48:14.324Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.324Z] 19:48:14     INFO - leakcheck | Processing leak log file /tmp/tmpjfgzx6q6.mozrunner/runtests_leaks_tab_pid5218.log
[task 2022-02-22T19:48:14.325Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.326Z] 19:48:14     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 5218
[task 2022-02-22T19:48:14.326Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.327Z] 19:48:14     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2022-02-22T19:48:14.328Z] 19:48:14     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2022-02-22T19:48:14.328Z] 19:48:14     INFO -    0 |TOTAL                                 |       49        0|   11956        0|
[task 2022-02-22T19:48:14.329Z] 19:48:14     INFO - 
[task 2022-02-22T19:48:14.329Z] 19:48:14     INFO - nsTraceRefcnt::DumpStatistics: 387 entries
[task 2022-02-22T19:48:14.330Z] 19:48:14     INFO - TEST-PASS | leakcheck | tab no leaks detected!

From the RasterImage and SourceBuffer in there I'm going to guess this is image related. Maybe some image-related data structure was getting passed between threads at some point very late in shutdown so it ended up getting leaked.

Component: General → ImageLib

Probably caused by bug 1722422. We were always leaking here, but 1722422 just hid the assert. Not sure what we can do here, an image decoder thread has a refptr to an image, which we need to release on the main thread, but we xpcom threads infrastructure have shutdown so we can't dispatch anything to the main thread, so we just leak so we don't release off main thread. Can we do anything better?

Regressed by: 1722422

I don't know if there's anything too much better you can do, except maybe shut down the image decoding stuff early enough that it can dispatch stuff to the main thread. If this is only a rare failure, it probably isn't worth the effort.

The original intermittent bug had enough failures that it generated a needinfo, so this probably will too.

I'll try a patch on try that asserts if we try queuing a new task, or start running a task if shutdown has started. Those are things we can avoid. But if shutdown starts while a decode task is in the middle of decoding there is not much we can do.

Yeah, we don't appear to have started shutdown before we enter the decoder, and when we exit the decoder we are already very late in shutdown. I reproduced on try with this code

void DecodedSurfaceProvider::Run() {
<snip>
MOZ_ASSERT(!DecodePool::Singleton()->IsShuttingDown());
MOZ_ASSERT(!gXPCOMThreadsShutDown);
MOZ_ASSERT(!gXPCOMShuttingDown);

// Run the decoder.
LexerResult result = mDecoder->Decode(WrapNotNull(this));

->MOZ_ASSERT(!DecodePool::Singleton()->IsShuttingDown());
MOZ_ASSERT(!gXPCOMThreadsShutDown);
MOZ_ASSERT(!gXPCOMShuttingDown);

We hit an assert on the line with "->" inside DecodePool::Singleton()

https://searchfox.org/mozilla-central/rev/20ebe9f39e8790e2db123f89fab3293dc0a796ac/image/DecodePool.cpp#62

indicating that sSingleton has been cleared. It is cleared by ClearOnShutdown, with ShutdownPhase::XPCOMShutdownFinal, after
XPCOMWillShutdown,
XPCOMShutdown,
XPCOMShutdownThreads,
XPCOMShutdownLoaders

So not sure what we can do here. Maybe just modify the test to wait for decode to complete?

Because these images are loaded as embeds/objects we can't get a hold of them to apply most usual methods of waiting for decode (img.decode, using a special powers image notifications observer). This should hopefully be enough to avoid hitting this in automation.

Backout the patch for bug 1722422 (the one that changed it from an assert to a leak) because I think it's easier to classify/recognize the assert than the leak in the logs.

Assignee: nobody → tnikkel
Status: NEW → ASSIGNED

Set release status flags based on info from the regressing bug 1722422

Has Regression Range: --- → yes
Pushed by tnikkel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e31aae5390ba
Make sure image decoding has finished in netwerk/test/browser/browser_opaque_response_blocking_telemetry.js. r=aosmond
Status: ASSIGNED → RESOLVED
Closed: 7 months ago
Resolution: --- → FIXED
Target Milestone: --- → 99 Branch
You need to log in before you can comment on or make changes to this bug.