gecko/xpcom/base/VisualEventTracer.cpp

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