From c8b9db84979e5382893fb9ef6e26da68dcca7470 Mon Sep 17 00:00:00 2001 From: Tim Taubert Date: Fri, 1 Nov 2013 11:25:17 +0100 Subject: [PATCH] Bug 932898 - Bring back the shutdown leak detector r=ted --- build/automation.py.in | 3 +- build/automationutils.py | 120 ++++++++++++++++++++++++++++++ testing/mochitest/browser-test.js | 33 +++++++- testing/mochitest/runtests.py | 26 ++++++- 4 files changed, 176 insertions(+), 6 deletions(-) diff --git a/build/automation.py.in b/build/automation.py.in index 5898e211a8f0..e0254293c047 100644 --- a/build/automation.py.in +++ b/build/automation.py.in @@ -840,7 +840,8 @@ class Automation(object): runSSLTunnel = False, utilityPath = None, xrePath = None, certPath = None, debuggerInfo = None, symbolsPath = None, - timeout = -1, maxTime = None, onLaunch = None): + timeout = -1, maxTime = None, onLaunch = None, + webapprtChrome = False): """ Run the app, log the duration it took to execute, return the status code. Kills the app if it runs for longer than |maxTime| seconds, or outputs nothing for |timeout| seconds. diff --git a/build/automationutils.py b/build/automationutils.py index 367419a56b5c..053246683c95 100644 --- a/build/automationutils.py +++ b/build/automationutils.py @@ -8,6 +8,7 @@ import glob, logging, os, platform, shutil, subprocess, sys, tempfile, urllib2, import base64 import re from urlparse import urlparse +from operator import itemgetter try: import mozinfo @@ -46,6 +47,7 @@ __all__ = [ 'systemMemory', 'environment', 'dumpScreen', + "ShutdownLeaks" ] # Map of debugging programs to information about them, like default arguments @@ -527,3 +529,121 @@ def dumpScreen(utilityPath): uri = "data:image/png;base64,%s" % encoded log.info("SCREENSHOT: %s", uri) return uri + +class ShutdownLeaks(object): + """ + Parses the mochitest run log when running a debug build, assigns all leaked + DOM windows (that are still around after test suite shutdown, despite running + the GC) to the tests that created them and prints leak statistics. + """ + + def __init__(self, logger): + self.logger = logger + self.tests = [] + self.leakedWindows = {} + self.leakedDocShells = set() + self.currentTest = None + self.seenShutdown = False + + def log(self, line): + if line[2:11] == "DOMWINDOW": + self._logWindow(line) + elif line[2:10] == "DOCSHELL": + self._logDocShell(line) + elif line.startswith("TEST-START"): + fileName = line.split(" ")[-1].strip().replace("chrome://mochitests/content/browser/", "") + self.currentTest = {"fileName": fileName, "windows": set(), "docShells": set()} + elif line.startswith("INFO TEST-END"): + # don't track a test if no windows or docShells leaked + if self.currentTest and (self.currentTest["windows"] or self.currentTest["docShells"]): + self.tests.append(self.currentTest) + self.currentTest = None + elif line.startswith("INFO TEST-START | Shutdown"): + self.seenShutdown = True + + def process(self): + leakingTests = self._parseLeakingTests() + + if leakingTests: + totalWindows = sum(len(test["leakedWindows"]) for test in leakingTests) + totalDocShells = sum(len(test["leakedDocShells"]) for test in leakingTests) + self.logger("TEST-UNEXPECTED-FAIL | ShutdownLeaks | leaked %d DOMWindow(s) and %d DocShell(s) until shutdown", totalWindows, totalDocShells) + + for test in leakingTests: + for url, count in self._zipLeakedWindows(test["leakedWindows"]): + self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]", test["fileName"], count, url) + + if test["leakedDocShells"]: + self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until shutdown", test["fileName"], len(test["leakedDocShells"])) + + def _logWindow(self, line): + created = line[:2] == "++" + pid = self._parseValue(line, "pid") + serial = self._parseValue(line, "serial") + + # log line has invalid format + if not pid or not serial: + self.logger("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>", line) + return + + key = pid + "." + serial + + if self.currentTest: + windows = self.currentTest["windows"] + if created: + windows.add(key) + else: + windows.discard(key) + elif self.seenShutdown and not created: + self.leakedWindows[key] = self._parseValue(line, "url") + + def _logDocShell(self, line): + created = line[:2] == "++" + pid = self._parseValue(line, "pid") + id = self._parseValue(line, "id") + + # log line has invalid format + if not pid or not id: + self.logger("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>", line) + return + + key = pid + "." + id + + if self.currentTest: + docShells = self.currentTest["docShells"] + if created: + docShells.add(key) + else: + docShells.discard(key) + elif self.seenShutdown and not created: + self.leakedDocShells.add(key) + + def _parseValue(self, line, name): + match = re.search("\[%s = (.+?)\]" % name, line) + if match: + return match.group(1) + return None + + def _parseLeakingTests(self): + leakingTests = [] + + for test in self.tests: + test["leakedWindows"] = [self.leakedWindows[id] for id in test["windows"] if id in self.leakedWindows] + test["leakedDocShells"] = [id for id in test["docShells"] if id in self.leakedDocShells] + test["leakCount"] = len(test["leakedWindows"]) + len(test["leakedDocShells"]) + + if test["leakCount"]: + leakingTests.append(test) + + return sorted(leakingTests, key=itemgetter("leakCount"), reverse=True) + + def _zipLeakedWindows(self, leakedWindows): + counts = [] + counted = set() + + for url in leakedWindows: + if not url in counted: + counts.append((url, leakedWindows.count(url))) + counted.add(url) + + return sorted(counts, key=itemgetter(1), reverse=True) diff --git a/testing/mochitest/browser-test.js b/testing/mochitest/browser-test.js index 0ba9c0830f56..8f67ad114004 100644 --- a/testing/mochitest/browser-test.js +++ b/testing/mochitest/browser-test.js @@ -13,6 +13,9 @@ Cu.import("resource://gre/modules/XPCOMUtils.jsm"); XPCOMUtils.defineLazyModuleGetter(this, "Services", "resource://gre/modules/Services.jsm"); +XPCOMUtils.defineLazyModuleGetter(this, "BrowserNewTabPreloader", + "resource:///modules/BrowserNewTabPreloader.jsm", "BrowserNewTabPreloader"); + window.addEventListener("load", testOnLoad, false); function testOnLoad() { @@ -194,7 +197,7 @@ Tester.prototype = { Services.console.unregisterListener(this); Services.obs.removeObserver(this, "chrome-document-global-created"); Services.obs.removeObserver(this, "content-document-global-created"); - + this.dumper.dump("\nINFO TEST-START | Shutdown\n"); if (this.tests.length) { this.dumper.dump("Browser Chrome Test Summary\n"); @@ -380,6 +383,34 @@ Tester.prototype = { gBrowser.removeCurrentTab(); } + // Replace the document currently loaded in the browser's sidebar. + // This will prevent false positives for tests that were the last + // to touch the sidebar. They will thus not be blamed for leaking + // a document. + let sidebar = document.getElementById("sidebar"); + sidebar.setAttribute("src", "data:text/html;charset=utf-8,"); + sidebar.docShell.createAboutBlankContentViewer(null); + sidebar.setAttribute("src", "about:blank"); + + // Do the same for the social sidebar. + let socialSidebar = document.getElementById("social-sidebar-browser"); + socialSidebar.setAttribute("src", "data:text/html;charset=utf-8,"); + socialSidebar.docShell.createAboutBlankContentViewer(null); + socialSidebar.setAttribute("src", "about:blank"); + + // Destroy BackgroundPageThumbs resources. + let {BackgroundPageThumbs} = + Cu.import("resource://gre/modules/BackgroundPageThumbs.jsm", {}); + BackgroundPageThumbs._destroy(); + + // Uninitialize a few things explicitly so that they can clean up + // frames and browser intentionally kept alive until shutdown to + // eliminate false positives. + BrowserNewTabPreloader.uninit(); + SocialFlyout.unload(); + SocialShare.uninit(); + TabView.uninit(); + // Schedule GC and CC runs before finishing in order to detect // DOM windows leaked by our tests or the tested code. diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py index 2f89ab536990..2d31bd8dfd14 100644 --- a/testing/mochitest/runtests.py +++ b/testing/mochitest/runtests.py @@ -28,7 +28,7 @@ import time import traceback import urllib2 -from automationutils import environment, getDebuggerInfo, isURL, KeyValueParseError, parseKeyValue, processLeakLog, systemMemory, dumpScreen +from automationutils import environment, getDebuggerInfo, isURL, KeyValueParseError, parseKeyValue, processLeakLog, systemMemory, dumpScreen, ShutdownLeaks from datetime import datetime from manifestparser import TestManifest from mochitest_options import MochitestOptions @@ -750,7 +750,8 @@ class Mochitest(MochitestUtilsMixin): debuggerInfo=None, symbolsPath=None, timeout=-1, - onLaunch=None): + onLaunch=None, + webapprtChrome=False): """ Run the app, log the duration it took to execute, return the status code. Kills the app if it runs for longer than |maxTime| seconds, or outputs nothing for |timeout| seconds. @@ -826,11 +827,17 @@ class Mochitest(MochitestUtilsMixin): if testUrl: args.append(testUrl) + if mozinfo.info["debug"] and not webapprtChrome: + shutdownLeaks = ShutdownLeaks(log.info) + else: + shutdownLeaks = None + # create an instance to process the output outputHandler = self.OutputHandler(harness=self, utilityPath=utilityPath, symbolsPath=symbolsPath, dump_screen_on_timeout=not debuggerInfo, + shutdownLeaks=shutdownLeaks, ) def timeoutHandler(): @@ -1006,7 +1013,8 @@ class Mochitest(MochitestUtilsMixin): debuggerInfo=debuggerInfo, symbolsPath=options.symbolsPath, timeout=timeout, - onLaunch=onLaunch + onLaunch=onLaunch, + webapprtChrome=options.webapprtChrome ) except KeyboardInterrupt: log.info("runtests.py | Received keyboard interrupt.\n"); @@ -1040,7 +1048,7 @@ class Mochitest(MochitestUtilsMixin): class OutputHandler(object): """line output handler for mozrunner""" - def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True): + def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True, shutdownLeaks=None): """ harness -- harness instance dump_screen_on_timeout -- whether to dump the screen on timeout @@ -1049,6 +1057,7 @@ class Mochitest(MochitestUtilsMixin): self.utilityPath = utilityPath self.symbolsPath = symbolsPath self.dump_screen_on_timeout = dump_screen_on_timeout + self.shutdownLeaks = shutdownLeaks # perl binary to use self.perl = which('perl') @@ -1078,6 +1087,7 @@ class Mochitest(MochitestUtilsMixin): self.record_last_test, self.dumpScreenOnTimeout, self.metro_subprocess_id, + self.trackShutdownLeaks, self.log, ] @@ -1126,6 +1136,9 @@ class Mochitest(MochitestUtilsMixin): if status and not didTimeout: log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run", status) + if self.shutdownLeaks: + self.shutdownLeaks.process() + # output line handlers: # these take a line and return a line @@ -1159,6 +1172,11 @@ class Mochitest(MochitestUtilsMixin): log.info("INFO | runtests.py | metro browser sub process id detected: %s", self.browserProcessId) return line + def trackShutdownLeaks(self, line): + if self.shutdownLeaks: + self.shutdownLeaks.log(line) + return line + def log(self, line): log.info(line) return line