Bug 992454 - Part 1: Log TaskTracer data into string buffers and bug fixes. r=khuey.

dom/ipc/ContentChild.cpp

@@ -515,6 +515,15 @@ InitOnContentProcessCreated()
     mozilla::dom::time::InitializeDateCacheCleaner();
 }
 
+#if defined(MOZ_TASK_TRACER) && defined(MOZ_NUWA_PROCESS)
+static void
+ReinitTaskTracer(void* /*aUnused*/)
+{
+    mozilla::tasktracer::InitTaskTracer(
+        mozilla::tasktracer::FORKED_AFTER_NUWA);
+}
+#endif
+
 ContentChild::ContentChild()
  : mID(uint64_t(-1))
 #ifdef ANDROID
@@ -594,6 +603,12 @@ ContentChild::Init(MessageLoop* aIOLoop,
     SendGetProcessAttributes(&mID, &mIsForApp, &mIsForBrowser);
     InitProcessAttributes();
 
+#if defined(MOZ_TASK_TRACER) && defined (MOZ_NUWA_PROCESS)
+    if (IsNuwaProcess()) {
+        NuwaAddConstructor(ReinitTaskTracer, nullptr);
+    }
+#endif
+
     return true;
 }
 

tools/profiler/GeckoProfilerImpl.h

@@ -18,7 +18,7 @@
 #include "nsISupports.h"
 
 #ifdef MOZ_TASK_TRACER
-#include "GeckoTaskTracerImpl.h"
+#include "GeckoTaskTracer.h"
 #endif
 
 /* QT has a #define for the word "slots" and jsfriendapi.h has a struct with

tools/profiler/GeckoTaskTracer.cpp

@@ -9,14 +9,14 @@
 
 #include "mozilla/StaticMutex.h"
 #include "mozilla/ThreadLocal.h"
+#include "mozilla/TimeStamp.h"
 #include "mozilla/unused.h"
 
-#include "nsClassHashtable.h"
+#include "nsString.h"
 #include "nsThreadUtils.h"
+#include "prtime.h"
 
 #include <stdarg.h>
-#include <stdio.h>
-#include <unistd.h>
 
 #if defined(__GLIBC__)
 // glibc doesn't implement gettid(2).
@@ -27,14 +27,13 @@ static pid_t gettid()
 }
 #endif
 
-#define MAX_USER_LABEL_LEN 512
-
 namespace mozilla {
 namespace tasktracer {
 
-static mozilla::ThreadLocal<TraceInfo*> sTraceInfoTLS;
-static StaticMutex sMutex;
-static nsClassHashtable<nsUint32HashKey, TraceInfo>* sTraceInfos = nullptr;
+static mozilla::ThreadLocal<TraceInfo*>* sTraceInfoTLS = nullptr;
+static mozilla::StaticMutex sMutex;
+static nsTArray<nsAutoPtr<TraceInfo>>* sTraceInfos = nullptr;
+static bool sIsLoggingStarted = false;
 
 namespace {
 
@@ -43,29 +42,25 @@ AllocTraceInfo(int aTid)
 {
   StaticMutexAutoLock lock(sMutex);
 
-  sTraceInfos->Put(aTid, new TraceInfo(aTid));
-  return sTraceInfos->Get(aTid);
-}
+  nsAutoPtr<TraceInfo>* info = sTraceInfos->AppendElement(
+                                 new TraceInfo(aTid, sIsLoggingStarted));
 
-static void
-FreeTraceInfo(int aTid)
-{
-  StaticMutexAutoLock lock(sMutex);
-
-  sTraceInfos->Remove(aTid);
+  return info->get();
 }
 
 static bool
 IsInitialized()
 {
-  return sTraceInfoTLS.initialized();
+  return sTraceInfoTLS ? sTraceInfoTLS->initialized() : false;
 }
 
 static void
 SaveCurTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mSavedCurTraceSourceId = info->mCurTraceSourceId;
   info->mSavedCurTraceSourceType = info->mCurTraceSourceType;
@@ -76,7 +71,9 @@ static void
 RestoreCurTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = info->mSavedCurTraceSourceId;
   info->mCurTraceSourceType = info->mSavedCurTraceSourceType;
@@ -116,25 +113,82 @@ DestroySourceEvent()
   RestoreCurTraceInfo();
 }
 
+static void
+CleanUp()
+{
+  StaticMutexAutoLock lock(sMutex);
+
+  if (sTraceInfos) {
+    delete sTraceInfos;
+    sTraceInfos = nullptr;
+  }
+
+  // pthread_key_delete() is not called at the destructor of
+  // mozilla::ThreadLocal (Bug 1064672).
+  if (sTraceInfoTLS) {
+    delete sTraceInfoTLS;
+    sTraceInfoTLS = nullptr;
+  }
+}
+
+static void
+SetLogStarted(bool aIsStartLogging)
+{
+  // TODO: This is called from a signal handler. Use semaphore instead.
+  StaticMutexAutoLock lock(sMutex);
+
+  for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) {
+    (*sTraceInfos)[i]->mStartLogging = aIsStartLogging;
+  }
+
+  sIsLoggingStarted = aIsStartLogging;
+}
+
+static bool
+IsStartLogging(TraceInfo* aInfo)
+{
+  StaticMutexAutoLock lock(sMutex);
+  return aInfo ? aInfo->mStartLogging : false;
+}
+
 } // namespace anonymous
 
-void
-InitTaskTracer()
+nsCString*
+TraceInfo::AppendLog()
 {
+  MutexAutoLock lock(mLogsMutex);
+  return mLogs.AppendElement();
+}
+
+void
+TraceInfo::MoveLogsInto(TraceInfoLogsType& aResult)
+{
+  MutexAutoLock lock(mLogsMutex);
+  aResult.MoveElementsFrom(mLogs);
+}
+
+void
+InitTaskTracer(uint32_t aFlags)
+{
+  if (aFlags & FORKED_AFTER_NUWA) {
+    CleanUp();
+  }
+
+  MOZ_ASSERT(!sTraceInfoTLS);
+  sTraceInfoTLS = new ThreadLocal<TraceInfo*>();
+
   MOZ_ASSERT(!sTraceInfos);
+  sTraceInfos = new nsTArray<nsAutoPtr<TraceInfo>>();
 
-  sTraceInfos = new nsClassHashtable<nsUint32HashKey, TraceInfo>();
-
-  if (!sTraceInfoTLS.initialized()) {
-    unused << sTraceInfoTLS.init();
+  if (!sTraceInfoTLS->initialized()) {
+    unused << sTraceInfoTLS->init();
   }
 }
 
 void
 ShutdownTaskTracer()
 {
-  delete sTraceInfos;
-  sTraceInfos = nullptr;
+  CleanUp();
 }
 
 TraceInfo*
@@ -142,10 +196,10 @@ GetOrCreateTraceInfo()
 {
   NS_ENSURE_TRUE(IsInitialized(), nullptr);
 
-  TraceInfo* info = sTraceInfoTLS.get();
+  TraceInfo* info = sTraceInfoTLS->get();
   if (!info) {
     info = AllocTraceInfo(gettid());
-    sTraceInfoTLS.set(info);
+    sTraceInfoTLS->set(info);
   }
 
   return info;
@@ -200,37 +254,68 @@ void
 LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId, uint64_t aSourceEventId,
             SourceEventType aSourceEventType)
 {
-  NS_ENSURE_TRUE_VOID(IsInitialized());
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (!IsStartLogging(info)) {
+    return;
+  }
 
   // Log format:
   // [0 taskId dispatchTime sourceEventId sourceEventType parentTaskId]
+  nsCString* log = info->AppendLog();
+  if (log) {
+    log->AppendPrintf("%d %lld %lld %lld %d %lld",
+                      ACTION_DISPATCH, aTaskId, PR_Now(), aSourceEventId,
+                      aSourceEventType, aParentTaskId);
+  }
 }
 
 void
 LogBegin(uint64_t aTaskId, uint64_t aSourceEventId)
 {
-  NS_ENSURE_TRUE_VOID(IsInitialized());
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (!IsStartLogging(info)) {
+    return;
+  }
 
   // Log format:
   // [1 taskId beginTime processId threadId]
+  nsCString* log = info->AppendLog();
+  if (log) {
+    log->AppendPrintf("%d %lld %lld %d %d",
+                      ACTION_BEGIN, aTaskId, PR_Now(), getpid(), gettid());
+  }
 }
 
 void
 LogEnd(uint64_t aTaskId, uint64_t aSourceEventId)
 {
-  NS_ENSURE_TRUE_VOID(IsInitialized());
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (!IsStartLogging(info)) {
+    return;
+  }
 
   // Log format:
   // [2 taskId endTime]
+  nsCString* log = info->AppendLog();
+  if (log) {
+    log->AppendPrintf("%d %lld %lld", ACTION_END, aTaskId, PR_Now());
+  }
 }
 
 void
 LogVirtualTablePtr(uint64_t aTaskId, uint64_t aSourceEventId, int* aVptr)
 {
-  NS_ENSURE_TRUE_VOID(IsInitialized());
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (!IsStartLogging(info)) {
+    return;
+  }
 
   // Log format:
   // [4 taskId address]
+  nsCString* log = info->AppendLog();
+  if (log) {
+    log->AppendPrintf("%d %lld %p", ACTION_GET_VTABLE, aTaskId, aVptr);
+  }
 }
 
 void
@@ -238,7 +323,11 @@ FreeTraceInfo()
 {
   NS_ENSURE_TRUE_VOID(IsInitialized());
 
-  FreeTraceInfo(gettid());
+  StaticMutexAutoLock lock(sMutex);
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (info) {
+    sTraceInfos->RemoveElement(info);
+  }
 }
 
 AutoSourceEvent::AutoSourceEvent(SourceEventType aType)
@@ -253,16 +342,53 @@ AutoSourceEvent::~AutoSourceEvent()
 
 void AddLabel(const char* aFormat, ...)
 {
-  NS_ENSURE_TRUE_VOID(IsInitialized());
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (!IsStartLogging(info)) {
+    return;
+  }
 
   va_list args;
   va_start(args, aFormat);
-  char buffer[MAX_USER_LABEL_LEN] = {0};
-  vsnprintf(buffer, MAX_USER_LABEL_LEN, aFormat, args);
+  nsAutoCString buffer;
+  buffer.AppendPrintf(aFormat, args);
   va_end(args);
 
   // Log format:
   // [3 taskId "label"]
+  nsCString* log = info->AppendLog();
+  if (log) {
+    log->AppendPrintf("%d %lld %lld \"%s\"", ACTION_ADD_LABEL, info->mCurTaskId,
+                      PR_Now(), buffer.get());
+  }
+}
+
+// Functions used by GeckoProfiler.
+
+void
+StartLogging()
+{
+  SetLogStarted(true);
+}
+
+void
+StopLogging()
+{
+  SetLogStarted(false);
+}
+
+TraceInfoLogsType*
+GetLoggedData(TimeStamp aStartTime)
+{
+  TraceInfoLogsType* result = new TraceInfoLogsType();
+
+  // TODO: This is called from a signal handler. Use semaphore instead.
+  StaticMutexAutoLock lock(sMutex);
+
+  for (uint32_t i = 0; i < sTraceInfos->Length(); ++i) {
+    (*sTraceInfos)[i]->MoveLogsInto(*result);
+  }
+
+  return result;
 }
 
 } // namespace tasktracer

tools/profiler/GeckoTaskTracer.h

@@ -25,10 +25,21 @@
 
 class Task;
 class nsIRunnable;
+class nsCString;
+template <class> class nsTArray;
 
 namespace mozilla {
+
+class TimeStamp;
+
 namespace tasktracer {
 
+enum {
+  FORKED_AFTER_NUWA = 1 << 0
+};
+void InitTaskTracer(uint32_t aFlags = 0);
+void ShutdownTaskTracer();
+
 class FakeTracedTask;
 
 enum SourceEventType {
@@ -52,6 +63,10 @@ public:
 // followed by corresponding parameters.
 void AddLabel(const char* aFormat, ...);
 
+void StartLogging();
+void StopLogging();
+nsTArray<nsCString>* GetLoggedData(TimeStamp aStartTime);
+
 /**
  * Internal functions.
  */

tools/profiler/GeckoTaskTracerImpl.h

@@ -8,26 +8,36 @@
 #define GECKO_TASK_TRACER_IMPL_H
 
 #include "GeckoTaskTracer.h"
+#include "mozilla/Mutex.h"
+#include "nsTArray.h"
 
 namespace mozilla {
 namespace tasktracer {
 
+typedef nsTArray<nsCString> TraceInfoLogsType;
+
 struct TraceInfo
 {
-  TraceInfo(uint32_t aThreadId) : mCurTraceSourceId(0)
-                                , mCurTaskId(0)
-                                , mSavedCurTraceSourceId(0)
-                                , mSavedCurTaskId(0)
-                                , mCurTraceSourceType(UNKNOWN)
-                                , mSavedCurTraceSourceType(UNKNOWN)
-                                , mThreadId(aThreadId)
-                                , mLastUniqueTaskId(0)
+  TraceInfo(uint32_t aThreadId, bool aStartLogging)
+    : mCurTraceSourceId(0)
+    , mCurTaskId(0)
+    , mSavedCurTraceSourceId(0)
+    , mSavedCurTaskId(0)
+    , mCurTraceSourceType(UNKNOWN)
+    , mSavedCurTraceSourceType(UNKNOWN)
+    , mThreadId(aThreadId)
+    , mLastUniqueTaskId(0)
+    , mStartLogging(aStartLogging)
+    , mLogsMutex("TraceInfoMutex")
   {
     MOZ_COUNT_CTOR(TraceInfo);
   }
 
   ~TraceInfo() { MOZ_COUNT_DTOR(TraceInfo); }
 
+  nsCString* AppendLog();
+  void MoveLogsInto(TraceInfoLogsType& aResult);
+
   uint64_t mCurTraceSourceId;
   uint64_t mCurTaskId;
   uint64_t mSavedCurTraceSourceId;
@@ -36,10 +46,13 @@ struct TraceInfo
   SourceEventType mSavedCurTraceSourceType;
   uint32_t mThreadId;
   uint32_t mLastUniqueTaskId;
-};
+  bool mStartLogging;
 
-void InitTaskTracer();
-void ShutdownTaskTracer();
+  // This mutex protects the following log array because MoveLogsInto() might
+  // be called on another thread.
+  mozilla::Mutex mLogsMutex;
+  TraceInfoLogsType mLogs;
+};
 
 // Return the TraceInfo of current thread, allocate a new one if not exit.
 TraceInfo* GetOrCreateTraceInfo();

tools/profiler/TracedTaskCommon.cpp

@@ -34,7 +34,9 @@ void
 TracedTaskCommon::SetTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = mSourceEventId;
   info->mCurTraceSourceType = mSourceEventType;
@@ -45,7 +47,9 @@ void
 TracedTaskCommon::ClearTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = 0;
   info->mCurTraceSourceType = SourceEventType::UNKNOWN;