From 39e83d0057f77455bbc30cd06201f97666e4309d Mon Sep 17 00:00:00 2001 From: Tim Taubert Date: Sat, 25 Feb 2012 12:48:05 +0100 Subject: [PATCH] Bug 683953 - Part 1 - Parse log output and collect statistics about leaked DOMWindows and DocShells; r=ted --- build/automation.py.in | 8 ++- build/automationutils.py | 105 ++++++++++++++++++++++++++++++++++ testing/mochitest/runtests.py | 11 ++++ 3 files changed, 121 insertions(+), 3 deletions(-) diff --git a/build/automation.py.in b/build/automation.py.in index 4b476a05ea4..ca9c8ce4c33 100644 --- a/build/automation.py.in +++ b/build/automation.py.in @@ -754,7 +754,7 @@ user_pref("camino.use_system_proxy_settings", false); // Camino-only, harmless t self.log.info("Can't trigger Breakpad, just killing process") proc.kill() - def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath): + def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, logger): """ Look for timeout or crashes and return the status after the process terminates """ stackFixerProcess = None stackFixerFunction = None @@ -788,6 +788,8 @@ user_pref("camino.use_system_proxy_settings", false); // Camino-only, harmless t (line, didTimeout) = self.readWithTimeout(logsource, timeout) while line != "" and not didTimeout: + if logger: + logger.log(line) if "TEST-START" in line and "|" in line: self.lastTestSeen = line.split("|")[1].strip() if stackFixerFunction: @@ -877,7 +879,7 @@ user_pref("camino.use_system_proxy_settings", false); // Camino-only, harmless t def runApp(self, testURL, env, app, profileDir, extraArgs, runSSLTunnel = False, utilityPath = None, - xrePath = None, certPath = None, + xrePath = None, certPath = None, logger = None, debuggerInfo = None, symbolsPath = None, timeout = -1, maxTime = None): """ @@ -936,7 +938,7 @@ user_pref("camino.use_system_proxy_settings", false); // Camino-only, harmless t stderr = subprocess.STDOUT) self.log.info("INFO | automation.py | Application pid: %d", proc.pid) - status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath) + status = self.waitForFinish(proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, logger) self.log.info("INFO | automation.py | Application ran for: %s", str(datetime.now() - startTime)) # Do a final check for zombie child processes. diff --git a/build/automationutils.py b/build/automationutils.py index d55e0f28be8..4a937960858 100644 --- a/build/automationutils.py +++ b/build/automationutils.py @@ -40,6 +40,7 @@ from __future__ import with_statement import glob, logging, os, platform, shutil, subprocess, sys, tempfile, urllib2, zipfile import re from urlparse import urlparse +from operator import itemgetter __all__ = [ "ZipFileReader", @@ -52,6 +53,7 @@ __all__ = [ "DEBUGGER_INFO", "replaceBackSlashes", "wrapCommand", + "ShutdownLeakLogger" ] # Map of debugging programs to information about them, like default arguments @@ -450,3 +452,106 @@ def wrapCommand(cmd): return ["arch", "-arch", "i386"] + cmd # otherwise just execute the command normally return cmd + +class ShutdownLeakLogger(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. + """ + MAX_LEAK_COUNT = 120 + + 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["windows"] and self.currentTest["docShells"]: + self.tests.append(self.currentTest) + self.currentTest = None + elif line.startswith("INFO TEST-START | Shutdown"): + self.seenShutdown = True + + def parse(self): + leakingTests = self._parseLeakingTests() + + if leakingTests: + totalWindows = sum(len(test["leakedWindows"]) for test in leakingTests) + totalDocShells = sum(len(test["leakedDocShells"]) for test in leakingTests) + msgType = "INFO" if totalWindows + totalDocShells < self.MAX_LEAK_COUNT else "UNEXPECTED-FAIL" + self.logger.info("TEST-%s | ShutdownLeaks | leaked %d DOMWindow(s) and %d DocShell(s) until shutdown", msgType, totalWindows, totalDocShells) + + for test in leakingTests: + self.logger.info("\n[%s]", test["fileName"]) + + for url, count in self._zipLeakedWindows(test["leakedWindows"]): + self.logger.info(" %d window(s) [url = %s]", count, url) + + if test["leakedDocShells"]: + self.logger.info(" %d docShell(s)", len(test["leakedDocShells"])) + + def _logWindow(self, line): + created = line[:2] == "++" + id = self._parseValue(line, "serial") + + if self.currentTest: + windows = self.currentTest["windows"] + if created: + windows.add(id) + else: + windows.discard(id) + elif self.seenShutdown and not created: + self.leakedWindows[id] = self._parseValue(line, "url") + + def _logDocShell(self, line): + created = line[:2] == "++" + id = self._parseValue(line, "id") + + if self.currentTest: + docShells = self.currentTest["docShells"] + if created: + docShells.add(id) + else: + docShells.discard(id) + elif self.seenShutdown and not created: + self.leakedDocShells.add(id) + + def _parseValue(self, line, name): + return re.search("\[%s = (.+?)\]" % name, line).group(1) + + 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/runtests.py b/testing/mochitest/runtests.py index 9c8930a0c05..2b324bf77f9 100644 --- a/testing/mochitest/runtests.py +++ b/testing/mochitest/runtests.py @@ -675,6 +675,12 @@ class Mochitest(object): else: timeout = 330.0 # default JS harness timeout is 300 seconds + # it's a debug build, we can parse leaked DOMWindows and docShells + if Automation.IS_DEBUG_BUILD: + logger = ShutdownLeakLogger(self.automation.log) + else: + logger = None + if options.vmwareRecording: self.startVMwareRecording(options); @@ -688,6 +694,7 @@ class Mochitest(object): certPath=options.certPath, debuggerInfo=debuggerInfo, symbolsPath=options.symbolsPath, + logger = logger, timeout = timeout) except KeyboardInterrupt: self.automation.log.info("INFO | runtests.py | Received keyboard interrupt.\n"); @@ -702,6 +709,10 @@ class Mochitest(object): self.stopWebServer(options) self.stopWebSocketServer(options) processLeakLog(self.leak_report_file, options.leakThreshold) + + if logger: + logger.parse() + self.automation.log.info("\nINFO | runtests.py | Running tests: end.") if manifest is not None: