gecko/xpcom/base/VisualEventTracer.cpp

/* ***** BEGIN LICENSE BLOCK *****
 * Version: MPL 1.1/GPL 2.0/LGPL 2.1
 *
 * The contents of this file are subject to the Mozilla Public License Version
 * 1.1 (the "License"); you may not use this file except in compliance with
 * the License. You may obtain a copy of the License at
 * http://www.mozilla.org/MPL/
 *
 * Software distributed under the License is distributed on an "AS IS" basis,
 * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
 * for the specific language governing rights and limitations under the
 * License.
 *
 * The Original Code is Mozilla code.
 *
 * The Initial Developer of the Original Code is
 * Mozilla Foundation.
 * Portions created by the Initial Developer are Copyright (C) 2012
 * the Initial Developer. All Rights Reserved.
 *
 * Contributor(s):
 *   Honza Bambas <honzab.moz@firemni.cz>
 *
 * Alternatively, the contents of this file may be used under the terms of
 * either the GNU General Public License Version 2 or later (the "GPL"), or
 * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
 * in which case the provisions of the GPL or the LGPL are applicable instead
 * of those above. If you wish to allow use of your version of this file only
 * under the terms of either the GPL or the LGPL, and not to allow others to
 * use your version of this file under the terms of the MPL, indicate your
 * decision by deleting the provisions above and replace them with the notice
 * and other provisions required by the GPL or the LGPL. If you do not delete
 * the provisions above, a recipient may use your version of this file under
 * the terms of any one of the MPL, the GPL or the LGPL.
 *
 * ***** END LICENSE BLOCK ***** */

#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"  

namespace mozilla { namespace eventtracer {

#ifdef MOZ_VISUAL_EVENT_TRACER

namespace {

const PRUint32 kBatchSize = 0x1000;
const char kTypeChars[eventtracer::eLast] = {' ','N','S','W','E','D'};

// Flushing thread and records queue monitor
mozilla::Monitor * gMonitor = nsnull;

// 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(nsnull)
    , mText(nsnull)
    , mText2(nsnull) 
  {
    MOZ_COUNT_CTOR(Record);
  } 
  ~Record() 
  {
    PL_strfree(mText); 
    PL_strfree(mText2);
    MOZ_COUNT_DTOR(Record);
  }

  PRUint32 mType;
  double mTime;
  void * mItem;
  char * mText;
  char * mText2;
};

// 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(nsnull)
    , mThreadNameCopy(PL_strdup(PR_GetThreadName(PR_GetCurrentThread())))
  {
    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 = nsnull;
RecordBatch * gLogTail = nsnull;

// 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 nsnull;

  // Reads a comma serpatated list of events.

  // Copied from nspr logging code (read of NSPR_LOG_MODULES)
  char eventName[64];
  PRIntn 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 nsnull;

  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 = nsnull;
const char * gLogFilePath = nsnull;
PRThread * gFlushingThread = nsnull;
PRUintn 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;
  }

  PRInt32 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 = nsnull;
    gLogTail = nsnull;

    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 PRIntn 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.
        PRUint32 type = record->mType & 0xffffUL;
        PRUint32 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(PRUint32 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,
                                    nsnull,
                                    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, nsnull);

  if (gFlushingThread) {
    {
      MonitorAutoLock mon(*gMonitor);
      gInitialized = false;
      gStopFlushingThread = true;
      mon.Notify();
    }

    PR_JoinThread(gFlushingThread);
    gFlushingThread = nsnull;
  }

  if (gMonitor) {
    delete gMonitor;
    gMonitor = nsnull;
  }

  if (gEventFilter) {
    delete gEventFilter;
    gEventFilter = nsnull;
  }
#endif
}

// static 
void Mark(PRUint32 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) : nsnull;

  ++threadLogPrivate->mNextRecord;
  if (threadLogPrivate->mNextRecord == threadLogPrivate->mRecordsTail) {
    // This calls RecordBatch::FlushBatch(threadLogPrivate)
    PR_SetThreadPrivate(gThreadPrivateIndex, nsnull);
  }
#endif
}

} // eventtracer
} // mozilla