Bug 664453: Stop jprof from crashing before a profile is selected on JP_START. r=dbaron DONTBUILD
authorRandell Jesup <rjesup@wgate.com>
Fri, 12 Aug 2011 11:59:17 -0400
changeset 74341 71c422d27ed4ea3c3951ae23b134318310c8682e
parent 74313 3c8f87c6cbc69dc1f90cfac82b5ed1dd9c171558
child 74342 997256d4e070a07ea648ad5f554ae9302651ab01
push id1193
push userMs2ger@gmail.com
push dateSat, 13 Aug 2011 12:50:08 +0000
treeherdermozilla-inbound@19ab9ba1c623 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdbaron
bugs664453
milestone8.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 664453: Stop jprof from crashing before a profile is selected on JP_START. r=dbaron DONTBUILD
tools/jprof/intcnt.cpp
tools/jprof/intcnt.h
tools/jprof/leaky.cpp
tools/jprof/leaky.h
tools/jprof/stub/libmalloc.cpp
tools/jprof/stub/libmalloc.h
--- a/tools/jprof/intcnt.cpp
+++ b/tools/jprof/intcnt.cpp
@@ -36,16 +36,23 @@
 #include "intcnt.h"
 
 IntCount::IntCount() : numInts(0), iPair(0) { }
 IntCount::~IntCount() { delete [] iPair;}
 int IntCount::getSize() {return numInts;}
 int IntCount::getCount(int pos) {return iPair[pos].cnt;}
 int IntCount::getIndex(int pos) {return iPair[pos].idx;}
 
+void IntCount::clear()
+{
+    delete[] iPair;
+    iPair = new IntPair[0];
+    numInts = 0;
+}
+
 int IntCount::countAdd(int index, int increment)
 {
     if(numInts) {
 	// Do a binary search to find the element
 	int divPoint = 0;
 
 	if(index>iPair[numInts-1].idx) {
 	    divPoint = numInts;
--- a/tools/jprof/intcnt.h
+++ b/tools/jprof/intcnt.h
@@ -36,16 +36,17 @@
 #ifndef INTCNT_H
 #define INTCNT_H
 
 class IntCount
 {
 public:
     IntCount();
     ~IntCount();
+    void clear();
     int countAdd(int index, int increment=1);
     int countGet(int index);
     int getSize();
     int getCount(int pos);
     int getIndex(int pos);
 
 private:
     IntCount(const IntCount&); // No copy constructor
--- a/tools/jprof/leaky.cpp
+++ b/tools/jprof/leaky.cpp
@@ -1,9 +1,9 @@
-/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* ***** BEGIN LICENSE BLOCK *****
  * Version: MPL 1.1/GPL 2.0/LGPL 2.1
  *
  * The contents of this file are subject to the Mozilla Public License Version
  * 1.1 (the "License"); you may not use this file except in compliance with
  * the License. You may obtain a copy of the License at
  * http://www.mozilla.org/MPL/
  *
@@ -14,16 +14,17 @@
  *
  * The Original Code is mozilla.org code.
  *
  * The Initial Developer of the Original Code is Netscape Communications Corp.
  * Portions created by the Initial Developer are Copyright (C) 1998
  * the Initial Developer. All Rights Reserved.
  *
  * Contributor(s):
+ *    Randell Jesup (recent improvements, threads, etc)
  *
  * Alternatively, the contents of this file may be used under the terms of
  * either the GNU General Public License Version 2 or later (the "GPL"), or
  * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
  * in which case the provisions of the GPL or the LGPL are applicable instead
  * of those above. If you wish to allow use of your version of this file only
  * under the terms of either the GPL or the LGPL, and not to allow others to
  * use your version of this file under the terms of the MPL, indicate your
@@ -126,57 +127,83 @@ leaky::leaky()
   applicationName = NULL;
   logFile = NULL;
   progFile = NULL;
 
   quiet = TRUE;
   showAddress = FALSE;
   showThreads = FALSE;
   stackDepth = 100000;
+  onlyThread = 0;
 
   mappedLogFile = -1;
   firstLogEntry = lastLogEntry = 0;
 
   sfd = -1;
   externalSymbols = 0;
   usefulSymbols = 0;
   numExternalSymbols = 0;
   lowestSymbolAddr = 0;
   highestSymbolAddr = 0;
 
   loadMap = NULL;
+
+  collect_last  = false;
+  collect_start = -1;
+  collect_end   = -1;
 }
 
 leaky::~leaky()
 {
 }
 
 void leaky::usageError()
 {
-  fprintf(stderr, "Usage: %s [-v][-t] [-e exclude] [-i include] [-s stackdepth] prog log\n", (char*) applicationName);
-  fprintf(stderr, "\t-v: verbose\n\t-t: split threads\n");
+  fprintf(stderr, "Usage: %s [-v] [-t] [-e exclude] [-i include] [-s stackdepth] [--last] [--all] [--start n [--end m]] prog log\n", (char*) applicationName);
+  fprintf(stderr, 
+          "\t-v: verbose\n"
+          "\t-t | --threads: split threads\n"
+          "\t--only-thread n: only profile thread N\n"
+          "\t-i include-id: stack must include specified id\n"
+          "\t-e exclude-id: stack must NOT include specified id\n"
+          "\t--last: only profile the last capture section\n"
+          "\t--start n [--end m]: profile n to m (or end) capture sections\n"
+          );
   exit(-1);
 }
 
+static struct option longopts[] = {
+    { "threads", 0, NULL, 't' },
+    { "only-thread", 1, NULL, 'T' },
+    { "last", 0, NULL, 'l' },
+    { "start", 1, NULL, 'x' },
+    { "end", 1, NULL, 'n' },
+    { NULL, 0, NULL, 0 },
+};
+
 void leaky::initialize(int argc, char** argv)
 {
   applicationName = argv[0];
   applicationName = strrchr(applicationName, '/');
   if (!applicationName) {
     applicationName = argv[0];
   } else {
     applicationName++;
   }
 
   int arg;
   int errflg = 0;
-  while ((arg = getopt(argc, argv, "adEe:gh:i:r:Rs:tqvx")) != -1) {
+  int longindex = 0;
+  onlyThread = 0;
+  // XXX tons of cruft here left over from tracemalloc
+  while (((arg = getopt_long(argc, argv, "adEe:gh:i:r:Rs:tT:qvx:ln:",longopts,&longindex)) != -1)) {
     switch (arg) {
       case '?':
       default:
+        fprintf(stderr,"error: unknown option %c\n",optopt);
 	errflg++;
 	break;
       case 'a':
 	break;
       case 'A': // not implemented
 	showAddress = TRUE;
 	break;
       case 'd':
@@ -204,25 +231,39 @@ void leaky::initialize(int argc, char** 
 	break;
       case 's':
 	stackDepth = atoi(optarg);
 	if (stackDepth < 2) {
 	  stackDepth = 2;
 	}
 	break;
       case 'x':
+        // --start
+        collect_start = atoi(optarg);
 	break;
+      case 'n':
+        // --end
+        collect_end = atoi(optarg);
+        break;
+      case 'l':
+        // --last
+        collect_last = true;
+        break;
       case 'q':
         break;
       case 'v':
         quiet = !quiet;
         break;
       case 't':
         showThreads = TRUE;
 	break;
+      case 'T':
+        showThreads = TRUE;
+        onlyThread = atoi(optarg);
+	break;
     }
   }
   if (errflg || ((argc - optind) < 2)) {
     usageError();
   }
   progFile = argv[optind++];
   logFile = argv[optind];
 }
@@ -255,95 +296,130 @@ void leaky::LoadMap()
   }
   for (;;) {
     int nb = read(fd, &mme, sizeof(mme));
     if (nb != sizeof(mme)) break;
     nb = read(fd, name, mme.nameLen);
     if (nb != (int)mme.nameLen) break;
     name[mme.nameLen] = 0;
     if (!quiet) {
-      printf("%s @ %lx\n", name, mme.address);
+      fprintf(stderr,"%s @ %lx\n", name, mme.address);
     }
 
     LoadMapEntry* lme = new LoadMapEntry;
     lme->address = mme.address;
     lme->name = strdup(name);
     lme->next = loadMap;
     loadMap = lme;
   }
   close(fd);
 }
 
 void leaky::open()
 {
   int threadArray[100]; // should auto-expand
   int last_thread = -1;
-  int numThreads=0;
+  int numThreads = 0;
+  int section = -1;
+  bool collecting = false;
 
   LoadMap();
 
   setupSymbols(progFile);
 
   // open up the log file
   mappedLogFile = ::open(logFile, O_RDONLY);
   if (mappedLogFile < 0) {
     perror("open");
     exit(-1);
   }
   off_t size;
   firstLogEntry = (malloc_log_entry*) mapFile(mappedLogFile, PROT_READ, &size);
   lastLogEntry = (malloc_log_entry*)((char*)firstLogEntry + size);
 
-  fprintf(stdout,"<html><head><title>Jprof Profile Report</title></head><body>\n");
-  fprintf(stdout,"<h1><center>Jprof Profile Report</center></h1>\n");
+  if (!collect_last || collect_start < 0) {
+    collecting = true;
+  }
+
+  // First, restrict it to the capture sections specified (all, last, start/end)
+  // This loop walks through all the call stacks we recorded
+  for (malloc_log_entry* lep=firstLogEntry;
+       lep < lastLogEntry;
+       lep = reinterpret_cast<malloc_log_entry*>(&lep->pcs[lep->numpcs])) {
 
-  if (showThreads)
-  {
+    if (lep->flags & JP_FIRST_AFTER_PAUSE) {
+      section++;
+      if (collect_last) {
+        firstLogEntry = lep;
+        numThreads = 0;
+        collecting = true;
+      }
+      if (collect_start == section) {
+        collecting = true;
+        firstLogEntry = lep;
+      }
+      if (collect_end == section) {
+        collecting = false;
+        lastLogEntry = lep;
+      }
+      fprintf(stderr,"New section %d: first=%x, last=%x, collecting=%d\n",
+              section,firstLogEntry,lastLogEntry,collecting);
+    }
+
+    // Capture thread info at the same time
+
     // Find all the threads captured
 
     // pthread/linux docs say the signal can be delivered to any thread in
     // the process.  In practice, it appears in Linux that it's always
     // delivered to the thread that called setitimer(), and each thread can
     // have a separate itimer.  There's a support library for gprof that
     // overlays pthread_create() to set timers in any threads you spawn.
-
-    // This loop walks through all the call stacks we recorded
-    for (malloc_log_entry* lep=firstLogEntry;
-         lep < lastLogEntry;
-         lep = reinterpret_cast<malloc_log_entry*>(&lep->pcs[lep->numpcs])) {
+    if (showThreads && collecting) {
       if (lep->thread != last_thread)
       {
         int i;
         for (i=0; i<numThreads; i++)
         {
           if (lep->thread == threadArray[i])
             break;
         }
         if (i == numThreads &&
             i < (int) (sizeof(threadArray)/sizeof(threadArray[0])))
         {
           threadArray[i] = lep->thread;
           numThreads++;
-          fprintf(stderr,"new thread %d\n",lep->thread);
+          if (!quiet)
+            fprintf(stderr,"new thread %d\n",lep->thread);
         }
       }
     }
+  }  
+  fprintf(stderr,"Done collecting: sections %d: first=%x, last=%x, numThreads=%d\n",
+          section,firstLogEntry,lastLogEntry,numThreads);
+
+  fprintf(stdout,"<html><head><title>Jprof Profile Report</title></head><body>\n");
+  fprintf(stdout,"<h1><center>Jprof Profile Report</center></h1>\n");
+
+  if (showThreads)
+  {
     fprintf(stderr,"Num threads %d\n",numThreads);
 
     fprintf(stdout,"<hr>Threads:<p><pre>\n");
     for (int i=0; i<numThreads; i++)
     {
-      fprintf(stdout,"   <a href=\"thread_%d\">%d</a><p>\n",
+      fprintf(stdout,"   <a href=\"#thread_%d\">%d</a>  ",
               threadArray[i],threadArray[i]);
     }
-    fprintf(stdout,"</pre><hr>");
+    fprintf(stdout,"</pre>");
 
     for (int i=0; i<numThreads; i++)
     {
-      analyze(threadArray[i]);
+      if (!onlyThread || onlyThread == threadArray[i])
+        analyze(threadArray[i]);
     }
   }
   else
   {
     analyze(0);
   }
 
   fprintf(stdout,"</pre></body></html>\n");
@@ -375,17 +451,17 @@ void leaky::setupSymbols(const char *fil
 {
   // Read in symbols from the program
   ReadSymbols(fileName, 0);
 
   // Read in symbols from the .so's
   ReadSharedLibrarySymbols();
 
   if (!quiet) {
-    printf("A total of %d symbols were loaded\n", usefulSymbols);
+    fprintf(stderr,"A total of %d symbols were loaded\n", usefulSymbols);
   }
 
   // Now sort them
   qsort(externalSymbols, usefulSymbols, sizeof(Symbol), symbolOrder);
   lowestSymbolAddr = externalSymbols[0].address;
   highestSymbolAddr = externalSymbols[usefulSymbols-1].address;
 }
 
@@ -622,25 +698,32 @@ void leaky::generateReportHTML(FILE *fp,
 void leaky::analyze(int thread)
 {
   int *countArray = new int[usefulSymbols];
   int *flagArray  = new int[usefulSymbols];
 
   //Zero our function call counter
   memset(countArray, 0, sizeof(countArray[0])*usefulSymbols);
 
+  // reset hit counts
+  for(int i=0; i<usefulSymbols; i++) {
+    externalSymbols[i].timerHit = 0;
+    externalSymbols[i].regClear();
+  }
+
   // The flag array is used to prevent counting symbols multiple times
   // if functions are called recursively.  In order to keep from having
   // to zero it on each pass through the loop, we mark it with the value
   // of stacks on each trip through the loop.  This means we can determine
   // if we have seen this symbol for this stack trace w/o having to reset
   // from the prior stacktrace.
   memset(flagArray, -1, sizeof(flagArray[0])*usefulSymbols);
 
   // This loop walks through all the call stacks we recorded
+  // --last, --start and --end can restrict it, as can excludes/includes
   stacks = 0;
   for(malloc_log_entry* lep=firstLogEntry; 
     lep < lastLogEntry;
     lep = reinterpret_cast<malloc_log_entry*>(&lep->pcs[lep->numpcs])) {
 
     if ((thread != 0 && lep->thread != thread) ||
         excluded(lep) || !included(lep))
     {
--- a/tools/jprof/leaky.h
+++ b/tools/jprof/leaky.h
@@ -58,16 +58,17 @@ public:
 struct Symbol {
   char* name;
   u_long address;
   int    timerHit;
   FunctionCount cntP, cntC;
 
   int regChild(int id) {return cntC.countAdd(id, 1);}
   int regParrent(int id) {return cntP.countAdd(id, 1);}
+  void regClear() {cntC.clear(); cntP.clear();}
 
   Symbol() : timerHit(0) {}
   void Init(const char* aName, u_long aAddress) {
     name = aName ? strdup(aName) : (char *)"";
     address = aAddress;
   }
 };
 
@@ -87,16 +88,17 @@ struct leaky {
   char*  applicationName;
   char*  logFile;
   char*  progFile;
 
   int   quiet;
   int   showAddress;
   int   showThreads;
   u_int  stackDepth;
+  int   onlyThread;
 
   int   mappedLogFile;
   malloc_log_entry* firstLogEntry;
   malloc_log_entry* lastLogEntry;
 
   int    stacks;
 
   int sfd;
@@ -104,16 +106,20 @@ struct leaky {
   int     usefulSymbols;
   int     numExternalSymbols;
   StrSet exclusions;
   u_long lowestSymbolAddr;
   u_long highestSymbolAddr;
 
   LoadMapEntry* loadMap;
 
+  bool collect_last;
+  int  collect_start;
+  int  collect_end;
+
   StrSet roots;
   StrSet includes;
 
   void usageError();
 
   void LoadMap();
 
   void analyze(int thread);
--- a/tools/jprof/stub/libmalloc.cpp
+++ b/tools/jprof/stub/libmalloc.cpp
@@ -208,32 +208,41 @@ static void DumpAddressMap()
       }
       map = map->l_next;
     }
     close(mfd);
   }
 }
 #endif
 
+static bool was_paused = true;
+
 static void EndProfilingHook(int signum)
 {
     DumpAddressMap();
+    was_paused = true;
     puts("Jprof: profiling paused.");
 }
 
 //----------------------------------------------------------------------
 
 JPROF_STATIC void
 JprofLog(u_long aTime, void* stack_top, void* top_instr_ptr)
 {
-  // Static is simply to make debugging tollerable
+  // Static is simply to make debugging tolerable
   static malloc_log_entry me;
 
   me.delTime = aTime;
   me.thread = syscall(SYS_gettid); //gettid();
+  if (was_paused) {
+      me.flags = JP_FIRST_AFTER_PAUSE;
+      was_paused = 0;
+  } else {
+      me.flags = 0;
+  }
 
   CrawlStack(&me, stack_top, top_instr_ptr);
 
 #ifndef NTO
   write(gLogFD, &me, offsetof(malloc_log_entry, pcs) + me.numpcs*sizeof(char*));
 #else
   printf("Neutrino is missing the pcs member of malloc_log_entry!! \n");
 #endif
@@ -492,21 +501,23 @@ NS_EXPORT_(void) setupProfilingStuff(voi
                             fputs("jprof: Error initializing RTC, NOT "
                                   "profiling\n", stderr);
                             return;
                         }
                     }
 
                     if (!rtcHz || firstDelay != 0)
 #endif
-                    if (realTime) {
-                        sigaction(SIGALRM, &action, NULL);
-                    } else {
-                        sigaction(SIGPROF, &action, NULL);
+                    {
+                        if (realTime) {
+                            sigaction(SIGALRM, &action, NULL);
+                        }
                     }
+                    // enable PROF in all cases to simplify JP_DEFER/pause/restart
+                    sigaction(SIGPROF, &action, NULL);
 
 		    // make it so a SIGUSR1 will stop the profiling
 		    // Note:  It currently does not close the logfile.
 		    // This could be configurable (so that it could
 		    // later be reopened).
 
 		    struct sigaction stop_action;
 		    stop_action.sa_handler = EndProfilingHook;
--- a/tools/jprof/stub/libmalloc.h
+++ b/tools/jprof/stub/libmalloc.h
@@ -42,21 +42,27 @@
 #ifdef __cplusplus
 extern "C" {
 #endif
 
 #include "config.h"
 
 typedef unsigned long u_long;
 
-// Format of a malloc log entry. This is what's written out to the
-// "malloc-log" file.
+// For me->flags
+#define JP_FIRST_AFTER_PAUSE 1
+
+// Format of a jprof log entry. This is what's written out to the
+// "jprof-log" file.
+// It's called malloc_log_entry because the history of jprof is that
+// it's a modified version of tracemalloc.
 struct malloc_log_entry {
   u_long delTime;
   u_long numpcs;
+  unsigned int flags;
   int thread;
   char* pcs[MAX_STACK_CRAWL];
 };
 
 // type's
 #define malloc_log_stack   7
 
 // Format of a malloc map entry; after this struct is nameLen+1 bytes of