The Tor Browser / file revision

 /* 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<RecordBatch*>(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<RecordBatch *>(

       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<uint64_t>((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<nsIVisualEventTracerLog> 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<VisualEventTracerLog> log = new VisualEventTracerLog(batch);

   log.forget(_result);

   return NS_OK;

 }

 #endif

 } // eventtracer

 } // mozilla