Bug 683953 - Part 1 - Parse log output and collect statistics about leaked DOMWindows and DocShells; r=ted

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.

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)

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: