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

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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!

Comment 1

[Andrew McCreight [:mccr8]]

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.

Comment 2

[Timothy Nikkel (:tnikkel)]

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?

Comment 3

[Andrew McCreight [:mccr8]]

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.

Comment 4

[Timothy Nikkel (:tnikkel)]

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.

Comment 5

[Timothy Nikkel (:tnikkel)]

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?

Comment 6

[Timothy Nikkel (:tnikkel)]

Attachment: Bug 1756696. Make sure image decoding has finished in netwerk/test/browser/browser_opaque_response_blocking_telemetry.js. r?aosmond

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.

Comment 7

[BugBot [:suhaib / :marco]]

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

Comment 8

[Pulsebot]

Pushed by [e-mail]:
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

Comment 9

[Marian-Vasile Laza]

https://hg.mozilla.org/mozilla-central/rev/e31aae5390ba

Comment 10

[Intermittent Failures Robot]

6 failures in 2992 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6

Platform and build breakdown:

• linux1804-64-qr: 5
  • debug: 5
• windows10-64-2004-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1756696&startday=2022-02-21&endday=2022-02-27&tree=all