2012-06-13 15:35:31 +00:00
|
|
|
/* This Source Code Form is subject to the terms of the Mozilla Public
|
|
|
|
* License, v. 2.0. If a copy of the MPL was not distributed with this
|
|
|
|
* file, You can obtain one at http://mozilla.org/MPL/2.0/. */
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
#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"
|
2012-07-11 18:20:17 +00:00
|
|
|
#include "plstr.h"
|
|
|
|
#include "nsThreadUtils.h"
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
namespace mozilla { namespace eventtracer {
|
|
|
|
|
|
|
|
#ifdef MOZ_VISUAL_EVENT_TRACER
|
|
|
|
|
|
|
|
namespace {
|
|
|
|
|
2012-08-22 15:56:38 +00:00
|
|
|
const uint32_t kBatchSize = 0x1000;
|
2012-06-12 17:06:21 +00:00
|
|
|
const char kTypeChars[eventtracer::eLast] = {' ','N','S','W','E','D'};
|
|
|
|
|
|
|
|
// Flushing thread and records queue monitor
|
2012-07-30 14:20:58 +00:00
|
|
|
mozilla::Monitor * gMonitor = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
// 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)
|
2012-07-30 14:20:58 +00:00
|
|
|
, mItem(nullptr)
|
|
|
|
, mText(nullptr)
|
|
|
|
, mText2(nullptr)
|
2012-06-12 17:06:21 +00:00
|
|
|
{
|
|
|
|
MOZ_COUNT_CTOR(Record);
|
|
|
|
}
|
|
|
|
~Record()
|
|
|
|
{
|
|
|
|
PL_strfree(mText);
|
|
|
|
PL_strfree(mText2);
|
|
|
|
MOZ_COUNT_DTOR(Record);
|
|
|
|
}
|
|
|
|
|
2012-08-22 15:56:38 +00:00
|
|
|
uint32_t mType;
|
2012-06-12 17:06:21 +00:00
|
|
|
double mTime;
|
|
|
|
void * mItem;
|
|
|
|
char * mText;
|
|
|
|
char * mText2;
|
|
|
|
};
|
|
|
|
|
2012-07-11 18:20:17 +00:00
|
|
|
char * DupCurrentThreadName()
|
|
|
|
{
|
|
|
|
if (NS_IsMainThread())
|
|
|
|
return PL_strdup("Main Thread");
|
|
|
|
|
|
|
|
PRThread * currentThread = PR_GetCurrentThread();
|
|
|
|
const char * name = PR_GetThreadName(currentThread);
|
|
|
|
if (name)
|
|
|
|
return PL_strdup(name);
|
|
|
|
|
|
|
|
char buffer[128];
|
|
|
|
PR_snprintf(buffer, 127, "Nameless %p", currentThread);
|
|
|
|
|
|
|
|
return PL_strdup(buffer);
|
|
|
|
}
|
|
|
|
|
2012-06-12 17:06:21 +00:00
|
|
|
// An array of events, each thread keeps its own private instance
|
|
|
|
class RecordBatch {
|
|
|
|
public:
|
|
|
|
RecordBatch()
|
|
|
|
: mRecordsHead(new Record[kBatchSize])
|
|
|
|
, mRecordsTail(mRecordsHead + kBatchSize)
|
|
|
|
, mNextRecord(mRecordsHead)
|
2012-07-30 14:20:58 +00:00
|
|
|
, mNextBatch(nullptr)
|
2012-07-11 18:20:17 +00:00
|
|
|
, mThreadNameCopy(DupCurrentThreadName())
|
2012-06-12 17:06:21 +00:00
|
|
|
{
|
|
|
|
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
|
2012-07-30 14:20:58 +00:00
|
|
|
RecordBatch * gLogHead = nullptr;
|
|
|
|
RecordBatch * gLogTail = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
// 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)
|
2012-07-30 14:20:58 +00:00
|
|
|
return nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
// Reads a comma serpatated list of events.
|
|
|
|
|
|
|
|
// Copied from nspr logging code (read of NSPR_LOG_MODULES)
|
|
|
|
char eventName[64];
|
2012-08-09 07:09:40 +00:00
|
|
|
int evlen = strlen(filterVar), pos = 0, count, delta = 0;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
// 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)
|
2012-07-30 14:20:58 +00:00
|
|
|
return nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
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.
|
2012-07-30 14:20:58 +00:00
|
|
|
EventFilter * gEventFilter = nullptr;
|
|
|
|
const char * gLogFilePath = nullptr;
|
|
|
|
PRThread * gFlushingThread = nullptr;
|
2012-08-22 15:56:38 +00:00
|
|
|
unsigned gThreadPrivateIndex;
|
2012-06-12 17:06:21 +00:00
|
|
|
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;
|
|
|
|
}
|
|
|
|
|
2012-08-22 15:56:38 +00:00
|
|
|
int32_t rv;
|
2012-06-12 17:06:21 +00:00
|
|
|
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;
|
2012-07-30 14:20:58 +00:00
|
|
|
gLogHead = nullptr;
|
|
|
|
gLogTail = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
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;
|
|
|
|
|
2012-08-09 07:09:40 +00:00
|
|
|
static const int kBufferSize = 2048;
|
2012-06-12 17:06:21 +00:00
|
|
|
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.
|
2012-08-22 15:56:38 +00:00
|
|
|
uint32_t type = record->mType & 0xffffUL;
|
|
|
|
uint32_t flags = record->mType >> 16;
|
2012-06-12 17:06:21 +00:00
|
|
|
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
|
2012-08-22 15:56:38 +00:00
|
|
|
bool CheckEventFilters(uint32_t aType, void * aItem, const char * aText)
|
2012-06-12 17:06:21 +00:00
|
|
|
{
|
|
|
|
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,
|
2012-07-30 14:20:58 +00:00
|
|
|
nullptr,
|
2012-06-12 17:06:21 +00:00
|
|
|
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.
|
2012-07-30 14:20:58 +00:00
|
|
|
PR_SetThreadPrivate(gThreadPrivateIndex, nullptr);
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
if (gFlushingThread) {
|
|
|
|
{
|
|
|
|
MonitorAutoLock mon(*gMonitor);
|
|
|
|
gInitialized = false;
|
|
|
|
gStopFlushingThread = true;
|
|
|
|
mon.Notify();
|
|
|
|
}
|
|
|
|
|
|
|
|
PR_JoinThread(gFlushingThread);
|
2012-07-30 14:20:58 +00:00
|
|
|
gFlushingThread = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if (gMonitor) {
|
|
|
|
delete gMonitor;
|
2012-07-30 14:20:58 +00:00
|
|
|
gMonitor = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if (gEventFilter) {
|
|
|
|
delete gEventFilter;
|
2012-07-30 14:20:58 +00:00
|
|
|
gEventFilter = nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
}
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
// static
|
2012-08-22 15:56:38 +00:00
|
|
|
void Mark(uint32_t aType, void * aItem, const char * aText, const char * aText2)
|
2012-06-12 17:06:21 +00:00
|
|
|
{
|
|
|
|
#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);
|
2012-07-30 14:20:58 +00:00
|
|
|
record->mText2 = aText2 ? PL_strdup(aText2) : nullptr;
|
2012-06-12 17:06:21 +00:00
|
|
|
|
|
|
|
++threadLogPrivate->mNextRecord;
|
|
|
|
if (threadLogPrivate->mNextRecord == threadLogPrivate->mRecordsTail) {
|
|
|
|
// This calls RecordBatch::FlushBatch(threadLogPrivate)
|
2012-07-30 14:20:58 +00:00
|
|
|
PR_SetThreadPrivate(gThreadPrivateIndex, nullptr);
|
2012-06-12 17:06:21 +00:00
|
|
|
}
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
|
|
|
} // eventtracer
|
|
|
|
} // mozilla
|