/* 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 * data); // 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 * data) { RecordBatch * batch = static_cast(data); 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 * 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 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 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 & _retval) { nsCString buffer; buffer.Assign(NS_LITERAL_CSTRING("{\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.Append(NS_LITERAL_CSTRING(",\n")); } buffer.Append(NS_LITERAL_CSTRING("{\"thread\":\"")); buffer.Append(batch->mThreadNameCopy); buffer.Append(NS_LITERAL_CSTRING("\",\"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.Append(NS_LITERAL_CSTRING("]}\n")); RecordBatch * next = batch->mNextBatch; batch = next; } buffer.Append(NS_LITERAL_CSTRING("]}\n")); _retval.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 ** _result) { if (!gInitialized) return NS_ERROR_UNEXPECTED; RecordBatch * batch = RecordBatch::CloneLog(); nsRefPtr log = new VisualEventTracerLog(batch); log.forget(_result); return NS_OK; } #endif } // eventtracer } // mozilla