Bug 519570. Log leaks for child processes in separate files, and handle them in automation.py. r=bsmedberg
authorJonathan Griffin <jgriffin@mozilla.com>
Tue, 10 Nov 2009 11:16:12 -0800
changeset 36065 246ea55e42c37b95c7da0a09b24950a11987a8f5
parent 36064 8212015ff29d47dd436692a72cd9e2e29163d84d
child 36066 4157d7f9205f38fb2acb9d49e1e8cb29f9d50425
push id10694
push userbsmedberg@mozilla.com
push dateMon, 14 Dec 2009 15:23:10 +0000
treeherdermozilla-central@683dfdc4adf0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbsmedberg
bugs519570
milestone1.9.3a1pre
Bug 519570. Log leaks for child processes in separate files, and handle them in automation.py. r=bsmedberg
build/automationutils.py
toolkit/xre/nsEmbedFunctions.cpp
xpcom/base/nsTraceRefcntImpl.cpp
--- a/build/automationutils.py
+++ b/build/automationutils.py
@@ -195,87 +195,118 @@ def dumpLeakLog(leakLogFile, filter = Fa
   # Only |XPCOM_MEM_LEAK_LOG| reports can be actually filtered out.
   # Only check whether an actual leak was reported.
   if filter and not "0 TOTAL " in leakReport:
     return
 
   # Simply copy the log.
   log.info(leakReport.rstrip("\n"))
 
-def processLeakLog(leakLogFile, leakThreshold = 0):
-  """Process the leak log, parsing it.
-
-  Use this function if you want an additional PASS/FAIL summary.
-  It must be used with the |XPCOM_MEM_BLOAT_LOG| environment variable.
+def processSingleLeakFile(leakLogFileName, PID, processType, leakThreshold):
+  """Process a single leak log, corresponding to the specified
+  process PID and type.
   """
 
-  if not os.path.exists(leakLogFile):
-    log.info("WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!")
-    return
-
   #                  Per-Inst  Leaked      Total  Rem ...
   #   0 TOTAL              17     192  419115886    2 ...
   # 833 nsTimerImpl        60     120      24726    2 ...
   lineRe = re.compile(r"^\s*\d+\s+(?P<name>\S+)\s+"
                       r"(?P<size>-?\d+)\s+(?P<bytesLeaked>-?\d+)\s+"
                       r"-?\d+\s+(?P<numLeaked>-?\d+)")
 
-  leaks = open(leakLogFile, "r")
+  processString = ""
+  if PID and processType:
+    processString = "| %s process %s " % (processType, PID)
+  leaks = open(leakLogFileName, "r")
   for line in leaks:
     matches = lineRe.match(line)
     if (matches and
         int(matches.group("numLeaked")) == 0 and
         matches.group("name") != "TOTAL"):
       continue
     log.info(line.rstrip())
   leaks.close()
 
-  leaks = open(leakLogFile, "r")
+  leaks = open(leakLogFileName, "r")
   seenTotal = False
   prefix = "TEST-PASS"
   for line in leaks:
     matches = lineRe.match(line)
     if not matches:
       continue
     name = matches.group("name")
     size = int(matches.group("size"))
     bytesLeaked = int(matches.group("bytesLeaked"))
     numLeaked = int(matches.group("numLeaked"))
     if size < 0 or bytesLeaked < 0 or numLeaked < 0:
-      log.info("TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | negative leaks caught!")
+      log.info("TEST-UNEXPECTED-FAIL %s| automationutils.processLeakLog() | negative leaks caught!" %
+               processString)
       if name == "TOTAL":
         seenTotal = True
     elif name == "TOTAL":
       seenTotal = True
       # Check for leaks.
       if bytesLeaked < 0 or bytesLeaked > leakThreshold:
         prefix = "TEST-UNEXPECTED-FAIL"
-        leakLog = "TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | leaked" \
-                  " %d bytes during test execution" % bytesLeaked
+        leakLog = "TEST-UNEXPECTED-FAIL %s| automationutils.processLeakLog() | leaked" \
+                  " %d bytes during test execution" % (processString, bytesLeaked)
       elif bytesLeaked > 0:
-        leakLog = "TEST-PASS | automationutils.processLeakLog() | WARNING leaked" \
-                  " %d bytes during test execution" % bytesLeaked
+        leakLog = "TEST-PASS %s| automationutils.processLeakLog() | WARNING leaked" \
+                  " %d bytes during test execution" % (processString, bytesLeaked)
       else:
-        leakLog = "TEST-PASS | automationutils.processLeakLog() | no leaks detected!"
+        leakLog = "TEST-PASS %s| automationutils.processLeakLog() | no leaks detected!" \
+                  % processString
       # Remind the threshold if it is not 0, which is the default/goal.
       if leakThreshold != 0:
         leakLog += " (threshold set at %d bytes)" % leakThreshold
       # Log the information.
       log.info(leakLog)
     else:
       if numLeaked != 0:
         if numLeaked > 1:
           instance = "instances"
           rest = " each (%s bytes total)" % matches.group("bytesLeaked")
         else:
           instance = "instance"
           rest = ""
-        log.info("%(prefix)s | automationutils.processLeakLog() | leaked %(numLeaked)d %(instance)s of %(name)s "
+        log.info("%(prefix)s %(process)s| automationutils.processLeakLog() | leaked %(numLeaked)d %(instance)s of %(name)s "
                  "with size %(size)s bytes%(rest)s" %
                  { "prefix": prefix,
+                   "process": processString,
                    "numLeaked": numLeaked,
                    "instance": instance,
                    "name": name,
                    "size": matches.group("size"),
                    "rest": rest })
   if not seenTotal:
-    log.info("TEST-UNEXPECTED-FAIL | automationutils.processLeakLog() | missing output line for total leaks!")
+    log.info("TEST-UNEXPECTED-FAIL %s| automationutils.processLeakLog() | missing output line for total leaks!" %
+             processString)
   leaks.close()
+
+
+def processLeakLog(leakLogFile, leakThreshold = 0):
+  """Process the leak log, including separate leak logs created
+  by child processes.
+
+  Use this function if you want an additional PASS/FAIL summary.
+  It must be used with the |XPCOM_MEM_BLOAT_LOG| environment variable.
+  """
+
+  if not os.path.exists(leakLogFile):
+    log.info("WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!")
+    return
+
+  (leakLogFileDir, leakFileBase) = os.path.split(leakLogFile)
+  pidRegExp = re.compile(r".*?_([a-z]*)_pid(\d*)$")
+  if leakFileBase[-4:] == ".log":
+    leakFileBase = leakFileBase[:-4]
+    pidRegExp = re.compile(r".*?_([a-z]*)_pid(\d*).log$")
+
+  for fileName in os.listdir(leakLogFileDir):
+    if fileName.find(leakFileBase) != -1:
+      thisFile = os.path.join(leakLogFileDir, fileName)
+      processPID = 0
+      processType = None
+      m = pidRegExp.search(fileName)
+      if m:
+        processType = m.group(1)
+        processPID = m.group(2)
+      processSingleLeakFile(thisFile, processPID, processType, leakThreshold)
--- a/toolkit/xre/nsEmbedFunctions.cpp
+++ b/toolkit/xre/nsEmbedFunctions.cpp
@@ -251,16 +251,18 @@ nsresult
 XRE_InitChildProcess(int aArgc,
                      char* aArgv[],
                      GeckoProcessType aProcess)
 {
   NS_ENSURE_ARG_MIN(aArgc, 2);
   NS_ENSURE_ARG_POINTER(aArgv);
   NS_ENSURE_ARG_POINTER(aArgv[0]);
 
+  sChildProcessType = aProcess;
+  
 #if defined(MOZ_WIDGET_GTK2)
   g_thread_init(NULL);
 #endif
 
   if (PR_GetEnv("MOZ_DEBUG_CHILD_PROCESS")) {
 #ifdef OS_POSIX
       printf("\n\nCHILDCHILDCHILDCHILD\n  debug me @%d\n\n", getpid());
       sleep(30);
@@ -314,17 +316,16 @@ XRE_InitChildProcess(int aArgc,
       NS_RUNTIMEABORT("rebuild with --enable-ipdl-tests");
 #endif
       break;
 
     default:
       NS_RUNTIMEABORT("Unknown main thread class");
     }
 
-    sChildProcessType = aProcess;
     ChildProcess process(mainThread);
 
     // Do IPC event loop
     sIOMessageLoop = MessageLoop::current();
 
     sIOMessageLoop->Run();
 
     sIOMessageLoop = nsnull;
--- a/xpcom/base/nsTraceRefcntImpl.cpp
+++ b/xpcom/base/nsTraceRefcntImpl.cpp
@@ -45,16 +45,27 @@
 #include "plstr.h"
 #include "prlink.h"
 #include <stdlib.h>
 #include "nsCOMPtr.h"
 #include "nsCRT.h"
 #include <math.h>
 #include "nsStackWalk.h"
 
+#ifdef MOZ_IPC
+#include "nsXULAppAPI.h"
+#include "nsString.h"
+#ifdef XP_WIN
+#include <process.h>
+#define getpid _getpid
+#else
+#include <unistd.h>
+#endif
+#endif
+
 #ifdef HAVE_LIBDL
 #include <dlfcn.h>
 #endif
 
 ////////////////////////////////////////////////////////////////////////////////
 
 NS_COM void
 NS_MeanAndStdDev(double n, double sumOfValues, double sumOfSquaredValues,
@@ -313,18 +324,22 @@ public:
   }
 
   static PRBool HaveLeaks(nsTraceRefcntStats* stats) {
     return ((stats->mAddRefs != stats->mReleases) ||
             (stats->mCreates != stats->mDestroys));
   }
 
   PRBool PrintDumpHeader(FILE* out, const char* msg, nsTraceRefcntImpl::StatisticsType type) {
+#ifdef MOZ_IPC
+    fprintf(out, "\n== BloatView: %s, %s process %d\n", msg,
+            XRE_ChildProcessTypeToString(XRE_GetProcessType()), getpid());
+#else
     fprintf(out, "\n== BloatView: %s\n", msg);
-
+#endif
     nsTraceRefcntStats& stats =
       (type == nsTraceRefcntImpl::NEW_STATS) ? mNewStats : mAllStats;
     if (gLogLeaksOnly && !HaveLeaks(&stats))
       return PR_FALSE;
 
     fprintf(out,
         "\n" \
         "     |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->|\n" \
@@ -613,28 +628,43 @@ static PRBool InitLog(const char* envVar
     }
     else if (nsCRT::strcmp(value, "2") == 0) {
       *result = stderr;
       fprintf(stdout, "### %s defined -- logging %s to stderr\n",
               envVar, msg);
       return PR_TRUE;
     }
     else {
-      FILE *stream = ::fopen(value, "w");
+      FILE *stream;
+      nsCAutoString fname(value);
+#ifdef MOZ_IPC
+      if (XRE_GetProcessType() != GeckoProcessType_Default) {
+        bool hasLogExtension = 
+            fname.RFind(".log", PR_TRUE, -1, 4) == kNotFound ? false : true;
+        if (hasLogExtension)
+          fname.Cut(fname.Length() - 4, 4);
+        fname.AppendLiteral("_");
+        fname.Append((char*)XRE_ChildProcessTypeToString(XRE_GetProcessType()));
+        fname.AppendLiteral("_pid");
+        fname.AppendInt(getpid());
+        if (hasLogExtension)
+          fname.AppendLiteral(".log");
+      }
+#endif
+      stream = ::fopen(fname.get(), "w");
       if (stream != NULL) {
         *result = stream;
         fprintf(stdout, "### %s defined -- logging %s to %s\n",
-                envVar, msg, value);
-        return PR_TRUE;
+                envVar, msg, fname.get());
       }
       else {
         fprintf(stdout, "### %s defined -- unable to log %s to %s\n",
-                envVar, msg, value);
-        return PR_FALSE;
+                envVar, msg, fname.get());
       }
+      return stream != NULL;
     }
   }
   return PR_FALSE;
 }
 
 
 static PLHashNumber HashNumber(const void* aKey)
 {