1617709 - Intermittent leakcheck | tab 2456 bytes leaked (CondVar, Mutex, PProcessHangMonitorChild, ProcessHangMonitor, RefCountedMonitor, ...)

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-02-24T18:19:19.637Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.637Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid20065.log
[task 2020-02-24T18:19:19.637Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.638Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 20065
[task 2020-02-24T18:19:19.638Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.639Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.639Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.639Z] 18:19:19     INFO -    0 |TOTAL                                 |       37        0|  109236        0|
[task 2020-02-24T18:19:19.643Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.643Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1008 entries
[task 2020-02-24T18:19:19.644Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.644Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid17515.log
[task 2020-02-24T18:19:19.645Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.645Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 17515
[task 2020-02-24T18:19:19.645Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.646Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.646Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.647Z] 18:19:19     INFO -    0 |TOTAL                                 |       37        0|  113942        0|
[task 2020-02-24T18:19:19.653Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.654Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1011 entries
[task 2020-02-24T18:19:19.654Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.654Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid18628.log
[task 2020-02-24T18:19:19.655Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.655Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 18628
[task 2020-02-24T18:19:19.656Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.656Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.656Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.657Z] 18:19:19     INFO -    0 |TOTAL                                 |       44     2456|   14298       18|
[task 2020-02-24T18:19:19.657Z] 18:19:19     INFO -   33 |CondVar                               |       80      240|      44        3|
[task 2020-02-24T18:19:19.657Z] 18:19:19     INFO -  110 |Mutex                                 |       72      288|     294        4|
[task 2020-02-24T18:19:19.657Z] 18:19:19     INFO -  146 |PProcessHangMonitorChild              |      808      808|       1        1|
[task 2020-02-24T18:19:19.658Z] 18:19:19     INFO -  162 |ProcessHangMonitor                    |       40       40|       1        1|
[task 2020-02-24T18:19:19.658Z] 18:19:19     INFO -  169 |RefCountedMonitor                     |      160      160|       9        1|
[task 2020-02-24T18:19:19.658Z] 18:19:19     INFO -  216 |ThreadEventTarget                     |       48       48|      11        1|
[task 2020-02-24T18:19:19.659Z] 18:19:19     INFO -  219 |ThreadTargetSink                      |       16       16|      11        1|
[task 2020-02-24T18:19:19.659Z] 18:19:19     INFO -  265 |ipc::MessageChannel                   |      528      528|       9        1|
[task 2020-02-24T18:19:19.660Z] 18:19:19     INFO -  266 |ipc::MessageChannel::DispatchOnChannel|       40       40|       9        1|
[task 2020-02-24T18:19:19.660Z] 18:19:19     INFO -  356 |nsTArray_base                         |        8       24|    3868        3|
[task 2020-02-24T18:19:19.660Z] 18:19:19     INFO -  357 |nsThread                              |      264      264|      15        1|
[task 2020-02-24T18:19:19.661Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.661Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 383 entries
[task 2020-02-24T18:19:19.662Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 3 CondVar
[task 2020-02-24T18:19:19.662Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 4 Mutex
[task 2020-02-24T18:19:19.664Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 PProcessHangMonitorChild
[task 2020-02-24T18:19:19.664Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 ProcessHangMonitor
[task 2020-02-24T18:19:19.664Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 RefCountedMonitor
[task 2020-02-24T18:19:19.665Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 ThreadEventTarget
[task 2020-02-24T18:19:19.665Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 ThreadTargetSink
[task 2020-02-24T18:19:19.665Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 ipc::MessageChannel
[task 2020-02-24T18:19:19.666Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 ipc::MessageChannel::DispatchOnChannel
[task 2020-02-24T18:19:19.666Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 3 nsTArray_base
[task 2020-02-24T18:19:19.667Z] 18:19:19     INFO - TEST-INFO | leakcheck | tab leaked 1 nsThread
[task 2020-02-24T18:19:19.667Z] 18:19:19     INFO - TEST-UNEXPECTED-FAIL | leakcheck | tab 2456 bytes leaked (CondVar, Mutex, PProcessHangMonitorChild, ProcessHangMonitor, RefCountedMonitor, ...)
[task 2020-02-24T18:19:19.667Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.668Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid18538.log
[task 2020-02-24T18:19:19.668Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.668Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 18538
[task 2020-02-24T18:19:19.669Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.669Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.670Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.670Z] 18:19:19     INFO -    0 |TOTAL                                 |       36        0|  160262        0|
[task 2020-02-24T18:19:19.670Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.671Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1013 entries
[task 2020-02-24T18:19:19.671Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.672Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid18807.log
[task 2020-02-24T18:19:19.672Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.672Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 18807
[task 2020-02-24T18:19:19.673Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.673Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.673Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.674Z] 18:19:19     INFO -    0 |TOTAL                                 |       39        0|   66346        0|
[task 2020-02-24T18:19:19.676Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.677Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 922 entries
[task 2020-02-24T18:19:19.677Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.677Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid20094.log
[task 2020-02-24T18:19:19.678Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.679Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 20094
[task 2020-02-24T18:19:19.679Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.679Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.680Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.680Z] 18:19:19     INFO -    0 |TOTAL                                 |       39        0|  103172        0|
[task 2020-02-24T18:19:19.683Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.683Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1011 entries
[task 2020-02-24T18:19:19.684Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.684Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid17224.log
[task 2020-02-24T18:19:19.685Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.685Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 17224
[task 2020-02-24T18:19:19.686Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.686Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.687Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.687Z] 18:19:19     INFO -    0 |TOTAL                                 |       33        0|  283978        0|
[task 2020-02-24T18:19:19.690Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.690Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1038 entries
[task 2020-02-24T18:19:19.691Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.691Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid18102.log
[task 2020-02-24T18:19:19.692Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.692Z] 18:19:19     INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 18102
[task 2020-02-24T18:19:19.693Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.693Z] 18:19:19     INFO -      |<----------------Class--------------->|<-----Bytes------>|<----Objects---->|
[task 2020-02-24T18:19:19.694Z] 18:19:19     INFO -      |                                      | Per-Inst   Leaked|   Total      Rem|
[task 2020-02-24T18:19:19.694Z] 18:19:19     INFO -    0 |TOTAL                                 |       39        0|   68251        0|
[task 2020-02-24T18:19:19.697Z] 18:19:19     INFO - 
[task 2020-02-24T18:19:19.697Z] 18:19:19     INFO - nsTraceRefcnt::DumpStatistics: 1001 entries
[task 2020-02-24T18:19:19.698Z] 18:19:19     INFO - TEST-PASS | leakcheck | tab no leaks detected!
[task 2020-02-24T18:19:19.698Z] 18:19:19     INFO - leakcheck | Processing leak log file /tmp/tmpYgjX7e.mozrunner/runtests_leaks_tab_pid17698.log

Comment 1

[Emilio Cobos Álvarez (:emilio)]

The jobs that are failing are browser-chrome tests, what makes this a "CSS Parsing and Computation" bug?

Comment 2

[Daniel Varga [:dvarga]]

:emilio, sorry, wrong paste. Changed the component.

Comment 3

[Intermittent Failures Robot]

2 failures in 5233 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-02-24&endday=2020-03-01&tree=all

Comment 4

[Intermittent Failures Robot]

4 failures in 5483 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• autoland: 2
• mozilla-central: 1

Platform breakdown:

• linux1804-64-qr: 3
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-03-02&endday=2020-03-08&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures in 5336 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-03-09&endday=2020-03-15&tree=all

Comment 6

[Intermittent Failures Robot]

2 failures in 4955 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1

Platform breakdown:

• macosx1014-64: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-03-16&endday=2020-03-22&tree=all

Comment 7

[Intermittent Failures Robot]

3 failures in 4773 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1
• autoland: 2

Platform breakdown:

• linux1804-64: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-03-23&endday=2020-03-29&tree=all

Comment 8

[Intermittent Failures Robot]

2 failures in 5015 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• try: 1

Platform breakdown:

• linux1804-64-qr: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-03-30&endday=2020-04-05&tree=all

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 4
• try: 2

Platform breakdown:

• linux1804-64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-04-06&endday=2020-04-12&tree=all

Comment 10

[Andrew McCreight [:mccr8]]

The notable thing about this leak is that we're leaking a ProcessHangMonitor and what looks like some auxiliary data structures.

Comment 11

[Andrew McCreight [:mccr8]]

This is probably some kind of startup, shutdown race.

I took a look at a log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=296756078&repo=autoland&lineNumber=22993

The process that leaks gets shutdown almost immediately after it starts up.

[task 2020-04-08T06:21:31.981Z] 06:21:31 INFO - GECKO(7783) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpoH18IY.mozrunner/runtests_leaks_tab_pid8174.log
...
[task 2020-04-08T06:21:32.661Z] 06:21:32 INFO - GECKO(7783) | => Process ID: 8174, Thread ID: 140102611453824

That's during the test image/test/browser/browser_offscreen_image_in_out_of_process_iframe.js

Comment 12

[Andrew McCreight [:mccr8]]

mozilla::CreateHangMonitorChild() creates a hang monitor and hang monitor child (this starts listening for xpcom-shutdown), then it dispatches to the hang monitor thread to do HangMonitorChild::Bind. Bind sets sInstance to HangMonitorChild (which also seems like a race, because this is just a bare pointer being accessed from multiple threads...).

When hang monitor gets xpcom-shutdown, it checks sInstance. So I think if we have mozilla::CreateHangMonitorChild() --> xpcom-shutdown --> Bind then we'll leak the HangMonitorChild and all of the rest.

Comment 13

[Andrew McCreight [:mccr8]]

I'm also wondering if we can race between xpcom-shutdown and the creation of the ProcessHangMonitor.

Comment 14

[Andrew McCreight [:mccr8]]

Somehow I missed that sInstance is already atomic, so accessing it from multiple threads shouldn't be an issue.

Comment 15

[Andrew McCreight [:mccr8]]

Adding usleep(5000); to the start of HangMonitorChild::Bind() causes this leak on my local machine when doing ./mach test --headless --enable-fission image/test/browser/browser_offscreen_image_in_out_of_process_iframe.js.

Comment 16

[Intermittent Failures Robot]

1 failures in 4528 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1617709&startday=2020-04-13&endday=2020-04-19&tree=all

Comment 17

[Andrew McCreight [:mccr8]]

Kris said he could take a look at this.

My first approach was refcounting these protocols, which we probably want to do anyways, but without further fixes that just turns this leak into the release of a main thread object on the wrong thread, so that's probably worse. I'll file a bug and upload my patches for that.

Comment 18

[Kris Maglione [:kmag]]

Attachment: Bug 1617709: Fix hang monitor init/shutdown race in short-lived processes. r=mccr8

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/52fb91a02056
Fix hang monitor init/shutdown race in short-lived processes. r=mccr8

Comment 20

[Stefan Hindli [:stefan_hindli]]

https://hg.mozilla.org/mozilla-central/rev/52fb91a02056