/* 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 "prenv.h" #include "plstr.h" #include "nsThreadUtils.h" namespace mozilla { namespace eventtracer { #ifdef MOZ_VISUAL_EVENT_TRACER namespace { const uint32_t kBatchSize = 256; const char kTypeChars[eventtracer::eLast] = {' ', 'N', 'S', 'W', 'E', 'D'}; // Flushing thread and records queue monitor mozilla::Monitor* gMonitor = nullptr; // gInitialized and gCapture can be accessed from multiple threads // simultaneously without any locking. However, since they are only ever // *set* from the main thread, the chance of races manifesting is small // and unlikely to be a problem in practice. bool gInitialized; // Flag to allow capturing bool gCapture; // Time stamp of the epoch we have started to capture mozilla::TimeStamp* gProfilerStart; // Duration of the log to keep up to mozilla::TimeDuration* gMaxBacklogTime; // Record of a single event class Record { public: Record() : mType(::mozilla::eventtracer::eNone) , mItem(nullptr) , mText(nullptr) , mText2(nullptr) { MOZ_COUNT_CTOR(Record); } Record& operator=(const Record& aOther) { mType = aOther.mType; mTime = aOther.mTime; mItem = aOther.mItem; mText = PL_strdup(aOther.mText); mText2 = aOther.mText2 ? PL_strdup(aOther.mText2) : nullptr; return *this; } ~Record() { PL_strfree(mText2); PL_strfree(mText); MOZ_COUNT_DTOR(Record); } uint32_t mType; TimeStamp 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(size_t aLength = kBatchSize, char* aThreadName = DupCurrentThreadName()) : mRecordsHead(new Record[aLength]) , mRecordsTail(mRecordsHead + aLength) , mNextRecord(mRecordsHead) , mNextBatch(nullptr) , mThreadNameCopy(aThreadName) , mClosed(false) { MOZ_COUNT_CTOR(RecordBatch); } ~RecordBatch() { delete [] mRecordsHead; PL_strfree(mThreadNameCopy); MOZ_COUNT_DTOR(RecordBatch); } void Close() { mClosed = true; } size_t Length() const { return mNextRecord - mRecordsHead; } bool CanBeDeleted(const TimeStamp& aUntil) const; static RecordBatch* Register(); static void Close(void* aData); // Registered on freeing thread data static RecordBatch* Clone(RecordBatch* aLog, const TimeStamp& aSince); static void Delete(RecordBatch* aLog); static RecordBatch* CloneLog(); static void GCLog(const TimeStamp& aUntil); static void DeleteLog(); Record* mRecordsHead; Record* mRecordsTail; Record* mNextRecord; RecordBatch* mNextBatch; char* mThreadNameCopy; bool mClosed; }; // Protected by gMonitor, accessed concurently // Linked list of batches threads want to flush on disk RecordBatch* gLogHead = nullptr; RecordBatch* gLogTail = nullptr; // Registers the batch in the linked list // static RecordBatch* RecordBatch::Register() { MonitorAutoLock mon(*gMonitor); if (!gInitialized) { return nullptr; } if (gLogHead) { RecordBatch::GCLog(TimeStamp::Now() - *gMaxBacklogTime); } RecordBatch* batch = new RecordBatch(); if (!gLogHead) { gLogHead = batch; } else { // gLogTail is non-null gLogTail->mNextBatch = batch; } gLogTail = batch; mon.Notify(); return batch; } void RecordBatch::Close(void* aData) { RecordBatch* batch = static_cast(aData); batch->Close(); } // static RecordBatch* RecordBatch::Clone(RecordBatch* aOther, const TimeStamp& aSince) { if (!aOther) { return nullptr; } size_t length = aOther->Length(); size_t min = 0; size_t max = length; Record* record = nullptr; // Binary search for record with time >= aSince size_t i; while (min < max) { i = (max + min) / 2; record = aOther->mRecordsHead + i; if (record->mTime >= aSince) { max = i; } else { min = i + 1; } } i = (max + min) / 2; // How many Record's to copy? size_t toCopy = length - i; if (!toCopy) { return RecordBatch::Clone(aOther->mNextBatch, aSince); } // Clone RecordBatch* clone = new RecordBatch(toCopy, PL_strdup(aOther->mThreadNameCopy)); for (; i < length; ++i) { record = aOther->mRecordsHead + i; *clone->mNextRecord = *record; ++clone->mNextRecord; } clone->mNextBatch = RecordBatch::Clone(aOther->mNextBatch, aSince); return clone; } // static void RecordBatch::Delete(RecordBatch* aLog) { while (aLog) { RecordBatch* batch = aLog; aLog = aLog->mNextBatch; delete batch; } } // static RecordBatch* RecordBatch::CloneLog() { TimeStamp startEpoch = *gProfilerStart; TimeStamp backlogEpoch = TimeStamp::Now() - *gMaxBacklogTime; TimeStamp since = (startEpoch > backlogEpoch) ? startEpoch : backlogEpoch; MonitorAutoLock mon(*gMonitor); return RecordBatch::Clone(gLogHead, since); } // static void RecordBatch::GCLog(const TimeStamp& aUntil) { // Garbage collect all unreferenced and old batches gMonitor->AssertCurrentThreadOwns(); RecordBatch* volatile* referer = &gLogHead; gLogTail = nullptr; RecordBatch* batch = *referer; while (batch) { if (batch->CanBeDeleted(aUntil)) { // The batch is completed and thus unreferenced by the thread // and the most recent record has time older then the time // we want to save records for, hence delete it. *referer = batch->mNextBatch; delete batch; batch = *referer; } else { // We walk the whole list, so this will end up filled with // the very last valid element of it. gLogTail = batch; // The current batch is active, examine the next in the list. batch = batch->mNextBatch; // When the next batch is found expired, we must extract it // from the list, shift the referer. referer = &((*referer)->mNextBatch); } } } // static void RecordBatch::DeleteLog() { RecordBatch* batch; { MonitorAutoLock mon(*gMonitor); batch = gLogHead; gLogHead = nullptr; gLogTail = nullptr; } RecordBatch::Delete(batch); } bool RecordBatch::CanBeDeleted(const TimeStamp& aUntil) const { if (mClosed) { // This flag is set when a thread releases this batch as // its private data. It happens when the list is full or // when the thread ends its job. We must not delete this // batch from memory while it's held by a thread. if (!Length()) { // There are no records, just get rid of this empty batch. return true; } if ((mNextRecord - 1)->mTime <= aUntil) { // Is the last record older then the time we demand records // for? If not, this batch has expired. return true; } } // Not all conditions to close the batch met, keep it. return false; } // Helper class for filtering events by MOZ_PROFILING_EVENTS class EventFilter { public: static EventFilter* Build(const char* aFilterVar); bool EventPasses(const char* aFilterVar); ~EventFilter() { delete mNext; PL_strfree(mFilter); MOZ_COUNT_DTOR(EventFilter); } private: EventFilter(const char* aEventName, EventFilter* aNext) : mFilter(PL_strdup(aEventName)) , mNext(aNext) { MOZ_COUNT_CTOR(EventFilter); } char* mFilter; EventFilter* mNext; }; // static EventFilter* EventFilter::Build(const char* aFilterVar) { if (!aFilterVar || !*aFilterVar) { return nullptr; } // Reads a comma serpatated list of events. // Copied from nspr logging code (read of NSPR_LOG_MODULES) char eventName[64]; int pos = 0, count, delta = 0; // Read up to a comma or EOF -> get name of an event first in the list count = sscanf(aFilterVar, "%63[^,]%n", eventName, &delta); if (count == 0) { return nullptr; } pos = delta; // Skip a comma, if present, accept spaces around it count = sscanf(aFilterVar + 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(aFilterVar + pos)); } bool EventFilter::EventPasses(const char* aEventName) { if (!strcmp(aEventName, mFilter)) { return true; } if (mNext) { return mNext->EventPasses(aEventName); } return false; } // State and control variables, initialized in Init() method, after it // immutable and read concurently. EventFilter* gEventFilter = nullptr; unsigned gThreadPrivateIndex; // static bool CheckEventFilters(uint32_t aType, void* aItem, const char* aText) { if (!gEventFilter) { return true; } if (aType == eName) { return true; } return gEventFilter->EventPasses(aText); } } // anon namespace #endif //MOZ_VISUAL_EVENT_TRACER // static void Init() { #ifdef MOZ_VISUAL_EVENT_TRACER const char* logEvents = PR_GetEnv("MOZ_PROFILING_EVENTS"); if (logEvents && *logEvents) { gEventFilter = EventFilter::Build(logEvents); } PRStatus status = PR_NewThreadPrivateIndex(&gThreadPrivateIndex, &RecordBatch::Close); if (status != PR_SUCCESS) { return; } gMonitor = new mozilla::Monitor("Profiler"); if (!gMonitor) { return; } gProfilerStart = new mozilla::TimeStamp(); gMaxBacklogTime = new mozilla::TimeDuration(); gInitialized = true; #endif } // static void Shutdown() { #ifdef MOZ_VISUAL_EVENT_TRACER gCapture = false; gInitialized = false; RecordBatch::DeleteLog(); if (gMonitor) { delete gMonitor; gMonitor = nullptr; } if (gEventFilter) { delete gEventFilter; gEventFilter = nullptr; } if (gProfilerStart) { delete gProfilerStart; gProfilerStart = nullptr; } if (gMaxBacklogTime) { delete gMaxBacklogTime; gMaxBacklogTime = nullptr; } #endif } // static void Mark(uint32_t aType, void* aItem, const char* aText, const char* aText2) { #ifdef MOZ_VISUAL_EVENT_TRACER if (!gInitialized || !gCapture) { return; } if (aType == eNone) { return; } if (!CheckEventFilters(aType, aItem, aText)) { // Events use just aText return; } RecordBatch* threadLogPrivate = static_cast( PR_GetThreadPrivate(gThreadPrivateIndex)); if (!threadLogPrivate) { threadLogPrivate = RecordBatch::Register(); if (!threadLogPrivate) { return; } PR_SetThreadPrivate(gThreadPrivateIndex, threadLogPrivate); } Record* record = threadLogPrivate->mNextRecord; record->mType = aType; record->mTime = mozilla::TimeStamp::Now(); record->mItem = aItem; record->mText = PL_strdup(aText); record->mText2 = aText2 ? PL_strdup(aText2) : nullptr; ++threadLogPrivate->mNextRecord; if (threadLogPrivate->mNextRecord == threadLogPrivate->mRecordsTail) { // Calls RecordBatch::Close(threadLogPrivate) that marks // the batch as OK to be deleted from memory when no longer needed. PR_SetThreadPrivate(gThreadPrivateIndex, nullptr); } #endif } #ifdef MOZ_VISUAL_EVENT_TRACER // The scriptable classes class VisualEventTracerLog : public nsIVisualEventTracerLog { NS_DECL_ISUPPORTS NS_DECL_NSIVISUALEVENTTRACERLOG VisualEventTracerLog(RecordBatch* aBatch) : mBatch(aBatch) , mProfilerStart(*gProfilerStart) { } virtual ~VisualEventTracerLog(); protected: RecordBatch* mBatch; TimeStamp mProfilerStart; }; NS_IMPL_ISUPPORTS(VisualEventTracerLog, nsIVisualEventTracerLog) VisualEventTracerLog::~VisualEventTracerLog() { RecordBatch::Delete(mBatch); } NS_IMETHODIMP VisualEventTracerLog::GetJSONString(nsACString& aResult) { nsCString buffer; buffer.AssignLiteral("{\n\"version\": 1,\n\"records\":[\n"); RecordBatch* batch = mBatch; while (batch) { if (batch != mBatch) { // This is not the first batch we are writting, add comma buffer.AppendLiteral(",\n"); } buffer.AppendLiteral("{\"thread\":\""); buffer.Append(batch->mThreadNameCopy); buffer.AppendLiteral("\",\"log\":[\n"); static const int kBufferSize = 2048; char buf[kBufferSize]; for (Record* record = batch->mRecordsHead; record < batch->mNextRecord; ++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\":%llu,\"f\":%d,\"i\":\"%p\",\"n\":\"%s%s\"}%s\n", kTypeChars[type], static_cast((record->mTime - mProfilerStart).ToMilliseconds()), flags, record->mItem, record->mText, record->mText2 ? record->mText2 : "", (record == batch->mNextRecord - 1) ? "" : ","); buffer.Append(buf); } buffer.AppendLiteral("]}\n"); RecordBatch* next = batch->mNextBatch; batch = next; } buffer.AppendLiteral("]}\n"); aResult.Assign(buffer); return NS_OK; } nsresult VisualEventTracerLog::WriteToProfilingFile() { const char* filename = PR_GetEnv("MOZ_TRACE_FILE"); if (!filename) { return NS_OK; } PRFileDesc* fd = PR_Open(filename, PR_WRONLY | PR_CREATE_FILE | PR_TRUNCATE, 0644); if (!fd) { return NS_ERROR_FILE_ACCESS_DENIED; } nsCString json; GetJSONString(json); int32_t bytesWritten = PR_Write(fd, json.get(), json.Length()); PR_Close(fd); if (bytesWritten < json.Length()) { return NS_ERROR_UNEXPECTED; } return NS_OK; } NS_IMPL_ISUPPORTS(VisualEventTracer, nsIVisualEventTracer) NS_IMETHODIMP VisualEventTracer::Start(const uint32_t aMaxBacklogSeconds) { if (!gInitialized) { return NS_ERROR_UNEXPECTED; } if (gCapture) { NS_WARNING("VisualEventTracer has already been started"); return NS_ERROR_ALREADY_INITIALIZED; } *gMaxBacklogTime = TimeDuration::FromMilliseconds(aMaxBacklogSeconds * 1000); *gProfilerStart = mozilla::TimeStamp::Now(); { MonitorAutoLock mon(*gMonitor); RecordBatch::GCLog(*gProfilerStart); } gCapture = true; MOZ_EVENT_TRACER_MARK(this, "trace::start"); return NS_OK; } NS_IMETHODIMP VisualEventTracer::Stop() { if (!gInitialized) { return NS_ERROR_UNEXPECTED; } if (!gCapture) { NS_WARNING("VisualEventTracer is not runing"); return NS_ERROR_NOT_INITIALIZED; } MOZ_EVENT_TRACER_MARK(this, "trace::stop"); gCapture = false; nsresult rv = NS_OK; if (PR_GetEnv("MOZ_TRACE_FILE")) { nsCOMPtr tracelog; rv = Snapshot(getter_AddRefs(tracelog)); if (NS_SUCCEEDED(rv)) { rv = tracelog->WriteToProfilingFile(); } } return rv; } NS_IMETHODIMP VisualEventTracer::Snapshot(nsIVisualEventTracerLog** aResult) { if (!gInitialized) { return NS_ERROR_UNEXPECTED; } RecordBatch* batch = RecordBatch::CloneLog(); nsRefPtr log = new VisualEventTracerLog(batch); log.forget(aResult); return NS_OK; } #endif } // eventtracer } // mozilla