/* 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/. */ #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" #include "nsThreadUtils.h" namespace mozilla { namespace eventtracer { #ifdef MOZ_VISUAL_EVENT_TRACER namespace { const uint32_t kBatchSize = 0x1000; const char kTypeChars[eventtracer::eLast] = {' ','N','S','W','E','D'}; // Flushing thread and records queue monitor mozilla::Monitor * gMonitor = nullptr; // 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(nullptr) , mText(nullptr) , mText2(nullptr) { MOZ_COUNT_CTOR(Record); } ~Record() { PL_strfree(mText); PL_strfree(mText2); MOZ_COUNT_DTOR(Record); } uint32_t mType; double mTime; void * mItem; char * mText; char * mText2; }; 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); } // 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(nullptr) , mThreadNameCopy(DupCurrentThreadName()) { 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 = nullptr; RecordBatch * gLogTail = nullptr; // Registered as thread private data destructor void RecordBatch::FlushBatch(void * aData) { RecordBatch * threadLogPrivate = static_cast(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 nullptr; // Reads a comma serpatated list of events. // Copied from nspr logging code (read of NSPR_LOG_MODULES) char eventName[64]; int 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 nullptr; 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 = nullptr; const char * gLogFilePath = nullptr; PRThread * gFlushingThread = nullptr; unsigned 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; } int32_t 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 = nullptr; gLogTail = nullptr; 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 int 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. uint32_t type = record->mType & 0xffffUL; uint32_t 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(uint32_t 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, nullptr, 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, nullptr); if (gFlushingThread) { { MonitorAutoLock mon(*gMonitor); gInitialized = false; gStopFlushingThread = true; mon.Notify(); } PR_JoinThread(gFlushingThread); gFlushingThread = nullptr; } if (gMonitor) { delete gMonitor; gMonitor = nullptr; } if (gEventFilter) { delete gEventFilter; gEventFilter = nullptr; } #endif } // static void Mark(uint32_t 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( 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) : nullptr; ++threadLogPrivate->mNextRecord; if (threadLogPrivate->mNextRecord == threadLogPrivate->mRecordsTail) { // This calls RecordBatch::FlushBatch(threadLogPrivate) PR_SetThreadPrivate(gThreadPrivateIndex, nullptr); } #endif } } // eventtracer } // mozilla