Bug 992454 - Part 1: Log TaskTracer data into string buffers and bug fixes. r=khuey.
authorShelly Lin <slin@mozilla.com>,Cervantes Yu <cyu@mozilla.com>
Tue, 14 Oct 2014 10:47:59 +0800
changeset 210264 6cb2c1756e099c72159ae4d9574956440de6d416
parent 210263 94d1b30bde0022bc8c79e5b1b0128e121b579b1b
child 210265 d150f12f7e603ec059a76b6b0ffe6fe03d3deaee
push id50384
push usercbook@mozilla.com
push dateTue, 14 Oct 2014 07:52:28 +0000
treeherdermozilla-inbound@073e83cef238 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerskhuey
bugs992454
milestone36.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 992454 - Part 1: Log TaskTracer data into string buffers and bug fixes. r=khuey.
dom/ipc/ContentChild.cpp
tools/profiler/GeckoProfilerImpl.h
tools/profiler/GeckoTaskTracer.cpp
tools/profiler/GeckoTaskTracer.h
tools/profiler/GeckoTaskTracerImpl.h
tools/profiler/TracedTaskCommon.cpp
--- a/dom/ipc/ContentChild.cpp
+++ b/dom/ipc/ContentChild.cpp
@@ -510,16 +510,25 @@ InitOnContentProcessCreated()
         return;
     }
 #endif
 
     // This will register cross-process observer.
     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
    ,mScreenSize(0, 0)
 #endif
    , mCanOverrideProcessName(true)
 {
     // This process is a content process, so it's clearly running in
@@ -589,16 +598,22 @@ ContentChild::Init(MessageLoop* aIOLoop,
                                   XRE_GetProcessType());
 #endif
 
     GetCPOWManager();
 
     SendGetProcessAttributes(&mID, &mIsForApp, &mIsForBrowser);
     InitProcessAttributes();
 
+#if defined(MOZ_TASK_TRACER) && defined (MOZ_NUWA_PROCESS)
+    if (IsNuwaProcess()) {
+        NuwaAddConstructor(ReinitTaskTracer, nullptr);
+    }
+#endif
+
     return true;
 }
 
 void
 ContentChild::InitProcessAttributes()
 {
 #ifdef MOZ_WIDGET_GONK
 #ifdef MOZ_NUWA_PROCESS
--- a/tools/profiler/GeckoProfilerImpl.h
+++ b/tools/profiler/GeckoProfilerImpl.h
@@ -13,17 +13,17 @@
 #include "mozilla/ThreadLocal.h"
 #include "mozilla/Assertions.h"
 #include "nscore.h"
 #include "GeckoProfilerFunc.h"
 #include "PseudoStack.h"
 #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
  * this variable name, causing compilation problems. Alleviate this for now by
  * removing this #define */
 #ifdef MOZ_WIDGET_QT
 #undef slots
 #endif
--- a/tools/profiler/GeckoTaskTracer.cpp
+++ b/tools/profiler/GeckoTaskTracer.cpp
@@ -4,84 +4,81 @@
  * 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 "GeckoTaskTracer.h"
 #include "GeckoTaskTracerImpl.h"
 
 #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).
 #include <sys/syscall.h>
 static pid_t gettid()
 {
   return (pid_t) syscall(SYS_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 {
 
 static TraceInfo*
 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;
   info->mSavedCurTaskId = info->mCurTaskId;
 }
 
 static void
 RestoreCurTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = info->mSavedCurTraceSourceId;
   info->mCurTraceSourceType = info->mSavedCurTraceSourceType;
   info->mCurTaskId = info->mSavedCurTaskId;
 }
 
 static void
 CreateSourceEvent(SourceEventType aType)
@@ -111,46 +108,103 @@ DestroySourceEvent()
   // Log a fake end for this source event.
   TraceInfo* info = GetOrCreateTraceInfo();
   LogEnd(info->mCurTraceSourceId, info->mCurTraceSourceId);
 
   // Restore the previously saved source event info.
   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
 
+nsCString*
+TraceInfo::AppendLog()
+{
+  MutexAutoLock lock(mLogsMutex);
+  return mLogs.AppendElement();
+}
+
 void
-InitTaskTracer()
+TraceInfo::MoveLogsInto(TraceInfoLogsType& aResult)
 {
-  MOZ_ASSERT(!sTraceInfos);
+  MutexAutoLock lock(mLogsMutex);
+  aResult.MoveElementsFrom(mLogs);
+}
 
-  sTraceInfos = new nsClassHashtable<nsUint32HashKey, TraceInfo>();
+void
+InitTaskTracer(uint32_t aFlags)
+{
+  if (aFlags & FORKED_AFTER_NUWA) {
+    CleanUp();
+  }
 
-  if (!sTraceInfoTLS.initialized()) {
-    unused << sTraceInfoTLS.init();
+  MOZ_ASSERT(!sTraceInfoTLS);
+  sTraceInfoTLS = new ThreadLocal<TraceInfo*>();
+
+  MOZ_ASSERT(!sTraceInfos);
+  sTraceInfos = new nsTArray<nsAutoPtr<TraceInfo>>();
+
+  if (!sTraceInfoTLS->initialized()) {
+    unused << sTraceInfoTLS->init();
   }
 }
 
 void
 ShutdownTaskTracer()
 {
-  delete sTraceInfos;
-  sTraceInfos = nullptr;
+  CleanUp();
 }
 
 TraceInfo*
 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;
 }
 
 uint64_t
 GenNewUniqueTaskId()
 {
@@ -195,75 +249,147 @@ GetCurTraceInfo(uint64_t* aOutSourceEven
   *aOutParentTaskId = info->mCurTaskId;
   *aOutSourceEventType = info->mCurTraceSourceType;
 }
 
 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
 FreeTraceInfo()
 {
   NS_ENSURE_TRUE_VOID(IsInitialized());
 
-  FreeTraceInfo(gettid());
+  StaticMutexAutoLock lock(sMutex);
+  TraceInfo* info = GetOrCreateTraceInfo();
+  if (info) {
+    sTraceInfos->RemoveElement(info);
+  }
 }
 
 AutoSourceEvent::AutoSourceEvent(SourceEventType aType)
 {
   CreateSourceEvent(aType);
 }
 
 AutoSourceEvent::~AutoSourceEvent()
 {
   DestroySourceEvent();
 }
 
 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
 } // namespace mozilla
--- a/tools/profiler/GeckoTaskTracer.h
+++ b/tools/profiler/GeckoTaskTracer.h
@@ -20,20 +20,31 @@
  * created, TaskTracer records the entire chain of Tasks and nsRunnables as they
  * are dispatched to different threads and processes. It records latency,
  * execution time, etc. for each Task and nsRunnable that chains back to the
  * original source event.
  */
 
 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 {
   UNKNOWN = 0,
   TOUCH,
   MOUSE,
   KEY,
   BLUETOOTH,
@@ -47,16 +58,20 @@ public:
   AutoSourceEvent(SourceEventType aType);
   ~AutoSourceEvent();
 };
 
 // Add a label to the currently running task, aFormat is the message to log,
 // followed by corresponding parameters.
 void AddLabel(const char* aFormat, ...);
 
+void StartLogging();
+void StopLogging();
+nsTArray<nsCString>* GetLoggedData(TimeStamp aStartTime);
+
 /**
  * Internal functions.
  */
 
 Task* CreateTracedTask(Task* aTask);
 
 already_AddRefed<nsIRunnable> CreateTracedRunnable(nsIRunnable* aRunnable);
 
--- a/tools/profiler/GeckoTaskTracerImpl.h
+++ b/tools/profiler/GeckoTaskTracerImpl.h
@@ -3,48 +3,61 @@
 /* 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/. */
 
 #ifndef GECKO_TASK_TRACER_IMPL_H
 #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;
   uint64_t mSavedCurTaskId;
   SourceEventType mCurTraceSourceType;
   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();
 
 uint64_t GenNewUniqueTaskId();
 
 class AutoSaveCurTraceInfo
 {
--- a/tools/profiler/TracedTaskCommon.cpp
+++ b/tools/profiler/TracedTaskCommon.cpp
@@ -29,28 +29,32 @@ TracedTaskCommon::Init()
 
   LogDispatch(mTaskId, info->mCurTaskId, mSourceEventId, mSourceEventType);
 }
 
 void
 TracedTaskCommon::SetTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = mSourceEventId;
   info->mCurTraceSourceType = mSourceEventType;
   info->mCurTaskId = mTaskId;
 }
 
 void
 TracedTaskCommon::ClearTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  if (!info) {
+    return;
+  }
 
   info->mCurTraceSourceId = 0;
   info->mCurTraceSourceType = SourceEventType::UNKNOWN;
   info->mCurTaskId = 0;
 }
 
 /**
  * Implementation of class TracedRunnable.