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