Bug 1287392 - Part 8: Improve performance of logging of TaskTracer. r=cyu
authorThinker K.F. Li <thinker@codemud.net>
Tue, 22 Nov 2016 00:15:00 +0800
changeset 323920 df33b1b46ef3d0626361f6e8191ba0c0a29db64f
parent 323919 48d6e51b95ea59d4ee1e4e091c12ee2cef27b40a
child 323921 1d2850876b6359ab35600dec69180c67c0d22abf
push id24
push usermaklebus@msu.edu
push dateTue, 20 Dec 2016 03:11:33 +0000
reviewerscyu
bugs1287392
milestone53.0a1
Bug 1287392 - Part 8: Improve performance of logging of TaskTracer. r=cyu
tools/profiler/tasktracer/GeckoTaskTracer.cpp
tools/profiler/tasktracer/GeckoTaskTracerImpl.h
--- a/tools/profiler/tasktracer/GeckoTaskTracer.cpp
+++ b/tools/profiler/tasktracer/GeckoTaskTracer.cpp
@@ -146,30 +146,32 @@ ObsoleteCurrentTraceInfos()
   // function is called before the other threads are recreated.
   for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) {
     (*sTraceInfos)[i]->mObsolete = true;
   }
 }
 
 } // namespace anonymous
 
-nsCString*
+TraceInfoLogType*
 TraceInfo::AppendLog()
 {
-  if (mLogs.Length() >= MAX_SIZE_LOG) {
+  if (mLogsSize >= MAX_SIZE_LOG) {
     return nullptr;
   }
-  return mLogs.AppendElement();
-}
-
-void
-TraceInfo::MoveLogsInto(TraceInfoLogsType& aResult)
-{
-  MutexAutoLock lock(mLogsMutex);
-  aResult.AppendElements(Move(mLogs));
+  TraceInfoLogNode* node = new TraceInfoLogNode;
+  node->mNext = nullptr;
+  if (mLogsTail) {
+    mLogsTail->mNext = node;
+    mLogsTail = node;
+  } else {
+    mLogsTail = mLogsHead = node;
+  }
+  mLogsSize++;
+  return &node->mLog;
 }
 
 void
 InitTaskTracer(uint32_t aFlags)
 {
   StaticMutexAutoLock lock(sMutex);
 
   if (aFlags & FORKED_AFTER_NUWA) {
@@ -292,70 +294,80 @@ LogDispatch(uint64_t aTaskId, uint64_t a
   // aDelayTimeMs is the expected delay time in milliseconds, thus the dispatch
   // time calculated of it might be slightly off in the real world.
   uint64_t time = (aDelayTimeMs <= 0) ? GetTimestamp() :
                   GetTimestamp() + aDelayTimeMs;
 
   MutexAutoLock lock(info->mLogsMutex);
   // Log format:
   // [0 taskId dispatchTime sourceEventId sourceEventType parentTaskId]
-  nsCString* log = info->AppendLog();
+  TraceInfoLogType* log = info->AppendLog();
   if (log) {
-    log->AppendPrintf("%d %lld %lld %lld %d %lld",
-                      ACTION_DISPATCH, aTaskId, time, aSourceEventId,
-                      aSourceEventType, aParentTaskId);
+    log->mDispatch.mType = ACTION_DISPATCH;
+    log->mDispatch.mTaskId = aTaskId;
+    log->mDispatch.mTime = time;
+    log->mDispatch.mSourceEventId = aSourceEventId;
+    log->mDispatch.mSourceEventType = aSourceEventType;
+    log->mDispatch.mParentTaskId = aParentTaskId;
   }
 }
 
 void
 LogBegin(uint64_t aTaskId, uint64_t aSourceEventId)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   ENSURE_TRUE_VOID(info);
 
   MutexAutoLock lock(info->mLogsMutex);
   // Log format:
   // [1 taskId beginTime processId threadId]
-  nsCString* log = info->AppendLog();
+  TraceInfoLogType* log = info->AppendLog();
   if (log) {
-    log->AppendPrintf("%d %lld %lld %d %d",
-                      ACTION_BEGIN, aTaskId, GetTimestamp(), getpid(), gettid());
+    log->mBegin.mType = ACTION_BEGIN;
+    log->mBegin.mTaskId = aTaskId;
+    log->mBegin.mTime = GetTimestamp();
+    log->mBegin.mPid = getpid();
+    log->mBegin.mTid = gettid();
   }
 }
 
 void
 LogEnd(uint64_t aTaskId, uint64_t aSourceEventId)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   ENSURE_TRUE_VOID(info);
 
   MutexAutoLock lock(info->mLogsMutex);
   // Log format:
   // [2 taskId endTime]
-  nsCString* log = info->AppendLog();
+  TraceInfoLogType* log = info->AppendLog();
   if (log) {
-    log->AppendPrintf("%d %lld %lld", ACTION_END, aTaskId, GetTimestamp());
+    log->mEnd.mType = ACTION_END;
+    log->mEnd.mTaskId = aTaskId;
+    log->mEnd.mTime = GetTimestamp();
   }
 }
 
 void
 LogVirtualTablePtr(uint64_t aTaskId, uint64_t aSourceEventId, uintptr_t* aVptr)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   ENSURE_TRUE_VOID(info);
 
   MutexAutoLock lock(info->mLogsMutex);
   // Log format:
   // [4 taskId address]
-  nsCString* log = info->AppendLog();
+  TraceInfoLogType* log = info->AppendLog();
   if (log) {
     // Since addr2line used by SPS addon can not solve non-function
     // addresses, we use the first entry of vtable as the symbol to
     // solve.  We should find a better solution later.
-    log->AppendPrintf("%d %lld %p", ACTION_GET_VTABLE, aTaskId, aVptr);
+    log->mVPtr.mType = ACTION_GET_VTABLE;
+    log->mVPtr.mTaskId = aTaskId;
+    log->mVPtr.mVPtr = reinterpret_cast<uintptr_t>(aVptr);
   }
 }
 
 AutoSourceEvent::AutoSourceEvent(SourceEventType aType)
   : AutoSaveCurTraceInfo()
 {
   CreateSourceEvent(aType);
 }
@@ -365,29 +377,31 @@ AutoSourceEvent::~AutoSourceEvent()
   DestroySourceEvent();
 }
 
 void AddLabel(const char* aFormat, ...)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   ENSURE_TRUE_VOID(info);
 
-  va_list args;
-  va_start(args, aFormat);
-  nsAutoCString buffer;
-  buffer.AppendPrintf(aFormat, args);
-  va_end(args);
-
   MutexAutoLock lock(info->mLogsMutex);
   // Log format:
   // [3 taskId "label"]
-  nsCString* log = info->AppendLog();
+  TraceInfoLogType* log = info->AppendLog();
   if (log) {
-    log->AppendPrintf("%d %lld %lld \"%s\"", ACTION_ADD_LABEL, info->mCurTaskId,
-                      GetTimestamp(), buffer.get());
+    va_list args;
+    va_start(args, aFormat);
+    nsCString &buffer = *info->mStrs.AppendElement();
+    buffer.AppendPrintf(aFormat, args);
+    va_end(args);
+
+    log->mLabel.mType = ACTION_ADD_LABEL;
+    log->mLabel.mTaskId = info->mCurTaskId;
+    log->mLabel.mTime = GetTimestamp();
+    log->mLabel.mStrIdx = info->mStrs.Length() - 1;
   }
 }
 
 // Functions used by GeckoProfiler.
 
 void
 StartLogging()
 {
@@ -396,27 +410,74 @@ StartLogging()
 }
 
 void
 StopLogging()
 {
   SetLogStarted(false);
 }
 
-UniquePtr<TraceInfoLogsType>
+UniquePtr<nsTArray<nsCString>>
 GetLoggedData(TimeStamp aTimeStamp)
 {
-  auto result = MakeUnique<TraceInfoLogsType>();
+  auto result = MakeUnique<nsTArray<nsCString>>();
 
   // TODO: This is called from a signal handler. Use semaphore instead.
   StaticMutexAutoLock lock(sMutex);
 
   for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) {
-    if (!(*sTraceInfos)[i]->mObsolete) {
-      (*sTraceInfos)[i]->MoveLogsInto(*result);
+    TraceInfo* info = (*sTraceInfos)[i].get();
+    MutexAutoLock lockLogs(info->mLogsMutex);
+    if (info->mObsolete) {
+      continue;
+    }
+
+    nsTArray<nsCString> &strs = info->mStrs;
+    for (TraceInfoLogNode* node = info->mLogsHead; node; node = node->mNext) {
+      TraceInfoLogType &log = node->mLog;
+      nsCString &buffer = *result->AppendElement();
+
+      switch (log.mType) {
+      case ACTION_DISPATCH:
+        buffer.AppendPrintf("%d %lld %lld %lld %d %lld",
+                            ACTION_DISPATCH,
+                            log.mDispatch.mTaskId,
+                            log.mDispatch.mTime,
+                            log.mDispatch.mSourceEventId,
+                            log.mDispatch.mSourceEventType,
+                            log.mDispatch.mParentTaskId);
+        break;
+
+      case ACTION_BEGIN:
+        buffer.AppendPrintf("%d %lld %lld %d %d",
+                            ACTION_BEGIN, log.mBegin.mTaskId,
+                            log.mBegin.mTime, log.mBegin.mPid,
+                            log.mBegin.mTid);
+        break;
+
+      case ACTION_END:
+        buffer.AppendPrintf("%d %lld %lld",
+                            ACTION_END, log.mEnd.mTaskId, log.mEnd.mTime);
+        break;
+
+      case ACTION_GET_VTABLE:
+        buffer.AppendPrintf("%d %lld %p",
+                            ACTION_GET_VTABLE, log.mVPtr.mTaskId,
+                            log.mVPtr.mVPtr);
+        break;
+
+      case ACTION_ADD_LABEL:
+        buffer.AppendPrintf("%d %lld %lld \"%s\"",
+                            ACTION_ADD_LABEL, log.mLabel.mTaskId,
+                            log.mLabel.mTime, strs[log.mLabel.mStrIdx].get());
+        break;
+
+      default:
+        MOZ_CRASH("Unknow TaskTracer log type!");
+      }
     }
   }
 
   return result;
 }
 
 const PRTime
 GetStartTime()
--- a/tools/profiler/tasktracer/GeckoTaskTracerImpl.h
+++ b/tools/profiler/tasktracer/GeckoTaskTracerImpl.h
@@ -9,48 +9,107 @@
 
 #include "GeckoTaskTracer.h"
 #include "mozilla/Mutex.h"
 #include "nsTArray.h"
 
 namespace mozilla {
 namespace tasktracer {
 
-typedef nsTArray<nsCString> TraceInfoLogsType;
+struct LogRecDispatch {
+  uint32_t mType;
+  uint32_t mSourceEventType;
+  uint64_t mTaskId;
+  uint64_t mTime;
+  uint64_t mSourceEventId;
+  uint64_t mParentTaskId;
+};
+
+struct LogRecBegin {
+  uint32_t mType;
+  uint64_t mTaskId;
+  uint64_t mTime;
+  uint32_t mPid;
+  uint32_t mTid;
+};
+
+struct LogRecEnd {
+  uint32_t mType;
+  uint64_t mTaskId;
+  uint64_t mTime;
+};
+
+struct LogRecVPtr {
+  uint32_t mType;
+  uint64_t mTaskId;
+  uintptr_t mVPtr;
+};
+
+struct LogRecLabel {
+  uint32_t mType;
+  uint32_t mStrIdx;
+  uint64_t mTaskId;
+  uint64_t mTime;
+};
+
+union TraceInfoLogType {
+  uint32_t mType;
+  LogRecDispatch mDispatch;
+  LogRecBegin mBegin;
+  LogRecEnd mEnd;
+  LogRecVPtr mVPtr;
+  LogRecLabel mLabel;
+};
+
+struct TraceInfoLogNode {
+  TraceInfoLogType mLog;
+  TraceInfoLogNode* mNext;
+};
 
 struct TraceInfo
 {
   TraceInfo(uint32_t aThreadId)
     : mCurTraceSourceId(0)
     , mCurTaskId(0)
     , mCurTraceSourceType(Unknown)
     , mThreadId(aThreadId)
     , mLastUniqueTaskId(0)
     , mObsolete(false)
     , mLogsMutex("TraceInfoMutex")
+    , mLogsHead(nullptr)
+    , mLogsTail(nullptr)
+    , mLogsSize(0)
   {
     MOZ_COUNT_CTOR(TraceInfo);
   }
 
-  ~TraceInfo() { MOZ_COUNT_DTOR(TraceInfo); }
+  ~TraceInfo() {
+    MOZ_COUNT_DTOR(TraceInfo);
+    while (mLogsHead) {
+      auto node = mLogsHead;
+      mLogsHead = node->mNext;
+      delete node;
+    }
+  }
 
-  nsCString* AppendLog();
-  void MoveLogsInto(TraceInfoLogsType& aResult);
+  TraceInfoLogType* AppendLog();
 
   uint64_t mCurTraceSourceId;
   uint64_t mCurTaskId;
   SourceEventType mCurTraceSourceType;
   uint32_t mThreadId;
   uint32_t mLastUniqueTaskId;
   mozilla::Atomic<bool> mObsolete;
 
-  // This mutex protects the following log array because MoveLogsInto() might
-  // be called on another thread.
+  // This mutex protects the following log
   mozilla::Mutex mLogsMutex;
-  TraceInfoLogsType mLogs;
+  TraceInfoLogNode* mLogsHead;
+  TraceInfoLogNode* mLogsTail;
+  int mLogsSize;
+  nsTArray<nsCString> mStrs;
 };
 
 // Return the TraceInfo of current thread, allocate a new one if not exit.
 TraceInfo* GetOrCreateTraceInfo();
 
 uint64_t GenNewUniqueTaskId();
 
 void SetCurTraceInfo(uint64_t aSourceEventId, uint64_t aParentTaskId,