Closed Bug 1617709 Opened 4 years ago Closed 4 years ago

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

Categories

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

defect

Tracking

()

RESOLVED FIXED
mozilla77
Tracking Status
firefox-esr68 --- unaffected
firefox75 --- wontfix
firefox76 --- wontfix
firefox77 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, memory-leak)

Attachments

(1 file)

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

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

Flags: needinfo?(dvarga)

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

Component: CSS Parsing and Computation → Safe Browsing
Flags: needinfo?(dvarga)
Product: Core → Toolkit

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

Component: Safe Browsing → DOM: Content Processes
Product: Toolkit → Core

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

Assignee: nobody → continuation

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.

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

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

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.

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.

Assignee: continuation → kmaglione+bmo
Pushed by maglione.k@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/52fb91a02056
Fix hang monitor init/shutdown race in short-lived processes. r=mccr8
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: