Bug 1103915: Output absolute starting time in the captured TaskTracer profile. r=tlee
authorCervantes Yu <cyu@mozilla.com>
Fri, 28 Nov 2014 17:27:09 +0800
changeset 251956 7c1d68ba4efe4ac3766b3e3a6188c7e79fb3db16
parent 251955 a98935079990720cb15a1a7b4f8a5ab4f88faddd
child 251957 fa7dbc827709ea19e84d714bc783113daec21946
push id4610
push userjlund@mozilla.com
push dateMon, 30 Mar 2015 18:32:55 +0000
treeherdermozilla-beta@4df54044d9ef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerstlee
bugs1103915
milestone38.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 1103915: Output absolute starting time in the captured TaskTracer profile. r=tlee
tools/profiler/GeckoTaskTracer.cpp
tools/profiler/GeckoTaskTracer.h
tools/profiler/TableTicker.cpp
tools/profiler/TableTicker.h
--- a/tools/profiler/GeckoTaskTracer.cpp
+++ b/tools/profiler/GeckoTaskTracer.cpp
@@ -4,16 +4,17 @@
  * 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 "nsString.h"
 #include "nsThreadUtils.h"
 #include "prtime.h"
 
 #include <stdarg.h>
 
@@ -21,31 +22,35 @@
 // glibc doesn't implement gettid(2).
 #include <sys/syscall.h>
 static pid_t gettid()
 {
   return (pid_t) syscall(SYS_gettid);
 }
 #endif
 
-using mozilla::TimeStamp;
-
 namespace mozilla {
 namespace tasktracer {
 
 static mozilla::ThreadLocal<TraceInfo*>* sTraceInfoTLS = nullptr;
 static mozilla::StaticMutex sMutex;
 static nsTArray<nsAutoPtr<TraceInfo>>* sTraceInfos = nullptr;
 static bool sIsLoggingStarted = false;
+static PRTime sStartTime;
 
-static TimeStamp sStartTime;
 static const char sJSLabelPrefix[] = "#tt#";
 
 namespace {
 
+static PRTime
+GetTimestamp()
+{
+  return PR_Now() / 1000;
+}
+
 static TraceInfo*
 AllocTraceInfo(int aTid)
 {
   StaticMutexAutoLock lock(sMutex);
 
   nsAutoPtr<TraceInfo>* info = sTraceInfos->AppendElement(
                                  new TraceInfo(aTid, sIsLoggingStarted));
 
@@ -167,22 +172,16 @@ SetLogStarted(bool aIsStartLogging)
 
 static bool
 IsStartLogging(TraceInfo* aInfo)
 {
   StaticMutexAutoLock lock(sMutex);
   return aInfo ? aInfo->mStartLogging : false;
 }
 
-static PRInt64
-DurationFromStart()
-{
-  return static_cast<PRInt64>((TimeStamp::Now() - sStartTime).ToMilliseconds());
-}
-
 } // namespace anonymous
 
 nsCString*
 TraceInfo::AppendLog()
 {
   MutexAutoLock lock(mLogsMutex);
   return mLogs.AppendElement();
 }
@@ -286,52 +285,51 @@ LogDispatch(uint64_t aTaskId, uint64_t a
     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, DurationFromStart(),
-                      aSourceEventId, aSourceEventType, aParentTaskId);
+                      ACTION_DISPATCH, aTaskId, GetTimestamp(), aSourceEventId,
+                      aSourceEventType, aParentTaskId);
   }
 }
 
 void
 LogBegin(uint64_t aTaskId, uint64_t aSourceEventId)
 {
   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, DurationFromStart(), getpid(), gettid());
+                      ACTION_BEGIN, aTaskId, GetTimestamp(), getpid(), gettid());
   }
 }
 
 void
 LogEnd(uint64_t aTaskId, uint64_t aSourceEventId)
 {
   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,
-                      DurationFromStart());
+    log->AppendPrintf("%d %lld %lld", ACTION_END, aTaskId, GetTimestamp());
   }
 }
 
 void
 LogVirtualTablePtr(uint64_t aTaskId, uint64_t aSourceEventId, int* aVptr)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   if (!IsStartLogging(info)) {
@@ -381,50 +379,56 @@ void AddLabel(const char* aFormat, ...)
   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,
-                      DurationFromStart(), buffer.get());
+                      GetTimestamp(), buffer.get());
   }
 }
 
 // Functions used by GeckoProfiler.
 
 void
-StartLogging(TimeStamp aStartTime)
+StartLogging()
 {
-  sStartTime = aStartTime;
+  sStartTime = GetTimestamp();
   SetLogStarted(true);
 }
 
 void
 StopLogging()
 {
   SetLogStarted(false);
 }
 
 TraceInfoLogsType*
-GetLoggedData(TimeStamp aStartTime)
+GetLoggedData()
 {
   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;
 }
 
+const PRTime
+GetStartTime()
+{
+  return sStartTime;
+}
+
 const char*
 GetJSLabelPrefix()
 {
   return sJSLabelPrefix;
 }
 
 } // namespace tasktracer
 } // namespace mozilla
--- a/tools/profiler/GeckoTaskTracer.h
+++ b/tools/profiler/GeckoTaskTracer.h
@@ -3,17 +3,16 @@
 /* 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_H
 #define GECKO_TASK_TRACER_H
 
 #include "nsCOMPtr.h"
-#include "mozilla/TimeStamp.h"
 
 /**
  * TaskTracer provides a way to trace the correlation between different tasks
  * across threads and processes. Unlike sampling based profilers, TaskTracer can
  * tell you where a task is dispatched from, what its original source was, how
  * long it waited in the event queue, and how long it took to execute.
  *
  * Source Events are usually some kinds of I/O events we're interested in, such
@@ -59,20 +58,23 @@ 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(mozilla::TimeStamp aStartTime);
+void StartLogging();
 void StopLogging();
 nsTArray<nsCString>* GetLoggedData(TimeStamp aStartTime);
 
+// Returns the timestamp when Task Tracer is enabled in this process.
+const PRTime GetStartTime();
+
 /**
  * Internal functions.
  */
 
 Task* CreateTracedTask(Task* aTask);
 
 already_AddRefed<nsIRunnable> CreateTracedRunnable(nsIRunnable* aRunnable);
 
--- a/tools/profiler/TableTicker.cpp
+++ b/tools/profiler/TableTicker.cpp
@@ -114,17 +114,16 @@ void TableTicker::StreamTaskTracer(JSStr
 #ifdef MOZ_TASK_TRACER
     b.Name("data");
     b.BeginArray();
       nsAutoPtr<nsTArray<nsCString>> data(
         mozilla::tasktracer::GetLoggedData(sStartTime));
       for (uint32_t i = 0; i < data->Length(); ++i) {
         b.Value((data->ElementAt(i)).get());
       }
-      mozilla::tasktracer::StartLogging(sStartTime);
     b.EndArray();
 
     b.Name("threads");
     b.BeginArray();
       mozilla::MutexAutoLock lock(*sRegisteredThreadsMutex);
       for (size_t i = 0; i < sRegisteredThreads->size(); i++) {
         // Thread meta data
         ThreadInfo* info = sRegisteredThreads->at(i);
@@ -134,16 +133,19 @@ void TableTicker::StreamTaskTracer(JSStr
           b.NameValue("name", "Plugin");
         } else {
           b.NameValue("name", info->Name());
         }
         b.NameValue("tid", static_cast<int>(info->ThreadId()));
         b.EndObject();
       }
     b.EndArray();
+
+    b.NameValue("start",
+                static_cast<double>(mozilla::tasktracer::GetStartTime()));
 #endif
   b.EndObject();
 }
 
 
 void TableTicker::StreamMetaJSCustomObject(JSStreamWriter& b)
 {
   b.BeginObject();
--- a/tools/profiler/TableTicker.h
+++ b/tools/profiler/TableTicker.h
@@ -106,17 +106,17 @@ class TableTicker: public Sampler {
         RegisterThread(info);
       }
 
       SetActiveSampler(this);
     }
 
 #ifdef MOZ_TASK_TRACER
     if (mTaskTracer) {
-      mozilla::tasktracer::StartLogging(sStartTime);
+      mozilla::tasktracer::StartLogging();
     }
 #endif
   }
 
   ~TableTicker() {
     if (IsActive())
       Stop();