Bug 729182 - Implement visual event tracer, part1 - the core, r=benjamin+ehsan

This commit is contained in:
Honza Bambas 2012-06-12 19:06:21 +02:00
parent 41779e1714
commit 4ef538c86b
5 changed files with 721 additions and 0 deletions

View File

@ -7398,6 +7398,17 @@ if test -n "$NS_FUNCTION_TIMER"; then
AC_DEFINE(NS_FUNCTION_TIMER)
fi
dnl ========================================================
dnl = Enable runtime visual profiling logger
dnl ========================================================
MOZ_ARG_ENABLE_BOOL(visual-event-tracer,
[ --enable-visual-event-tracer Enable visual event tracer instrumentation],
MOZ_VISUAL_EVENT_TRACER=1,
MOZ_VISUAL_EVENT_TRACER=)
if test -n "$MOZ_VISUAL_EVENT_TRACER"; then
AC_DEFINE(MOZ_VISUAL_EVENT_TRACER)
fi
dnl ========================================================
dnl Turn on reflow counting
dnl ========================================================

View File

@ -39,6 +39,7 @@ CPPSRCS = \
nsMemoryReporterManager.cpp \
FunctionTimer.cpp \
ClearOnShutdown.cpp \
VisualEventTracer.cpp \
$(NULL)
ifeq ($(OS_ARCH),Linux)
@ -73,6 +74,7 @@ EXPORTS_mozilla = \
ClearOnShutdown.h \
AvailableMemoryTracker.h \
StackWalk.h \
VisualEventTracer.h \
$(NULL)
ifeq (windows,$(MOZ_WIDGET_TOOLKIT))

View File

@ -0,0 +1,462 @@
/* ***** 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/
*
* Software distributed under the License is distributed on an "AS IS" basis,
* WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
* for the specific language governing rights and limitations under the
* License.
*
* The Original Code is Mozilla code.
*
* The Initial Developer of the Original Code is
* Mozilla Foundation.
* Portions created by the Initial Developer are Copyright (C) 2012
* the Initial Developer. All Rights Reserved.
*
* Contributor(s):
* Honza Bambas <honzab.moz@firemni.cz>
*
* 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
* decision by deleting the provisions above and replace them with the notice
* and other provisions required by the GPL or the LGPL. If you do not delete
* the provisions above, a recipient may use your version of this file under
* the terms of any one of the MPL, the GPL or the LGPL.
*
* ***** END LICENSE BLOCK ***** */
#include "mozilla/VisualEventTracer.h"
#include "mozilla/Monitor.h"
#include "mozilla/TimeStamp.h"
#include "nscore.h"
#include "prthread.h"
#include "prprf.h"
#include "prio.h"
#include "prenv.h"
#include "plstr.h"
namespace mozilla { namespace eventtracer {
#ifdef MOZ_VISUAL_EVENT_TRACER
namespace {
const PRUint32 kBatchSize = 0x1000;
const char kTypeChars[eventtracer::eLast] = {' ','N','S','W','E','D'};
// Flushing thread and records queue monitor
mozilla::Monitor * gMonitor = nsnull;
// Accessed concurently but since this flag is not functionally critical
// for optimization purposes is not accessed under a lock
bool gInitialized = false;
// Record of a single event
class Record {
public:
Record()
: mType(::mozilla::eventtracer::eNone)
, mTime(0)
, mItem(nsnull)
, mText(nsnull)
, mText2(nsnull)
{
MOZ_COUNT_CTOR(Record);
}
~Record()
{
PL_strfree(mText);
PL_strfree(mText2);
MOZ_COUNT_DTOR(Record);
}
PRUint32 mType;
double mTime;
void * mItem;
char * mText;
char * mText2;
};
// An array of events, each thread keeps its own private instance
class RecordBatch {
public:
RecordBatch()
: mRecordsHead(new Record[kBatchSize])
, mRecordsTail(mRecordsHead + kBatchSize)
, mNextRecord(mRecordsHead)
, mNextBatch(nsnull)
, mThreadNameCopy(PL_strdup(PR_GetThreadName(PR_GetCurrentThread())))
{
MOZ_COUNT_CTOR(RecordBatch);
}
~RecordBatch()
{
delete [] mRecordsHead;
PL_strfree(mThreadNameCopy);
MOZ_COUNT_DTOR(RecordBatch);
}
static void FlushBatch(void * aData);
Record * mRecordsHead;
Record * mRecordsTail;
Record * mNextRecord;
RecordBatch * mNextBatch;
char * mThreadNameCopy;
};
// Protected by gMonitor, accessed concurently
// Linked list of batches threads want to flush on disk
RecordBatch * gLogHead = nsnull;
RecordBatch * gLogTail = nsnull;
// Registered as thread private data destructor
void
RecordBatch::FlushBatch(void * aData)
{
RecordBatch * threadLogPrivate = static_cast<RecordBatch *>(aData);
MonitorAutoLock mon(*gMonitor);
if (!gInitialized) {
delete threadLogPrivate;
return;
}
if (!gLogHead)
gLogHead = threadLogPrivate;
else // gLogTail is non-null
gLogTail->mNextBatch = threadLogPrivate;
gLogTail = threadLogPrivate;
mon.Notify();
}
// Helper class for filtering events by MOZ_PROFILING_EVENTS
class EventFilter
{
public:
static EventFilter * Build(const char * filterVar);
bool EventPasses(const char * eventName);
~EventFilter()
{
delete mNext;
PL_strfree(mFilter);
MOZ_COUNT_DTOR(EventFilter);
}
private:
EventFilter(const char * eventName, EventFilter * next)
: mFilter(PL_strdup(eventName))
, mNext(next)
{
MOZ_COUNT_CTOR(EventFilter);
}
char * mFilter;
EventFilter * mNext;
};
// static
EventFilter *
EventFilter::Build(const char * filterVar)
{
if (!filterVar || !*filterVar)
return nsnull;
// Reads a comma serpatated list of events.
// Copied from nspr logging code (read of NSPR_LOG_MODULES)
char eventName[64];
PRIntn evlen = strlen(filterVar), pos = 0, count, delta = 0;
// Read up to a comma or EOF -> get name of an event first in the list
count = sscanf(filterVar, "%63[^,]%n", eventName, &delta);
if (count == 0)
return nsnull;
pos = delta;
// Skip a comma, if present, accept spaces around it
count = sscanf(filterVar + pos, " , %n", &delta);
if (count != EOF)
pos += delta;
// eventName contains name of the first event in the list
// second argument recursively parses the rest of the list string and
// fills mNext of the just created EventFilter object chaining the objects
return new EventFilter(eventName, Build(filterVar + pos));
}
bool
EventFilter::EventPasses(const char * eventName)
{
if (!strcmp(eventName, mFilter))
return true;
if (mNext)
return mNext->EventPasses(eventName);
return false;
}
// State var to stop the flushing thread
bool gStopFlushingThread = false;
// State and control variables, initialized in Init() method, after it
// immutable and read concurently.
EventFilter * gEventFilter = nsnull;
const char * gLogFilePath = nsnull;
PRThread * gFlushingThread = nsnull;
PRUintn gThreadPrivateIndex;
mozilla::TimeStamp gProfilerStart;
// To prevent any major I/O blockade caused by call to eventtracer::Mark()
// we buffer the data produced by each thread and write it to disk
// in a separate low-priority thread.
// static
void FlushingThread(void * aArg)
{
PRFileDesc * logFile = PR_Open(gLogFilePath,
PR_WRONLY | PR_TRUNCATE | PR_CREATE_FILE,
0644);
MonitorAutoLock mon(*gMonitor);
if (!logFile) {
gInitialized = false;
return;
}
PRInt32 rv;
bool ioError = false;
const char logHead[] = "{\n\"version\": 1,\n\"records\":[\n";
rv = PR_Write(logFile, logHead, sizeof(logHead) - 1);
ioError |= (rv < 0);
bool firstBatch = true;
while (!gStopFlushingThread || gLogHead) {
if (ioError) {
gInitialized = false;
break;
}
mon.Wait();
// Grab the current log list head and start a new blank global list
RecordBatch * batch = gLogHead;
gLogHead = nsnull;
gLogTail = nsnull;
MonitorAutoUnlock unlock(*gMonitor); // no need to block on I/O :-)
while (batch) {
if (!firstBatch) {
const char threadDelimiter[] = ",\n";
rv = PR_Write(logFile, threadDelimiter, sizeof(threadDelimiter) - 1);
ioError |= (rv < 0);
}
firstBatch = false;
static const PRIntn kBufferSize = 2048;
char buf[kBufferSize];
PR_snprintf(buf, kBufferSize, "{\"thread\":\"%s\",\"log\":[\n",
batch->mThreadNameCopy);
rv = PR_Write(logFile, buf, strlen(buf));
ioError |= (rv < 0);
for (Record * record = batch->mRecordsHead;
record < batch->mNextRecord && !ioError;
++record) {
// mType carries both type and flags, separate type
// as lower 16 bits and flags as higher 16 bits.
// The json format expects this separated.
PRUint32 type = record->mType & 0xffffUL;
PRUint32 flags = record->mType >> 16;
PR_snprintf(buf, kBufferSize,
"{\"e\":\"%c\",\"t\":%f,\"f\":%d,\"i\":\"%p\",\"n\":\"%s%s\"}%s\n",
kTypeChars[type],
record->mTime,
flags,
record->mItem,
record->mText,
record->mText2 ? record->mText2 : "",
(record == batch->mNextRecord - 1) ? "" : ",");
rv = PR_Write(logFile, buf, strlen(buf));
ioError |= (rv < 0);
}
const char threadTail[] = "]}\n";
rv = PR_Write(logFile, threadTail, sizeof(threadTail) - 1);
ioError |= (rv < 0);
RecordBatch * next = batch->mNextBatch;
delete batch;
batch = next;
}
}
const char logTail[] = "]}\n";
rv = PR_Write(logFile, logTail, sizeof(logTail) - 1);
ioError |= (rv < 0);
PR_Close(logFile);
if (ioError)
PR_Delete(gLogFilePath);
}
// static
bool CheckEventFilters(PRUint32 aType, void * aItem, const char * aText)
{
if (!gEventFilter)
return true;
if (aType == eName)
return true;
if (aItem == gFlushingThread) // Pass events coming from the tracer
return true;
return gEventFilter->EventPasses(aText);
}
} // anon namespace
#endif //MOZ_VISUAL_EVENT_TRACER
// static
void Init()
{
#ifdef MOZ_VISUAL_EVENT_TRACER
const char * logFile = PR_GetEnv("MOZ_PROFILING_FILE");
if (!logFile || !*logFile)
return;
gLogFilePath = logFile;
const char * logEvents = PR_GetEnv("MOZ_PROFILING_EVENTS");
if (logEvents && *logEvents)
gEventFilter = EventFilter::Build(logEvents);
gProfilerStart = mozilla::TimeStamp::Now();
PRStatus status = PR_NewThreadPrivateIndex(&gThreadPrivateIndex,
&RecordBatch::FlushBatch);
if (status != PR_SUCCESS)
return;
gMonitor = new mozilla::Monitor("Profiler");
if (!gMonitor)
return;
gFlushingThread = PR_CreateThread(PR_USER_THREAD,
&FlushingThread,
nsnull,
PR_PRIORITY_LOW,
PR_LOCAL_THREAD,
PR_JOINABLE_THREAD,
32768);
if (!gFlushingThread)
return;
gInitialized = true;
MOZ_EVENT_TRACER_NAME_OBJECT(gFlushingThread, "Profiler");
MOZ_EVENT_TRACER_MARK(gFlushingThread, "Profiling Start");
#endif
}
// static
void Shutdown()
{
#ifdef MOZ_VISUAL_EVENT_TRACER
MOZ_EVENT_TRACER_MARK(gFlushingThread, "Profiling End");
// This must be called after all other threads had been shut down
// (i.e. their private data had been 'released').
// Release the private data of this thread to flush all the remaning writes.
PR_SetThreadPrivate(gThreadPrivateIndex, nsnull);
if (gFlushingThread) {
{
MonitorAutoLock mon(*gMonitor);
gInitialized = false;
gStopFlushingThread = true;
mon.Notify();
}
PR_JoinThread(gFlushingThread);
gFlushingThread = nsnull;
}
if (gMonitor) {
delete gMonitor;
gMonitor = nsnull;
}
if (gEventFilter) {
delete gEventFilter;
gEventFilter = nsnull;
}
#endif
}
// static
void Mark(PRUint32 aType, void * aItem, const char * aText, const char * aText2)
{
#ifdef MOZ_VISUAL_EVENT_TRACER
if (!gInitialized)
return;
if (aType == eNone)
return;
if (!CheckEventFilters(aType, aItem, aText)) // Events use just aText
return;
RecordBatch * threadLogPrivate = static_cast<RecordBatch *>(
PR_GetThreadPrivate(gThreadPrivateIndex));
if (!threadLogPrivate) {
// Deletion is made by the flushing thread
threadLogPrivate = new RecordBatch();
PR_SetThreadPrivate(gThreadPrivateIndex, threadLogPrivate);
}
Record * record = threadLogPrivate->mNextRecord;
record->mType = aType;
record->mTime = (mozilla::TimeStamp::Now() - gProfilerStart).ToMilliseconds();
record->mItem = aItem;
record->mText = PL_strdup(aText);
record->mText2 = aText2 ? PL_strdup(aText2) : nsnull;
++threadLogPrivate->mNextRecord;
if (threadLogPrivate->mNextRecord == threadLogPrivate->mRecordsTail) {
// This calls RecordBatch::FlushBatch(threadLogPrivate)
PR_SetThreadPrivate(gThreadPrivateIndex, nsnull);
}
#endif
}
} // eventtracer
} // mozilla

View File

@ -0,0 +1,240 @@
/* ***** 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/
*
* Software distributed under the License is distributed on an "AS IS" basis,
* WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
* for the specific language governing rights and limitations under the
* License.
*
* The Original Code is Mozilla code.
*
* The Initial Developer of the Original Code is
* Mozilla Foundation.
* Portions created by the Initial Developer are Copyright (C) 2012
* the Initial Developer. All Rights Reserved.
*
* Contributor(s):
* Honza Bambas <honzab.moz@firemni.cz>
*
* 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
* decision by deleting the provisions above and replace them with the notice
* and other provisions required by the GPL or the LGPL. If you do not delete
* the provisions above, a recipient may use your version of this file under
* the terms of any one of the MPL, the GPL or the LGPL.
*
* ***** END LICENSE BLOCK ***** */
/* Visual event tracer, creates a log of events on each thread for visualization */
/**
* The event tracer code is by default disabled in both build and run time.
*
* To enable this code at build time, add --enable-visual-profiling to your
* configure options.
*
* To enable this code at run time, export MOZ_PROFILING_FILE env var with
* a path to the file to write the log to. This is all you need to produce
* the log of all events instrumentation in the mozilla code.
* Check MOZ_EVENT_TRACER_* macros bellow to add your own.
*
* To let the event tracer log only some events to save disk space, export
* MOZ_PROFILING_EVENTS with comma separated list of event names you want
* to record in the log.
*/
#include "prlock.h"
#include "nscore.h"
#include "mozilla/GuardObjects.h"
#ifdef MOZ_VISUAL_EVENT_TRACER
// Bind an object instance, usually |this|, to a name, usually URL or
// host name, the instance deals with for its lifetime. The name string
// is duplicated.
// IMPORTANT: it is up to the caller to pass the correct static_cast
// of the |instance| pointer to all these macros ; otherwise the linking
// of events and objects will not work!
// The name will show in details of the events on the timeline and also
// will allow events filtering by host names, URLs etc.
#define MOZ_EVENT_TRACER_NAME_OBJECT(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eName, instance, name)
// The same as MOZ_EVENT_TRACER_NAME_OBJECT, just simplifies building
// names when it consists of two parts
#define MOZ_EVENT_TRACER_COMPOUND_NAME(instance, name, name2) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eName, instance, name, name2)
// Call the followings with the same |instance| reference as you have
// previously called MOZ_EVENT_TRACER_NAME_OBJECT.
// Let |name| be the name of the event happening, like "resolving",
// "connecting", "loading" etc.
// This will crate a single-point-in-time event marked with an arrow
// on the timeline, this is a way to indicate an event without a duration.
#define MOZ_EVENT_TRACER_MARK(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eShot, instance, name)
// Following macros are used to log events with duration.
// There always has to be complete WAIT,EXEC,DONE or EXEC,DONE
// uninterrupted and non-interferring tuple(s) for an event to be correctly
// shown on the timeline. Each can be called on any thread, the event tape is
// finally displayed on the thread where it has been EXECuted.
// Example of 3 phases usage for "HTTP request channel":
// WAIT: we've just created the channel and called AsyncOpen on it
// EXEC: we've just got first call to OnDataAvailable, so we are actually
// receiving the content after some time like connection establising,
// opening a cache entry, sending the GET request...
// DONE: we've just got OnStopRequest call that indicates the content
// has been completely delivered and the request is now finished
// Indicate an event pending start, on the timeline this will
// start the event's interval tape with a pale color, the time will
// show in details. Usually used when an event is being posted or
// we wait for a lock acquisition.
// WAITING is not mandatory, some events don't have a pending phase.
#define MOZ_EVENT_TRACER_WAIT(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eWait, instance, name)
// Indicate start of an event actual execution, on the timeline this will
// change the event's tape to a deeper color, the time will show in details.
#define MOZ_EVENT_TRACER_EXEC(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eExec, instance, name)
// Indicate the end of an event execution (the event has been done),
// on the timeline this will end the event's tape and show the time in
// event details.
// NOTE: when the event duration is extremely short, like 1ms, it will convert
// to an event w/o a duration - the same as MOZ_EVENT_TRACER_MARK would be used.
#define MOZ_EVENT_TRACER_DONE(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eDone, instance, name)
// The same meaning as the above macros, just for concurent events.
// Concurent event means it can happen for the same instance on more
// then just a single thread, e.g. a service method call, a global lock
// acquisition, enter and release.
#define MOZ_EVENT_TRACER_WAIT_THREADSAFE(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eWait | mozilla::eventtracer::eThreadConcurrent, instance, name)
#define MOZ_EVENT_TRACER_EXEC_THREADSAFE(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eExec | mozilla::eventtracer::eThreadConcurrent, instance, name)
#define MOZ_EVENT_TRACER_DONE_THREASAFE(instance, name) \
mozilla::eventtracer::Mark(mozilla::eventtracer::eDone | mozilla::eventtracer::eThreadConcurrent, instance, name)
#else
// MOZ_VISUAL_EVENT_TRACER disabled
#define MOZ_EVENT_TRACER_NAME_OBJECT(instance, name) (void)0
#define MOZ_EVENT_TRACER_COMPOUND_NAME(instance, name, name2) (void)0
#define MOZ_EVENT_TRACER_MARK(instance, name) (void)0
#define MOZ_EVENT_TRACER_WAIT(instance, name) (void)0
#define MOZ_EVENT_TRACER_EXEC(instance, name) (void)0
#define MOZ_EVENT_TRACER_DONE(instance, name) (void)0
#define MOZ_EVENT_TRACER_WAIT_THREADSAFE(instance, name) (void)0
#define MOZ_EVENT_TRACER_EXEC_THREADSAFE(instance, name) (void)0
#define MOZ_EVENT_TRACER_DONE_THREASAFE(instance, name) (void)0
#endif
namespace mozilla { namespace eventtracer {
// Initialize the event tracer engine, called automatically on XPCOM startup.
void Init();
// Shuts the event tracer engine down and closes the log file, called
// automatically during XPCOM shutdown.
void Shutdown();
enum MarkType {
eNone, // No operation, ignored
eName, // This is used to bind an object instance with a name
eShot, // An event with no duration
eWait, // Start of waiting for execution (lock acquire, post...)
eExec, // Start of the execution it self
eDone, // End of the execution
eLast, // Sentinel
// Flags
// The same object can execute the same event on several threads concurently
eThreadConcurrent = 0x10000
};
// Records an event on the calling thread.
// @param aType
// One of MarkType fields, can be bitwise or'ed with the flags.
// @param aItem
// Reference to the object we want to bind a name to or the event is
// happening on. Can be actually anything, but valid poitners should
// be used.
// @param aText
// Text of the name (for eName) or event's name for others. The string
// is duplicated.
// @param aText2
// Optional second part of the instnace name, or event name.
// Event filtering does apply only to the first part (aText).
void Mark(PRUint32 aType, void * aItem,
const char * aText, const char * aText2 = 0);
// Helper guard object. Use to mark an event in the constructor and a different
// event in the destructor.
//
// Example:
// int class::func()
// {
// AutoEventTracer tracer(this, eventtracer::eExec, eventtracer::eDone, "func");
//
// do_something_taking_a_long_time();
// }
class NS_STACK_CLASS AutoEventTracer
{
public:
AutoEventTracer(void * aInstance,
PRUint32 aTypeOn, // MarkType marked in constructor
PRUint32 aTypeOff, // MarkType marked in destructor
const char * aName,
const char * aName2 = 0
MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
: mInstance(aInstance)
, mTypeOn(aTypeOn)
, mTypeOff(aTypeOff)
, mName(aName)
, mName2(aName2)
{
MOZ_GUARD_OBJECT_NOTIFIER_INIT;
::mozilla::eventtracer::Mark(mTypeOn, mInstance, mName, mName2);
}
~AutoEventTracer()
{
::mozilla::eventtracer::Mark(mTypeOff, mInstance, mName, mName2);
}
private:
void * mInstance;
const char * mName;
const char * mName2;
PRUint32 mTypeOn;
PRUint32 mTypeOff;
MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER
};
} // eventtracer
} // mozilla

View File

@ -118,6 +118,8 @@ extern nsresult nsStringInputStreamConstructor(nsISupports *, REFNSIID, void **)
#include "mozilla/AvailableMemoryTracker.h"
#include "mozilla/ClearOnShutdown.h"
#include "mozilla/VisualEventTracer.h"
using base::AtExitManager;
using mozilla::ipc::BrowserProcessSubThread;
@ -507,6 +509,8 @@ NS_InitXPCOM2(nsIServiceManager* *result,
mozilla::Telemetry::Init();
mozilla::eventtracer::Init();
return NS_OK;
}
@ -719,6 +723,8 @@ ShutdownXPCOM(nsIServiceManager* servMgr)
HangMonitor::Shutdown();
eventtracer::Shutdown();
NS_LogTerm();
return NS_OK;