Bug 674384: jprof - better thread support, support e10s profiling and profile-by-capture-section. r=dbaron DONTBUILD

This commit is contained in:
Randell Jesup 2011-08-12 11:59:20 -04:00
Родитель 66270b3aa0
Коммит ba2312b9cb
5 изменённых файлов: 162 добавлений и 66 удалений

Просмотреть файл

@ -1558,7 +1558,12 @@ static nsresult LaunchChild(nsINativeAppSupport* aNative,
// Restart this process by exec'ing it into the current process
// if supported by the platform. Otherwise, use NSPR.
#ifdef MOZ_JPROF
// make sure JPROF doesn't think we're E10s
unsetenv("JPROF_SLAVE");
#endif
if (aBlankCommandLine) {
#if defined(MOZ_WIDGET_QT)
// Remove only arguments not given to Qt

Просмотреть файл

@ -48,18 +48,25 @@ equivalent to ensure frame pointer generation in the compiler you're using.</p>
<p>Finally, build mozilla with your new configuration. Now you can run jprof.</p>
<h3><a name="usage">Usage</a></h3>
<pre> jprof [-v] [-t] [-e exclude] [-i include] [-s stackdepth] [--last] [--all] [--start n [--end m]] [--output-dir dir] prog log [log2 ...]</pre>
Options:
<ul>
<li><b>-s depth</b> : Limit depth looked at from captured stack
frames</li>
<li><b>-v</b> : Output some information about the symbols, memory map, etc.</li>
<li><b>-t</b> : Group output according to thread. Requires external
<li><b>-t or --threads</b> : Group output according to thread. May require external
LD_PRELOAD library to help force sampling of spawned threads; jprof
normally captures the main thread only. See <a
may capture the main thread only. See <a
href="http://sam.zoy.org/writings/programming/gprof.html">gprof-helper</a>;
it may need adaption for jprof.</li>
<li><b>--only-thread id</b> : Only output data for thread 'id'</li>
<li><b>-e exclusion</b> : Allows excluding specific stack frames</li>
<li><b>-i inclusion</b> : Allows including specific stack frames</li>
<li><b>--last</b> : Only process data from the last 'section' of sampling
(starting at the last PROF)</li>
<li><b>--start N</b> : Start processing data at 'section' N </li>
<li><b>--end N</b> : Stop processing data at 'section' N </li>
<li><b>--output-dir dir</b> : Store generated .html files in the given directory </li>
</ul>
The behavior of jprof is determined by the value of the JPROF_FLAGS environment
variable. This environment variable can be composed of several substrings
@ -95,6 +102,12 @@ which have the following meanings:
set to is 8192. Note that <code>/dev/rtc</code> will need to be readable
by the Firefox process; making that file world-readable is a simple way to
accomplish that.
<li> <b>JP_FILENAME=basefilename</b> : This is the filename used for
saving the log files to; the default is "jprof-log". If Electrolysis
is used, each process after the first will have the process ID
added ("jprof-log-3212");
</ul>
<h4>Starting and stopping jprof from JavaScript</h4>
@ -149,12 +162,19 @@ this jprof needs the name of the mozilla binary and the log file. It deduces
the name of the map file:
<pre>
./jprof /home/user/mozilla/debug/dist/bin/mozilla-bin ./jprof-log > tmp.html
./jprof /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log > tmp.html
</pre>
This will generate the file <code>tmp.html</code> which you should view in a
web browser.
<pre>
./jprof --output-dir=/tmp /home/user/mozilla/objdir/dist/bin/firefox ./jprof-log*
</pre>
This will generate a set of files in /tmp for each process.
<h3><a name="interpretation">Interpretation</a></h3>

Просмотреть файл

@ -72,7 +72,30 @@ int main(int argc, char** argv)
leaky* l = new leaky;
l->initialize(argc, argv);
l->open();
l->outputfd = stdout;
for (int i = 0; i < l->numLogFiles; i++) {
if (l->output_dir || l->numLogFiles > 1) {
char name[2048]; // XXX fix
if (l->output_dir)
snprintf(name,sizeof(name),"%s/%s.html",l->output_dir,argv[l->logFileIndex + i]);
else
snprintf(name,sizeof(name),"%s.html",argv[l->logFileIndex + i]);
fprintf(stderr,"opening %s\n",name);
l->outputfd = fopen(name,"w");
// if an error we won't process the file
}
if (l->outputfd) { // paranoia
l->open(argv[l->logFileIndex + i]);
if (l->outputfd != stderr) {
fclose(l->outputfd);
l->outputfd = NULL;
}
}
}
return 0;
}
@ -125,12 +148,11 @@ htmlify(const char *in)
leaky::leaky()
{
applicationName = NULL;
logFile = NULL;
progFile = NULL;
quiet = TRUE;
showAddress = FALSE;
showThreads = FALSE;
quiet = true;
showAddress = false;
showThreads = false;
stackDepth = 100000;
onlyThread = 0;
@ -157,15 +179,19 @@ leaky::~leaky()
void leaky::usageError()
{
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, "Usage: %s [-v] [-t] [-e exclude] [-i include] [-s stackdepth] [--last] [--all] [--start n [--end m]] [--output-dir dir] prog log [log2 ...]\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-s stackdepth: Limit depth looked at from captured stack frames\n"
"\t--last: only profile the last capture section\n"
"\t--start n [--end m]: profile n to m (or end) capture sections\n"
"\t--output-dir dir: write output files to dir\n"
"\tIf there's one log, output goes to stdout unless --output-dir is set\n"
"\tIf there are more than one log, output files will be named with .html added\n"
);
exit(-1);
}
@ -176,6 +202,7 @@ static struct option longopts[] = {
{ "last", 0, NULL, 'l' },
{ "start", 1, NULL, 'x' },
{ "end", 1, NULL, 'n' },
{ "output-dir", 1, NULL, 'd' },
{ NULL, 0, NULL, 0 },
};
@ -192,8 +219,12 @@ void leaky::initialize(int argc, char** argv)
int arg;
int errflg = 0;
int longindex = 0;
onlyThread = 0;
output_dir = NULL;
// XXX tons of cruft here left over from tracemalloc
// XXX The -- options shouldn't need short versions, or they should be documented
while (((arg = getopt_long(argc, argv, "adEe:gh:i:r:Rs:tT:qvx:ln:",longopts,&longindex)) != -1)) {
switch (arg) {
case '?':
@ -204,9 +235,10 @@ void leaky::initialize(int argc, char** argv)
case 'a':
break;
case 'A': // not implemented
showAddress = TRUE;
showAddress = true;
break;
case 'd':
output_dir = optarg; // reference to an argv pointer
break;
case 'R':
break;
@ -253,10 +285,10 @@ void leaky::initialize(int argc, char** argv)
quiet = !quiet;
break;
case 't':
showThreads = TRUE;
showThreads = true;
break;
case 'T':
showThreads = TRUE;
showThreads = true;
onlyThread = atoi(optarg);
break;
}
@ -265,7 +297,10 @@ void leaky::initialize(int argc, char** argv)
usageError();
}
progFile = argv[optind++];
logFile = argv[optind];
logFileIndex = optind;
numLogFiles = argc - optind;
if (!quiet)
fprintf(stderr,"numlogfiles = %d\n",numLogFiles);
}
static void* mapFile(int fd, u_int flags, off_t* sz)
@ -289,31 +324,34 @@ void leaky::LoadMap()
malloc_map_entry mme;
char name[1000];
int fd = ::open(M_MAPFILE, O_RDONLY);
if (fd < 0) {
perror("open: " M_MAPFILE);
exit(-1);
}
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) {
fprintf(stderr,"%s @ %lx\n", name, mme.address);
if (!loadMap) {
// all files use the same map
int fd = ::open(M_MAPFILE, O_RDONLY);
if (fd < 0) {
perror("open: " M_MAPFILE);
exit(-1);
}
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) {
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;
LoadMapEntry* lme = new LoadMapEntry;
lme->address = mme.address;
lme->name = strdup(name);
lme->next = loadMap;
loadMap = lme;
}
close(fd);
}
close(fd);
}
void leaky::open()
void leaky::open(char *logFile)
{
int threadArray[100]; // should auto-expand
int last_thread = -1;
@ -326,6 +364,9 @@ void leaky::open()
setupSymbols(progFile);
// open up the log file
if (mappedLogFile)
::close(mappedLogFile);
mappedLogFile = ::open(logFile, O_RDONLY);
if (mappedLogFile < 0) {
perror("open");
@ -360,8 +401,9 @@ void leaky::open()
collecting = false;
lastLogEntry = lep;
}
fprintf(stderr,"New section %d: first=%x, last=%x, collecting=%d\n",
section,firstLogEntry,lastLogEntry,collecting);
if (!quiet)
fprintf(stderr,"New section %d: first=%p, last=%p, collecting=%d\n",
section,(void*)firstLogEntry,(void*)lastLogEntry,collecting);
}
// Capture thread info at the same time
@ -393,23 +435,24 @@ void leaky::open()
}
}
}
fprintf(stderr,"Done collecting: sections %d: first=%x, last=%x, numThreads=%d\n",
section,firstLogEntry,lastLogEntry,numThreads);
if (!quiet)
fprintf(stderr,"Done collecting: sections %d: first=%p, last=%p, numThreads=%d\n",
section,(void*)firstLogEntry,(void*)lastLogEntry,numThreads);
fprintf(stdout,"<html><head><title>Jprof Profile Report</title></head><body>\n");
fprintf(stdout,"<h1><center>Jprof Profile Report</center></h1>\n");
fprintf(outputfd,"<html><head><title>Jprof Profile Report</title></head><body>\n");
fprintf(outputfd,"<h1><center>Jprof Profile Report</center></h1>\n");
if (showThreads)
{
fprintf(stderr,"Num threads %d\n",numThreads);
fprintf(stdout,"<hr>Threads:<p><pre>\n");
fprintf(outputfd,"<hr>Threads:<p><pre>\n");
for (int i=0; i<numThreads; i++)
{
fprintf(stdout," <a href=\"#thread_%d\">%d</a> ",
fprintf(outputfd," <a href=\"#thread_%d\">%d</a> ",
threadArray[i],threadArray[i]);
}
fprintf(stdout,"</pre>");
fprintf(outputfd,"</pre>");
for (int i=0; i<numThreads; i++)
{
@ -422,9 +465,7 @@ void leaky::open()
analyze(0);
}
fprintf(stdout,"</pre></body></html>\n");
exit(0);
fprintf(outputfd,"</pre></body></html>\n");
}
//----------------------------------------------------------------------
@ -449,20 +490,24 @@ void leaky::ReadSharedLibrarySymbols()
void leaky::setupSymbols(const char *fileName)
{
// Read in symbols from the program
ReadSymbols(fileName, 0);
if (usefulSymbols == 0) {
// only read once!
// Read in symbols from the .so's
ReadSharedLibrarySymbols();
// Read in symbols from the program
ReadSymbols(fileName, 0);
if (!quiet) {
fprintf(stderr,"A total of %d symbols were loaded\n", usefulSymbols);
// Read in symbols from the .so's
ReadSharedLibrarySymbols();
if (!quiet) {
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;
}
// Now sort them
qsort(externalSymbols, usefulSymbols, sizeof(Symbol), symbolOrder);
lowestSymbolAddr = externalSymbols[0].address;
highestSymbolAddr = externalSymbols[usefulSymbols-1].address;
}
// Binary search the table, looking for a symbol that covers this
@ -568,7 +613,7 @@ void leaky::dumpEntryToLog(malloc_log_entry* lep)
{
printf("%ld\t", lep->delTime);
printf(" --> ");
displayStackTrace(stdout, lep);
displayStackTrace(outputfd, lep);
}
void leaky::generateReportHTML(FILE *fp, int *countArray, int count, int thread)
@ -774,7 +819,7 @@ void leaky::analyze(int thread)
}
}
generateReportHTML(stdout, countArray, stacks, thread);
generateReportHTML(outputfd, countArray, stacks, thread);
}
void FunctionCount::printReport(FILE *fp, leaky *lk, int parent, int total)

Просмотреть файл

@ -83,17 +83,20 @@ struct leaky {
~leaky();
void initialize(int argc, char** argv);
void open();
void open(char *arg);
char* applicationName;
char* logFile;
int logFileIndex;
int numLogFiles;
char* progFile;
FILE* outputfd;
int quiet;
int showAddress;
int showThreads;
u_int stackDepth;
bool quiet;
bool showAddress;
bool showThreads;
u_int stackDepth;
int onlyThread;
char* output_dir;
int mappedLogFile;
malloc_log_entry* firstLogEntry;

Просмотреть файл

@ -399,6 +399,8 @@ void *ucontext)
NS_EXPORT_(void) setupProfilingStuff(void)
{
static int gFirstTime = 1;
char filename[2048]; // XXX fix
if(gFirstTime && !(gFirstTime=0)) {
int startTimer = 1;
int doNotStart = 1;
@ -420,6 +422,10 @@ NS_EXPORT_(void) setupProfilingStuff(void)
* JP_APPEND -> Append to jprof-log rather than overwriting it.
* This is somewhat risky since it depends on the
* address map staying constant across multiple runs.
* JP_FILENAME -> base filename to use when saving logs. Note that
* this does not affect the mapfile.
*
* JPROF_SLAVE is set if this is not the first process.
*/
if(tst) {
if(strstr(tst, "JP_DEFER"))
@ -470,12 +476,29 @@ NS_EXPORT_(void) setupProfilingStuff(void)
#endif
}
char *f = strstr(tst,"JP_FILENAME=");
if (f)
f = f + strlen("JP_FILENAME=");
else
f = M_LOGFILE;
char *is_slave = getenv("JPROF_SLAVE");
if (!is_slave)
setenv("JPROF_SLAVE","", 0);
int pid = syscall(SYS_gettid); //gettid();
if (is_slave)
snprintf(filename,sizeof(filename),"%s-%d",f,pid);
else
snprintf(filename,sizeof(filename),"%s",f);
// XXX FIX! inherit current capture state!
}
if(!doNotStart) {
if(gLogFD<0) {
gLogFD = open(M_LOGFILE, O_CREAT | O_WRONLY | append, 0666);
gLogFD = open(filename, O_CREAT | O_WRONLY | append, 0666);
if(gLogFD<0) {
fprintf(stderr, "Unable to create " M_LOGFILE);
perror(":");