Bug 1113562 - Expected delay time of tasks should not be the latency of those kind. r=sinker

ipc/chromium/src/base/message_loop.cc

@@ -32,6 +32,7 @@
 #endif
 #ifdef MOZ_TASK_TRACER
 #include "GeckoTaskTracer.h"
+#include "TracedTaskCommon.h"
 #endif
 
 #include "MessagePump.h"
@@ -287,6 +288,7 @@ void MessageLoop::PostIdleTask(
 
 #ifdef MOZ_TASK_TRACER
   task = mozilla::tasktracer::CreateTracedTask(task);
+  (static_cast<mozilla::tasktracer::TracedTask*>(task))->DispatchTask();
 #endif
 
   task->SetBirthPlace(from_here);
@@ -301,6 +303,7 @@ void MessageLoop::PostTask_Helper(
 
 #ifdef MOZ_TASK_TRACER
   task = mozilla::tasktracer::CreateTracedTask(task);
+  (static_cast<mozilla::tasktracer::TracedTask*>(task))->DispatchTask(delay_ms);
 #endif
 
   task->SetBirthPlace(from_here);

layout/base/nsPresShell.cpp

@@ -6942,11 +6942,11 @@ PresShell::HandleEvent(nsIFrame* aFrame,
   // Make touch events, mouse events and hardware key events to be the source
   // events of TaskTracer, and originate the rest correlation tasks from here.
   SourceEventType type = SourceEventType::Unknown;
-  if (WidgetTouchEvent* inputEvent = aEvent->AsTouchEvent()) {
+  if (aEvent->AsTouchEvent()) {
     type = SourceEventType::Touch;
-  } else if (WidgetMouseEvent* inputEvent = aEvent->AsMouseEvent()) {
+  } else if (aEvent->AsMouseEvent()) {
     type = SourceEventType::Mouse;
-  } else if (WidgetKeyboardEvent* inputEvent = aEvent->AsKeyboardEvent()) {
+  } else if (aEvent->AsKeyboardEvent()) {
     type = SourceEventType::Key;
   }
   AutoSourceEvent taskTracerEvent(type);

tools/profiler/GeckoTaskTracer.cpp

@@ -311,16 +311,28 @@ GetCurTraceInfo(uint64_t* aOutSourceEventId, uint64_t* aOutParentTaskId,
 void
 LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId, uint64_t aSourceEventId,
             SourceEventType aSourceEventType)
+{
+  LogDispatch(aTaskId, aParentTaskId, aSourceEventId, aSourceEventType, 0);
+}
+
+void
+LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId, uint64_t aSourceEventId,
+            SourceEventType aSourceEventType, int aDelayTimeMs)
 {
   TraceInfo* info = GetOrCreateTraceInfo();
   ENSURE_TRUE_VOID(info);
 
+  // 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;
+
   // 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, GetTimestamp(), aSourceEventId,
+                      ACTION_DISPATCH, aTaskId, time, aSourceEventId,
                       aSourceEventType, aParentTaskId);
   }
 }

tools/profiler/GeckoTaskTracer.h

@@ -37,10 +37,6 @@ namespace tasktracer {
 enum {
   FORKED_AFTER_NUWA = 1 << 0
 };
-void InitTaskTracer(uint32_t aFlags = 0);
-void ShutdownTaskTracer();
-
-class FakeTracedTask;
 
 enum SourceEventType {
   Unknown = 0,
@@ -59,6 +55,9 @@ public:
   ~AutoSourceEvent();
 };
 
+void InitTaskTracer(uint32_t aFlags = 0);
+void ShutdownTaskTracer();
+
 // Add a label to the currently running task, aFormat is the message to log,
 // followed by corresponding parameters.
 void AddLabel(const char* aFormat, ...);
@@ -78,8 +77,6 @@ Task* CreateTracedTask(Task* aTask);
 
 already_AddRefed<nsIRunnable> CreateTracedRunnable(nsIRunnable* aRunnable);
 
-already_AddRefed<FakeTracedTask> CreateFakeTracedTask(int* aVptr);
-
 // Free the TraceInfo allocated on a thread's TLS. Currently we are wrapping
 // tasks running on nsThreads and base::thread, so FreeTraceInfo is called at
 // where nsThread and base::thread release themselves.

tools/profiler/GeckoTaskTracerImpl.h

@@ -86,6 +86,10 @@ enum ActionType {
 void LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId,
                  uint64_t aSourceEventId, SourceEventType aSourceEventType);
 
+void LogDispatch(uint64_t aTaskId, uint64_t aParentTaskId,
+                 uint64_t aSourceEventId, SourceEventType aSourceEventType,
+                 int aDelayTimeMs);
+
 void LogBegin(uint64_t aTaskId, uint64_t aSourceEventId);
 
 void LogEnd(uint64_t aTaskId, uint64_t aSourceEventId);

tools/profiler/TracedTaskCommon.cpp

@@ -7,49 +7,80 @@
 #include "GeckoTaskTracerImpl.h"
 #include "TracedTaskCommon.h"
 
+// NS_ENSURE_TRUE_VOID() without the warning on the debug build.
+#define ENSURE_TRUE_VOID(x)   \
+  do {                        \
+    if (MOZ_UNLIKELY(!(x))) { \
+       return;                \
+    }                         \
+  } while(0)
+
 namespace mozilla {
 namespace tasktracer {
 
 TracedTaskCommon::TracedTaskCommon()
-  : mSourceEventId(0)
-  , mSourceEventType(SourceEventType::Unknown)
+  : mSourceEventType(SourceEventType::Unknown)
+  , mSourceEventId(0)
+  , mParentTaskId(0)
+  , mTaskId(0)
+  , mIsTraceInfoInit(false)
+{
+}
+
+TracedTaskCommon::~TracedTaskCommon()
 {
-  Init();
 }
 
 void
 TracedTaskCommon::Init()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  NS_ENSURE_TRUE_VOID(info);
+  ENSURE_TRUE_VOID(info);
 
   mTaskId = GenNewUniqueTaskId();
   mSourceEventId = info->mCurTraceSourceId;
   mSourceEventType = info->mCurTraceSourceType;
-
-  LogDispatch(mTaskId, info->mCurTaskId, mSourceEventId, mSourceEventType);
+  mParentTaskId = info->mCurTaskId;
+  mIsTraceInfoInit = true;
 }
 
 void
-TracedTaskCommon::SetTraceInfo()
+TracedTaskCommon::DispatchTask(int aDelayTimeMs)
 {
-  TraceInfo* info = GetOrCreateTraceInfo();
-  if (!info) {
-    return;
-  }
-
-  info->mCurTraceSourceId = mSourceEventId;
-  info->mCurTraceSourceType = mSourceEventType;
-  info->mCurTaskId = mTaskId;
+  LogDispatch(mTaskId, mParentTaskId, mSourceEventId, mSourceEventType,
+              aDelayTimeMs);
 }
 
 void
-TracedTaskCommon::ClearTraceInfo()
+TracedTaskCommon::GetTLSTraceInfo()
 {
   TraceInfo* info = GetOrCreateTraceInfo();
-  if (!info) {
-    return;
+  ENSURE_TRUE_VOID(info);
+
+  mSourceEventType = info->mCurTraceSourceType;
+  mSourceEventId = info->mCurTraceSourceId;
+  mTaskId = info->mCurTaskId;
+  mIsTraceInfoInit = true;
+}
+
+void
+TracedTaskCommon::SetTLSTraceInfo()
+{
+  TraceInfo* info = GetOrCreateTraceInfo();
+  ENSURE_TRUE_VOID(info);
+
+  if (mIsTraceInfoInit) {
+    info->mCurTraceSourceId = mSourceEventId;
+    info->mCurTraceSourceType = mSourceEventType;
+    info->mCurTaskId = mTaskId;
   }
+}
+
+void
+TracedTaskCommon::ClearTLSTraceInfo()
+{
+  TraceInfo* info = GetOrCreateTraceInfo();
+  ENSURE_TRUE_VOID(info);
 
   info->mCurTraceSourceId = 0;
   info->mCurTraceSourceType = SourceEventType::Unknown;
@@ -63,19 +94,23 @@ TracedRunnable::TracedRunnable(nsIRunnable* aOriginalObj)
   : TracedTaskCommon()
   , mOriginalObj(aOriginalObj)
 {
+  Init();
   LogVirtualTablePtr(mTaskId, mSourceEventId, *(int**)(aOriginalObj));
 }
 
+TracedRunnable::~TracedRunnable()
+{
+}
+
 NS_IMETHODIMP
 TracedRunnable::Run()
 {
+  SetTLSTraceInfo();
   LogBegin(mTaskId, mSourceEventId);
-
-  SetTraceInfo();
   nsresult rv = mOriginalObj->Run();
-  ClearTraceInfo();
-
   LogEnd(mTaskId, mSourceEventId);
+  ClearTLSTraceInfo();
+
   return rv;
 }
 
@@ -86,54 +121,26 @@ TracedTask::TracedTask(Task* aOriginalObj)
   : TracedTaskCommon()
   , mOriginalObj(aOriginalObj)
 {
+  Init();
   LogVirtualTablePtr(mTaskId, mSourceEventId, *(int**)(aOriginalObj));
 }
 
+TracedTask::~TracedTask()
+{
+  if (mOriginalObj) {
+    delete mOriginalObj;
+    mOriginalObj = nullptr;
+  }
+}
+
 void
 TracedTask::Run()
 {
+  SetTLSTraceInfo();
   LogBegin(mTaskId, mSourceEventId);
-
-  SetTraceInfo();
   mOriginalObj->Run();
-  ClearTraceInfo();
-
   LogEnd(mTaskId, mSourceEventId);
-}
-
-FakeTracedTask::FakeTracedTask(int* aVptr)
-  : TracedTaskCommon()
-{
-  LogVirtualTablePtr(mTaskId, mSourceEventId, aVptr);
-}
-
-void
-FakeTracedTask::BeginFakeTracedTask()
-{
-  LogBegin(mTaskId, mSourceEventId);
-  SetTraceInfo();
-}
-
-void
-FakeTracedTask::EndFakeTracedTask()
-{
-  ClearTraceInfo();
-  LogEnd(mTaskId, mSourceEventId);
-}
-
-AutoRunFakeTracedTask::AutoRunFakeTracedTask(FakeTracedTask* aFakeTracedTask)
-  : mFakeTracedTask(aFakeTracedTask)
-{
-  if (mFakeTracedTask) {
-    mFakeTracedTask->BeginFakeTracedTask();
-  }
-}
-
-AutoRunFakeTracedTask::~AutoRunFakeTracedTask()
-{
-  if (mFakeTracedTask) {
-    mFakeTracedTask->EndFakeTracedTask();
-  }
+  ClearTLSTraceInfo();
 }
 
 /**
@@ -158,16 +165,5 @@ CreateTracedTask(Task* aTask)
   return task;
 }
 
-/**
- * CreateFakeTracedTask() returns a FakeTracedTask tracking the event which is
- * not dispatched from its parent task directly, such as timer events.
- */
-already_AddRefed<FakeTracedTask>
-CreateFakeTracedTask(int* aVptr)
-{
-  nsRefPtr<FakeTracedTask> task(new FakeTracedTask(aVptr));
-  return task.forget();
-}
-
 } // namespace tasktracer
 } // namespace mozilla

tools/profiler/TracedTaskCommon.h

@@ -19,22 +19,25 @@ class TracedTaskCommon
 {
 public:
   TracedTaskCommon();
-  virtual ~TracedTaskCommon() {}
+  virtual ~TracedTaskCommon();
+
+  void DispatchTask(int aDelayTimeMs = 0);
+
+  void SetTLSTraceInfo();
+  void GetTLSTraceInfo();
+  void ClearTLSTraceInfo();
 
 protected:
   void Init();
 
-  // Sets up the metadata on the current thread's TraceInfo for this task.
-  // After Run(), ClearTraceInfo is called to reset the metadata.
-  void SetTraceInfo();
-  void ClearTraceInfo();
-
-  // Its own task Id, an unique number base on its thread Id and a last unique
-  // task Id stored in its TraceInfo.
-  uint64_t mTaskId;
-
-  uint64_t mSourceEventId;
+  // TraceInfo of TLS will be set by the following parameters, including source
+  // event type, source event ID, parent task ID, and task ID of this traced
+  // task/runnable.
   SourceEventType mSourceEventType;
+  uint64_t mSourceEventId;
+  uint64_t mParentTaskId;
+  uint64_t mTaskId;
+  bool mIsTraceInfoInit;
 };
 
 class TracedRunnable : public TracedTaskCommon
@@ -46,7 +49,7 @@ public:
   TracedRunnable(nsIRunnable* aOriginalObj);
 
 private:
-  virtual ~TracedRunnable() {}
+  virtual ~TracedRunnable();
 
   nsCOMPtr<nsIRunnable> mOriginalObj;
 };
@@ -56,13 +59,7 @@ class TracedTask : public TracedTaskCommon
 {
 public:
   TracedTask(Task* aOriginalObj);
-  ~TracedTask()
-  {
-    if (mOriginalObj) {
-      delete mOriginalObj;
-      mOriginalObj = nullptr;
-    }
-  }
+  ~TracedTask();
 
   virtual void Run();
 
@@ -70,34 +67,6 @@ private:
   Task* mOriginalObj;
 };
 
-// FakeTracedTask is for tracking events that are not directly dispatched from
-// their parents, e.g. The timer events.
-class FakeTracedTask : public TracedTaskCommon
-{
-public:
-  NS_INLINE_DECL_REFCOUNTING(FakeTracedTask)
-
-  FakeTracedTask(int* aVptr);
-  void BeginFakeTracedTask();
-  void EndFakeTracedTask();
-private:
-  virtual ~FakeTracedTask() {}
-
-  // No copy allowed.
-  FakeTracedTask() = delete;
-  FakeTracedTask(const FakeTracedTask& aTask) = delete;
-  FakeTracedTask& operator=(const FakeTracedTask& aTask) = delete;
-};
-
-class AutoRunFakeTracedTask
-{
-public:
-  AutoRunFakeTracedTask(FakeTracedTask* aFakeTracedTask);
-  ~AutoRunFakeTracedTask();
-private:
-  nsRefPtr<FakeTracedTask> mFakeTracedTask;
-};
-
 } // namespace tasktracer
 } // namespace mozilla
 

xpcom/threads/TimerThread.cpp

@@ -452,9 +452,9 @@ TimerThread::AddTimerInternal(nsTimerImpl* aTimer)
   NS_ADDREF(aTimer);
 
 #ifdef MOZ_TASK_TRACER
-  // Create a FakeTracedTask, and dispatch it here. This is the start point of
-  // the latency.
-  aTimer->DispatchTracedTask();
+  // Caller of AddTimer is the parent task of its timer event, so we store the
+  // TraceInfo here for later used.
+  aTimer->GetTLSTraceInfo();
 #endif
 
   return insertSlot - mTimers.Elements();

xpcom/threads/nsThread.cpp

@@ -72,6 +72,7 @@
 
 #ifdef MOZ_TASK_TRACER
 #include "GeckoTaskTracer.h"
+#include "TracedTaskCommon.h"
 using namespace mozilla::tasktracer;
 #endif
 
@@ -540,6 +541,7 @@ nsThread::DispatchInternal(nsIRunnable* aEvent, uint32_t aFlags,
 
 #ifdef MOZ_TASK_TRACER
   nsCOMPtr<nsIRunnable> tracedRunnable = CreateTracedRunnable(aEvent);
+  (static_cast<TracedRunnable*>(tracedRunnable.get()))->DispatchTask();
   aEvent = tracedRunnable;
 #endif
 

xpcom/threads/nsTimerImpl.cpp

@@ -17,6 +17,10 @@
 #ifdef MOZ_NUWA_PROCESS
 #include "ipc/Nuwa.h"
 #endif
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracerImpl.h"
+using namespace mozilla::tasktracer;
+#endif
 
 using mozilla::Atomic;
 using mozilla::LogLevel;
@@ -556,13 +560,6 @@ nsTimerImpl::Fire()
                  js::ProfileEntry::Category::OTHER);
 #endif
 
-#ifdef MOZ_TASK_TRACER
-  // mTracedTask is an instance of FakeTracedTask created by
-  // DispatchTracedTask(). AutoRunFakeTracedTask logs the begin/end time of the
-  // timer/FakeTracedTask instance in ctor/dtor.
-  mozilla::tasktracer::AutoRunFakeTracedTask runTracedTask(mTracedTask);
-#endif
-
   TimeStamp now = TimeStamp::Now();
   if (MOZ_LOG_TEST(GetTimerLog(), LogLevel::Debug)) {
     TimeDuration   a = now - mStart; // actual delay in intervals
@@ -752,6 +749,14 @@ nsTimerImpl::PostTimerEvent(already_AddRefed<nsTimerImpl> aTimerRef)
     }
   }
 
+#ifdef MOZ_TASK_TRACER
+  // During the dispatch of TimerEvent, we overwrite the current TraceInfo
+  // partially with the info saved in timer earlier, and restore it back by
+  // AutoSaveCurTraceInfo.
+  AutoSaveCurTraceInfo saveCurTraceInfo;
+  (timer->GetTracedTask()).SetTLSTraceInfo();
+#endif
+
   nsIEventTarget* target = timer->mEventTarget;
   event->SetTimer(timer.forget());
 
@@ -795,3 +800,18 @@ nsTimerImpl::SizeOfIncludingThis(mozilla::MallocSizeOf aMallocSizeOf) const
 {
   return aMallocSizeOf(this);
 }
+
+#ifdef MOZ_TASK_TRACER
+void
+nsTimerImpl::GetTLSTraceInfo()
+{
+  mTracedTask.GetTLSTraceInfo();
+}
+
+TracedTaskCommon
+nsTimerImpl::GetTracedTask()
+{
+  return mTracedTask;
+}
+#endif
+

xpcom/threads/nsTimerImpl.h

@@ -59,10 +59,8 @@ public:
   }
 
 #ifdef MOZ_TASK_TRACER
-  void DispatchTracedTask()
-  {
-    mTracedTask = mozilla::tasktracer::CreateFakeTracedTask(*(int**)(this));
-  }
+  void GetTLSTraceInfo();
+  mozilla::tasktracer::TracedTaskCommon GetTracedTask();
 #endif
 
   virtual size_t SizeOfIncludingThis(mozilla::MallocSizeOf aMallocSizeOf) const override;
@@ -150,7 +148,7 @@ private:
   TimeStamp             mTimeout;
 
 #ifdef MOZ_TASK_TRACER
-  nsRefPtr<mozilla::tasktracer::FakeTracedTask> mTracedTask;
+  mozilla::tasktracer::TracedTaskCommon mTracedTask;
 #endif
 
   TimeStamp             mStart, mStart2;