Closed Bug 1503887 Opened 7 years ago Closed 7 years ago

Intermittent toolkit/components/printing/tests/<random_test> | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/simplifyArticleSample.html]

Categories

(Toolkit :: Printing, defect, P1)

Product:
Toolkit
Component:
Printing
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla65
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox64 --- unaffected
firefox65 --- fixed

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, memory-leak, Whiteboard: [stockwell disable-recommended])

Attachments

(1 file)

Bug 1503887 - clear focused window when Blur() is called and there's no docshell, presshell, or the focused element is no longer in the composed document
47 bytes, text/x-phabricator-request
Details | Review
Filed by: rgurzau [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=209158080&repo=mozilla-inbound https://queue.taskcluster.net/v1/task/JOe_LGSHR4OhcauRnUZZaw/runs/0/artifacts/public/logs/live_backing.log [task 2018-11-01T13:47:46.434Z] 13:47:46 INFO - TEST-INFO | Main app process: exit 0 [task 2018-11-01T13:47:46.436Z] 13:47:46 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/simplifyArticleSample.html] [task 2018-11-01T13:47:46.438Z] 13:47:46 INFO - TEST-INFO | toolkit/components/printing/tests/browser_preview_switch_print_selected.js | windows(s) leaked: [pid = 5654] [serial = 4] [task 2018-11-01T13:47:46.439Z] 13:47:46 INFO - runtests.py | Application ran for: 0:00:46.736943 [task 2018-11-01T13:47:46.440Z] 13:47:46 INFO - zombiecheck | Reading PID log: /tmp/tmpcHY_zspidlog
I suspect this is fall-out from bug 1362774 - but I'm not sure why/how, or how I'd go about debugging it. Mike, you recently did some work on leaks, do you have tips, like how I'd get a CC/GC log out of try?
Flags: needinfo?(mconley)
Flags: needinfo?(gijskruitbosch+bugs)
Assignee: nobody → gijskruitbosch+bugs
Blocks: 1362774
Status: NEW → ASSIGNED
Priority: P5 → P1
Flags: needinfo?(gijskruitbosch+bugs)
memory-leak key word?
Summary: Intermittent toolkit/components/printing/tests/browser_preview_switch_print_selected.js | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/simplifyArticleSample.html] → Intermittent toolkit/components/printing/tests/<random_test> | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/simplifyArticleSample.html]
I gave Gijs a link to the IRC conversation[1] I had with mccr8 and kmag for bug 1501789. Gijs, let me know if there's anything else here I can do to help you hunt this down. [1]: https://www.evernote.com/l/AbJndhpKUgZEkp1SCINwhttYdzRFx6fML1I
Flags: needinfo?(mconley)
I spent most of yesterday trying to get local CC/GC logs, but this reproduces only very rarely on my local machine without CC logging enabled, and I haven't yet managed to get it to reproduce at all *with* logging, even with chaos mode turned on. Given that it's random across the tests, I've been running the entire dir at a time, but maybe that's a mistake... I pushed to try, to see if I can get GC/CC logs out of there... https://treeherder.mozilla.org/#/jobs?repo=try&revision=d1e6db3486e48c2a2f60c6b1a2a83d4463b92d64
This bug failed 56 times in the last 7 days. It occurs on linux platforms on debug build types. Log: https://treeherder.mozilla.org/logviewer.html#?job_id=210385353&repo=autoland&lineNumber=19294 INFO - TEST-INFO | Main app process: exit 0 [task 2018-11-07T19:42:24.163Z] 19:42:24 ERROR - TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_page_change_print_original.js | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/file_page_change_print_original_1.html] [task 2018-11-07T19:42:24.164Z] 19:42:24 INFO - TEST-INFO | toolkit/components/printing/tests/browser_page_change_print_original.js | windows(s) leaked: [pid = 7473] [serial = 4] [task 2018-11-07T19:42:24.165Z] 19:42:24 INFO - runtests.py | Application ran for: 0:00:29.523190 [task 2018-11-07T19:42:24.166Z] 19:42:24 INFO - zombiecheck | Reading PID log: /tmp/tmpnPWoxmpidlog [task 2018-11-07T19:42:24.167Z] 19:42:24 INFO - ==> process 7304 launched child process 7324 [task 2018-11-07T19:42:24.168Z] 19:42:24 INFO - ==> process 7304 launched child process 7369 [task 2018-11-07T19:42:24.169Z] 19:42:24 INFO - ==> process 7304 launched child process 7389 [task 2018-11-07T19:42:24.170Z] 19:42:24 INFO - ==> process 7304 launched child process 7435 [task 2018-11-07T19:42:24.171Z] 19:42:24 INFO - ==> process 7304 launched child process 7463 [task 2018-11-07T19:42:24.172Z] 19:42:24 INFO - ==> process 7304 launched child process 7473 [task 2018-11-07T19:42:24.173Z] 19:42:24 INFO - ==> process 7304 launched child process 7520 [task 2018-11-07T19:42:24.174Z] 19:42:24 INFO - ==> process 7304 launched child process 7538 [task 2018-11-07T19:42:24.174Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7520 [task 2018-11-07T19:42:24.175Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7463 [task 2018-11-07T19:42:24.176Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7369 [task 2018-11-07T19:42:24.177Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7435 [task 2018-11-07T19:42:24.177Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7473 [task 2018-11-07T19:42:24.178Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7538 [task 2018-11-07T19:42:24.179Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7324 [task 2018-11-07T19:42:24.179Z] 19:42:24 INFO - zombiecheck | Checking for orphan process with PID: 7389 [task 2018-11-07T19:42:24.180Z] 19:42:24 INFO - Stopping web server [task 2018-11-07T19:42:24.203Z] 19:42:24 INFO - Stopping web socket server [task 2018-11-07T19:42:24.223Z] 19:42:24 INFO - Stopping ssltunnel [task 2018-11-07T19:42:24.244Z] 19:42:24 INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes [task 2018-11-07T19:42:24.246Z] 19:42:24 INFO - TEST-INFO | leakcheck | plugin process: leak threshold set at 0 bytes [task 2018-11-07T19:42:24.247Z] 19:42:24 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 0 bytes [task 2018-11-07T19:42:24.248Z] 19:42:24 INFO - TEST-INFO | leakcheck | geckomediaplugin process: leak threshold set at 20000 bytes [task 2018-11-07T19:42:24.250Z] 19:42:24 INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes [task 2018-11-07T19:42:24.251Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.251Z] 19:42:24 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 7389 [task 2018-11-07T19:42:24.253Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.254Z] 19:42:24 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| [task 2018-11-07T19:42:24.256Z] 19:42:24 INFO - | | Per-Inst Leaked| Total Rem| [task 2018-11-07T19:42:24.257Z] 19:42:24 INFO - 0 |TOTAL | 41 0| 51768 0| [task 2018-11-07T19:42:24.261Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.263Z] 19:42:24 INFO - nsTraceRefcnt::DumpStatistics: 791 entries [task 2018-11-07T19:42:24.264Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.266Z] 19:42:24 INFO - TEST-PASS | leakcheck | tab process: no leaks detected! [task 2018-11-07T19:42:24.267Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.269Z] 19:42:24 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 7435 [task 2018-11-07T19:42:24.272Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.273Z] 19:42:24 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| [task 2018-11-07T19:42:24.275Z] 19:42:24 INFO - | | Per-Inst Leaked| Total Rem| [task 2018-11-07T19:42:24.276Z] 19:42:24 INFO - 0 |TOTAL | 43 0| 32542 0| [task 2018-11-07T19:42:24.277Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.279Z] 19:42:24 INFO - nsTraceRefcnt::DumpStatistics: 698 entries [task 2018-11-07T19:42:24.280Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.282Z] 19:42:24 INFO - TEST-PASS | leakcheck | tab process: no leaks detected! [task 2018-11-07T19:42:24.284Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.285Z] 19:42:24 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 7304 [task 2018-11-07T19:42:24.286Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.287Z] 19:42:24 INFO - |<----------------Class--------------->|<-----Bytes------>|<----Objects---->| [task 2018-11-07T19:42:24.288Z] 19:42:24 INFO - | | Per-Inst Leaked| Total Rem| [task 2018-11-07T19:42:24.288Z] 19:42:24 INFO - 0 |TOTAL | 42 0| 3948280 0| [task 2018-11-07T19:42:24.296Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.297Z] 19:42:24 INFO - nsTraceRefcnt::DumpStatistics: 1949 entries [task 2018-11-07T19:42:24.299Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.300Z] 19:42:24 INFO - TEST-PASS | leakcheck | default process: no leaks detected! [task 2018-11-07T19:42:24.301Z] 19:42:24 INFO - [task 2018-11-07T19:42:24.302Z] 19:42:24 INFO - == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, tab process 7463
Yeah, I know there haven't been comments here, but I've been trying to debug this the past 2 weeks. THe problem is it's not clear what's causing the leak. I've been using GC/CC logging but I've so far been unsuccessful in tracking down the issue.
We can stem some bleeding here by disabling the last remaining enabled test on linux debug as well, I guess... I was hoping to figure this out this week, but I don't want to be causing the sheriffs headaches.
(In reply to Worcester12345 from comment #3) > memory-leak key word? ?
(In reply to Worcester12345 from comment #14) > (In reply to Worcester12345 from comment #3) > > memory-leak key word? > > ? I'm not aware of anyone actually using that keyword for anything, and there's no evidence in the bug today that suggests this is something other than a problem with the test(s) so it's not clear that, even in the presence of some kind of effort to audit memory leak bugs, this would be a useful thing to radar to them. Anyway, I can add it if it makes you happy, I just don't think it'll make any difference.
Keywords: memory-leak
Neil, it seems this leaks due to a remaining reference in the child process's focus manager's mFocusedWindow . For some debugging logging of a failing test run, see: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e2600e47e73d082bcdc0cafe4eb38b213961ea95&selectedJob=212893015 and a successful one: https://treeherder.mozilla.org/#/jobs?repo=try&revision=e2600e47e73d082bcdc0cafe4eb38b213961ea95&selectedJob=212905737 From that, it *seems* to me (but I could be missing something) like we fail to deactivate the child window, and then destroy the tabparent, at which point it never gets deactivated anymore, and stays the mFocusedWindow forever (or until/unless another tab opens in that process that becomes the mFocusedWindow). What would be the 'right' way of fixing this? I'm tempted to "just" make mFocusedWindow a weak reference, but I'm not sure if that'll have more serious consequences. We could also try to do better about making the destruction of the tabparent enforce nulling out the focused window ref in that process if the focused window was (a descendant of) the window in that tabchild, which (naively, from my perspective) would be more complex to implement, but perhaps "better" if we want to keep the ref in the focus manager strong. What do you think?
Flags: needinfo?(enndeakin)
I think we should find out why the focused window is not being cleared. Is WindowHidden not being called? Is this a document in print preview mode. If so, I could imagine some special case needs to be handled for that.
Flags: needinfo?(enndeakin)
(In reply to Neil Deakin (away until Nov 23) from comment #18) > I think we should find out why the focused window is not being cleared. Is > WindowHidden not being called? I've done another trypush, but AFAICT any changes to mFocusedWindow happen in SetFocusedWindowInternal, and all of those calls are being logged and are in the logs I already linked in comment #17. Can you elaborate on why WindowHidden is important here, rather than WindowLowered, which seems to normally be what calls SetFocusedWindowInternal ? > Is this a document in print preview mode. If > so, I could imagine some special case needs to be handled for that. Can you elaborate?
Flags: needinfo?(enndeakin)
(In reply to :Gijs (he/him) from comment #19) > (In reply to Neil Deakin (away until Nov 23) from comment #18) > > I think we should find out why the focused window is not being cleared. Is > > WindowHidden not being called? > > I've done another trypush, but AFAICT any changes to mFocusedWindow happen > in SetFocusedWindowInternal, and all of those calls are being logged and are > in the logs I already linked in comment #17. Can you elaborate on why > WindowHidden is important here, rather than WindowLowered, which seems to > normally be what calls SetFocusedWindowInternal ? > > > Is this a document in print preview mode. If > > so, I could imagine some special case needs to be handled for that. > > Can you elaborate? So I did some more logging ( https://treeherder.mozilla.org/#/jobs?repo=try&revision=94af446ee56d88542f3f95f57a7f2ab161403ebb&selectedJob=214620905 ). Here's what I found, debugging for the leak of: TEST-UNEXPECTED-FAIL | toolkit/components/printing/tests/browser_page_change_print_original.js | leaked 1 window(s) until shutdown [url = http://example.com/browser/toolkit/components/printing/tests/file_page_change_print_original_1.html] 1) in both the leaky and non-leaky case, we call WindowHidden. 2) in the non-leaky case, the window that would otherwise leak is not focused when WindowHidden is called, and we bail out at https://searchfox.org/mozilla-central/rev/e22c0d152060f4f8d4ca8904094f15f65a1b6f93/dom/base/nsFocusManager.cpp#979-980 3) in the leaky case, we focus the window shortly beforehand, and so we enter this branch instead: https://searchfox.org/mozilla-central/source/dom/base/nsFocusManager.cpp#1024-1035 nsCOMPtr<nsIDocShell> docShellBeingHidden = window->GetDocShell(); bool beingDestroyed = !docShellBeingHidden; if (docShellBeingHidden) { docShellBeingHidden->IsBeingDestroyed(&beingDestroyed); } if (beingDestroyed) { // There is usually no need to do anything if a toplevel window is going // away, as we assume that WindowLowered will be called. However, this may // not happen if nsIAppStartup::eForceQuit is used to quit, and can cause // a leak. So if the active window is being destroyed, call WindowLowered // directly. if (mActiveWindow == mFocusedWindow || mActiveWindow == window) WindowLowered(mActiveWindow); else ClearFocus(mActiveWindow); return NS_OK; } And we hit the ClearFocus() call. However, as far as I can tell, at that point mActiveWindow is null (this is assuming my logic in https://hg.mozilla.org/try/rev/94af446ee56d88542f3f95f57a7f2ab161403ebb#l1.19 is correct, and that the nsPIDOMWindowOuter::From() call only returns nullptr if its argument is a nullptr as well). Neil, does that help? I'm finding that if statement pretty weird anyway (shouldn't it be checking the full ancestor chain for mActiveWindow/mFocusedWindow? And if we're depending on this code for clearing mFocusedWindow, why are we only checking the mActiveWindow case?), though it's interesting that the comment before also talks about leaks...
We shouldn't normally be in a situation where mFocusedWindow is set but mActiveWindow is null. It looks like we rely on Blur() to clear the focused window when a window is lowered. Perhaps we need to harden Blur() a bit such that it doesn't skip over the part that clears mFocusedWindow when returning early. Is WindowLowered being called while the document is being destroyed? That might explain if Blur is returning early as no presshell or docshell might exist. Could you confirm why mFocusedWindow is set when mActiveWindow is not?
Flags: needinfo?(enndeakin)
(In reply to Neil Deakin from comment #23) > We shouldn't normally be in a situation where mFocusedWindow is set but > mActiveWindow is null. > > It looks like we rely on Blur() to clear the focused window when a window is > lowered. Perhaps we need to harden Blur() a bit such that it doesn't skip > over the part that clears mFocusedWindow when returning early. > > Is WindowLowered being called while the document is being destroyed? In the leaky case, no: [task 2018-11-30T17:34:14.550Z] 17:34:14 INFO - GECKO(1061) | gijs - Destroying a tab child (tab id 12 ) with outer window id 15032385540 [task 2018-11-30T17:34:14.552Z] 17:34:14 INFO - GECKO(1061) | gijs - Destroying window - got window? yes [task 2018-11-30T17:34:14.625Z] 17:34:14 INFO - GECKO(1061) | gijs - Starting to destroy docshell with window ID 15032385540 [task 2018-11-30T17:34:14.628Z] 17:34:14 INFO - GECKO(1061) | gijs - Actually firing pagehide [task 2018-11-30T17:34:14.631Z] 17:34:14 INFO - GECKO(1061) | gijs - (pid 1315) Hiding window 15032385540 (http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html) [task 2018-11-30T17:34:14.632Z] 17:34:14 INFO - GECKO(1061) | gijs - (pid 1315) we're being destroyed 15032385540 [task 2018-11-30T17:34:14.634Z] 17:34:14 INFO - GECKO(1061) | gijs - (pid 1315) calling ClearFocus for the active window: 0 This seems to be because this happened earlier already (ie before the destruction) because the parent requests the tab to be deactivated. But at that point (so before the snippet above): [task 2018-11-30T17:34:11.985Z] 17:34:11 INFO - GECKO(1061) | gijs - Deactivating a tabparent for pid 1315, tab 12 [task 2018-11-30T17:34:12.118Z] 17:34:12 INFO - GECKO(1061) | gijs - (pid 1315) Lowering window 15032385540 (http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html) [task 2018-11-30T17:34:12.125Z] 17:34:12 INFO - GECKO(1061) | gijs - matched active window, continuing to lower. [task 2018-11-30T17:34:12.127Z] 17:34:12 INFO - GECKO(1061) | gijs - (pid 1315) Clearing active window 15032385540 (http://example.com/browser/toolkit/components/printing/tests/simplifyNonArticleSample.html) [task 2018-11-30T17:34:12.127Z] 17:34:12 INFO - GECKO(1061) | gijs - also calling Blur() [task 2018-11-30T17:34:12.128Z] 17:34:12 INFO - GECKO(1061) | gijs - (pid 1315) Blurring! 0 [task 2018-11-30T17:34:12.129Z] 17:34:12 INFO - GECKO(1061) | gijs - (pid 1315) Blur bails, no presshell So we don't call WindowLowered when we destroy the tabparent, but we did so earlier and then bailed out because there was no presshell ( https://searchfox.org/mozilla-central/rev/8f0db72fb6e35414fb9a6fc88af19c69f332425f/dom/base/nsFocusManager.cpp#1681-1687 ) I'm guessing you're right that we should clear mFocusedWindow for all the early returns, too, not just mFocusedElement - after all, if the focused window doesn't have a docshell and/or presshell, blurring it shouldn't leave it as the focused window... Does that sound like the right fix? Or should we only do this if the window we're passed in Blur() is nullptr? Or something else?
Flags: needinfo?(enndeakin)
(Also, I wonder if this is making some sense of why there were issues with about:blank and focus - forcing about:blank creation early would maybe force creating presshells, and some of these calls would behave differently or something?)
Since this is being actively worked on, can we remove [stockwell disable-recommended] tag, or should that remain there?
Flags: needinfo?(jmaher)
I suspect this will change quickly to disable-recommended; keep in mind it is quick and easy to reenable the test- so if this falls into disable recommended again, lets disable it and Gijs can enable when the fix is landing.
Flags: needinfo?(jmaher)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Thank you Joel!
Try suggests the attached patch is sufficient, and I don't see any new/non-intermittent orange either https://treeherder.mozilla.org/#/jobs?repo=try&revision=aef0d8f861adda9b22741d9eefb635d50f3d5ecc&selectedJob=215215653 (I retriggered the x64 debug runs and the leaks are definitely gone.) Clearing ni in favour of the review request.
Flags: needinfo?(enndeakin)
As predicted above, this turned again to disable-recommended. It has 47 total failures in the last 7 days and 222 total failures in the last 30 days, on linux64, linux32 debug. Gijs, based on the results and your review+, can we add checkin-needed here and land this?
Flags: needinfo?(gijskruitbosch+bugs)
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/ce34faf0d1ef clear focused window when Blur() is called and there's no docshell, presshell, or the focused element is no longer in the composed document r=NeilDeakin
Depends on: 1512588
(In reply to Andreea Pavel [:apavel] from comment #33) > As predicted above, this turned again to disable-recommended. It has 47 > total failures in the last 7 days and 222 total failures in the last 30 > days, on linux64, linux32 debug. > > Gijs, based on the results and your review+, can we add checkin-needed here > and land this? I was waiting on a question that needed a response, but I've just moved that to bug 1512588 and landed this without changing the mFocusedElement case.
Flags: needinfo?(gijskruitbosch+bugs)
https://hg.mozilla.org/mozilla-central/rev/ce34faf0d1ef
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox65: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: