Bug 1300948 - Add thread identifier to LogAlloc output. r=njn

memory/replace/logalloc/LogAlloc.cpp

@@ -38,6 +38,22 @@ postfork() {
   sLock.Release();
 }
 
+static size_t
+GetPid()
+{
+  return size_t(getpid());
+}
+
+static size_t
+GetTid()
+{
+#if defined(_WIN32)
+  return size_t(GetCurrentThreadId());
+#else
+  return size_t(pthread_self());
+#endif
+}
+
 #ifdef ANDROID
 /* See mozglue/android/APKOpen.cpp */
 extern "C" MOZ_EXPORT __attribute__((weak))
@@ -144,7 +160,7 @@ replace_malloc(size_t aSize)
   AutoLock lock(sLock);
   void* ptr = sFuncs->malloc(aSize);
   if (ptr) {
-    FdPrintf(sFd, "%zu malloc(%zu)=%p\n", size_t(getpid()), aSize, ptr);
+    FdPrintf(sFd, "%zu %zu malloc(%zu)=%p\n", GetPid(), GetTid(), aSize, ptr);
   }
   return ptr;
 }
@@ -155,7 +171,7 @@ replace_posix_memalign(void** aPtr, size_t aAlignment, size_t aSize)
   AutoLock lock(sLock);
   int ret = sFuncs->posix_memalign(aPtr, aAlignment, aSize);
   if (ret == 0) {
-    FdPrintf(sFd, "%zu posix_memalign(%zu,%zu)=%p\n", size_t(getpid()),
+    FdPrintf(sFd, "%zu %zu posix_memalign(%zu,%zu)=%p\n", GetPid(), GetTid(),
              aAlignment, aSize, *aPtr);
   }
   return ret;
@@ -167,7 +183,7 @@ replace_aligned_alloc(size_t aAlignment, size_t aSize)
   AutoLock lock(sLock);
   void* ptr = sFuncs->aligned_alloc(aAlignment, aSize);
   if (ptr) {
-    FdPrintf(sFd, "%zu aligned_alloc(%zu,%zu)=%p\n", size_t(getpid()),
+    FdPrintf(sFd, "%zu %zu aligned_alloc(%zu,%zu)=%p\n", GetPid(), GetTid(),
              aAlignment, aSize, ptr);
   }
   return ptr;
@@ -179,7 +195,8 @@ replace_calloc(size_t aNum, size_t aSize)
   AutoLock lock(sLock);
   void* ptr = sFuncs->calloc(aNum, aSize);
   if (ptr) {
-    FdPrintf(sFd, "%zu calloc(%zu,%zu)=%p\n", size_t(getpid()), aNum, aSize, ptr);
+    FdPrintf(sFd, "%zu %zu calloc(%zu,%zu)=%p\n", GetPid(), GetTid(), aNum,
+             aSize, ptr);
   }
   return ptr;
 }
@@ -190,8 +207,8 @@ replace_realloc(void* aPtr, size_t aSize)
   AutoLock lock(sLock);
   void* new_ptr = sFuncs->realloc(aPtr, aSize);
   if (new_ptr || !aSize) {
-    FdPrintf(sFd, "%zu realloc(%p,%zu)=%p\n", size_t(getpid()), aPtr, aSize,
-             new_ptr);
+    FdPrintf(sFd, "%zu %zu realloc(%p,%zu)=%p\n", GetPid(), GetTid(), aPtr,
+             aSize, new_ptr);
   }
   return new_ptr;
 }
@@ -201,7 +218,7 @@ replace_free(void* aPtr)
 {
   AutoLock lock(sLock);
   if (aPtr) {
-    FdPrintf(sFd, "%zu free(%p)\n", size_t(getpid()), aPtr);
+    FdPrintf(sFd, "%zu %zu free(%p)\n", GetPid(), GetTid(), aPtr);
   }
   sFuncs->free(aPtr);
 }
@@ -212,8 +229,8 @@ replace_memalign(size_t aAlignment, size_t aSize)
   AutoLock lock(sLock);
   void* ptr = sFuncs->memalign(aAlignment, aSize);
   if (ptr) {
-    FdPrintf(sFd, "%zu memalign(%zu,%zu)=%p\n", size_t(getpid()), aAlignment,
-             aSize, ptr);
+    FdPrintf(sFd, "%zu %zu memalign(%zu,%zu)=%p\n", GetPid(), GetTid(),
+             aAlignment, aSize, ptr);
   }
   return ptr;
 }
@@ -224,7 +241,7 @@ replace_valloc(size_t aSize)
   AutoLock lock(sLock);
   void* ptr = sFuncs->valloc(aSize);
   if (ptr) {
-    FdPrintf(sFd, "%zu valloc(%zu)=%p\n", size_t(getpid()), aSize, ptr);
+    FdPrintf(sFd, "%zu %zu valloc(%zu)=%p\n", GetPid(), GetTid(), aSize, ptr);
   }
   return ptr;
 }
@@ -234,5 +251,5 @@ replace_jemalloc_stats(jemalloc_stats_t* aStats)
 {
   AutoLock lock(sLock);
   sFuncs->jemalloc_stats(aStats);
-  FdPrintf(sFd, "%zu jemalloc_stats()\n", size_t(getpid()));
+  FdPrintf(sFd, "%zu %zu jemalloc_stats()\n", GetPid(), GetTid());
 }

memory/replace/logalloc/README

@@ -42,17 +42,17 @@ then copies stderr to stdout. This leads to: fd1 and fd2 sending to stderr
 of the parent process (the shell), and fd3 sending to gzip.)
 
 Each line of the allocations log is formatted as follows:
-  <pid> <function>([<args>])[=<result>]
+  <pid> <tid> <function>([<args>])[=<result>]
 where <args> is a comma separated list of values. The number of <args> and
 the presence of <result> depend on the <function>.
 
 Example log:
-  18545 malloc(32)=0x7f90495120e0
-  18545 calloc(1,148)=0x7f9049537480
-  18545 realloc(0x7f90495120e0,64)=0x7f9049536680
-  18545 posix_memalign(256,240)=0x7f9049583300
-  18545 jemalloc_stats()
-  18545 free(0x7f9049536680)
+  18545 18545 malloc(32)=0x7f90495120e0
+  18545 18545 calloc(1,148)=0x7f9049537480
+  18545 18545 realloc(0x7f90495120e0,64)=0x7f9049536680
+  18545 18545 posix_memalign(256,240)=0x7f9049583300
+  18545 18545 jemalloc_stats()
+  18545 18545 free(0x7f9049536680)
 
 This log can be replayed with the logalloc-replay tool in
 memory/replace/logalloc/replay. However, as the goal of that tool is to
@@ -69,12 +69,12 @@ in a large (almost) linear array of allocation tracking slots (prefixed with
 first seen pid number is 1, the second is 2, etc.).
 
 The above example log would become the following, once preprocessed:
-  1 malloc(32)=#1
-  1 calloc(1,148)=#2
-  1 realloc(#1,64)=#1
-  1 posix_memalign(256,240)=#3
-  1 jemalloc_stats()
-  1 free(#1)
+  1 1 malloc(32)=#1
+  1 1 calloc(1,148)=#2
+  1 1 realloc(#1,64)=#1
+  1 1 posix_memalign(256,240)=#3
+  1 1 jemalloc_stats()
+  1 1 free(#1)
 
 The logalloc-replay tool then takes the preprocessed log on its stdin and
 replays the allocations printed there, but will only replay those with the
@@ -91,7 +91,7 @@ to about:memory in Firefox, but they can also be added after preprocessing.
 Here is an example of what one can do:
 
   gunzip -c log.gz | python logalloc_munge.py | \
-  awk '$1 == "2" { print $0 } !(NR % 10000) { print "2 jemalloc_stats()" }' | \
+  awk '$1 == "2" { print $0 } !(NR % 10000) { print "2 1 jemalloc_stats()" }' | \
     ./logalloc-replay
 
 The above command replays the allocations of process #2, with some stats
@@ -103,5 +103,5 @@ through a different allocator. For example:
 
   LD_PRELOAD=libreplace_jemalloc.so logalloc-replay < log
 
-Will replay the log against jemalloc3 (which is, as of writing, what
+Will replay the log against jemalloc4 (which is, as of writing, what
 libreplace_jemalloc.so contains).

memory/replace/logalloc/replay/Replay.cpp

@@ -509,6 +509,10 @@ main()
       continue;
     }
 
+    /* The log contains thread ids for manual analysis, but we just ignore them
+     * for now. */
+    parseNumber(line.SplitChar(' '));
+
     Buffer func = line.SplitChar('(');
     Buffer args = line.SplitChar(')');
 

memory/replace/logalloc/replay/logalloc_munge.py

@@ -61,8 +61,12 @@ class Ignored(Exception): pass
 
 def split_log_line(line):
     try:
+        # The format for each line is:
+        # <pid> [<tid>] <function>([<args>])[=<result>]
+        #
+        # The original format didn't include the tid, so we try to parse
+        # lines whether they have one or not.
         pid, func_call = line.split(' ', 1)
-        # func_call format is <function>([<args>])[=<result>]
         call, result = func_call.split(')')
         func, args = call.split('(')
         args = args.split(',') if args else []
@@ -70,7 +74,11 @@ def split_log_line(line):
             if result[0] != '=':
                 raise Ignored('Malformed input')
             result = result[1:]
-        return pid, func, args, result
+        if ' ' in func:
+            tid, func = func.split(' ', 1)
+        else:
+            tid = pid
+        return pid, tid, func, args, result
     except:
         raise Ignored('Malformed input')
 
@@ -91,14 +99,16 @@ NUM_ARGUMENTS = {
 def main():
     process_pointers = defaultdict(IdMapping)
     pids = IdMapping()
+    tids = IdMapping()
     for line in sys.stdin:
         line = line.strip()
 
         try:
-            pid, func, args, result = split_log_line(line)
+            pid, tid, func, args, result = split_log_line(line)
 
             # Replace pid with an id.
             pid = pids[int(pid)]
+            tid = tids[int(tid)]
 
             pointers = process_pointers[pid]
 
@@ -124,7 +134,7 @@ def main():
                     raise Ignored('Result is NULL')
                 result = "#%d" % pointers[result]
 
-            print('%d %s(%s)%s' % (pid, func, ','.join(args),
+            print('%d %d %s(%s)%s' % (pid, tid, func, ','.join(args),
                 '=%s' % result if result else ''))
 
         except Exception as e:

memory/replace/logalloc/replay/replay.log

@@ -1,17 +1,17 @@
-1 malloc(42)=#1
-1 malloc(24)=#2
-2 malloc(42)=#1
-1 free(#1)
-1 posix_memalign(4096,1024)=#1
-1 calloc(4,42)=#3
-1 free(#2)
-1 realloc(#3,84)=#2
-1 aligned_alloc(512,1024)=#3
-1 memalign(512,1024)=#4
-1 valloc(1024)=#5
-1 jemalloc_stats()
-1 free(#5)
-1 free(#4)
-1 free(#3)
-1 free(#2)
-1 free(#1)
+1 1 malloc(42)=#1
+1 1 malloc(24)=#2
+2 2 malloc(42)=#1
+1 1 free(#1)
+1 1 posix_memalign(4096,1024)=#1
+1 1 calloc(4,42)=#3
+1 1 free(#2)
+1 1 realloc(#3,84)=#2
+1 1 aligned_alloc(512,1024)=#3
+1 1 memalign(512,1024)=#4
+1 1 valloc(1024)=#5
+1 1 jemalloc_stats()
+1 1 free(#5)
+1 1 free(#4)
+1 1 free(#3)
+1 1 free(#2)
+1 1 free(#1)