Bug 908995 - Part 2: Track runnables, tasks and timer events with TaskTracer. r=khuey.
authorShelly Lin <slin@mozilla.com>
Thu, 27 Mar 2014 16:49:06 +0800
changeset 180248 2e0304d75739a923301d8f11759fed14113f7000
parent 180247 587ca014fdf038130f50406c7ac75805b940b4c6
child 180249 3064ab64f06ad6aedb84e326603b12a96f922eab
push id272
push userpvanderbeken@mozilla.com
push dateMon, 05 May 2014 16:31:18 +0000
reviewerskhuey
bugs908995
milestone31.0a1
Bug 908995 - Part 2: Track runnables, tasks and timer events with TaskTracer. r=khuey.
ipc/chromium/src/base/message_loop.cc
ipc/chromium/src/base/thread.cc
ipc/chromium/src/chrome/common/ipc_channel_posix.cc
ipc/chromium/src/chrome/common/ipc_message.cc
ipc/chromium/src/chrome/common/ipc_message.h
tools/profiler/GeckoProfilerImpl.h
xpcom/threads/TimerThread.cpp
xpcom/threads/nsThread.cpp
xpcom/threads/nsTimerImpl.cpp
xpcom/threads/nsTimerImpl.h
--- a/ipc/chromium/src/base/message_loop.cc
+++ b/ipc/chromium/src/base/message_loop.cc
@@ -26,16 +26,19 @@
 #endif
 #ifdef MOZ_WIDGET_QT
 #include "base/message_pump_qt.h"
 #endif
 #endif
 #ifdef ANDROID
 #include "base/message_pump_android.h"
 #endif
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracer.h"
+#endif
 
 #include "MessagePump.h"
 
 using base::Time;
 using base::TimeDelta;
 using base::TimeTicks;
 
 // A lazily created thread local storage for quick access to a thread's message
@@ -272,25 +275,35 @@ void MessageLoop::PostNonNestableTask(
 void MessageLoop::PostNonNestableDelayedTask(
     const tracked_objects::Location& from_here, Task* task, int delay_ms) {
   PostTask_Helper(from_here, task, delay_ms, false);
 }
 
 void MessageLoop::PostIdleTask(
     const tracked_objects::Location& from_here, Task* task) {
   DCHECK(current() == this);
+
+#ifdef MOZ_TASK_TRACER
+  task = mozilla::tasktracer::CreateTracedTask(task);
+#endif
+
   task->SetBirthPlace(from_here);
   PendingTask pending_task(task, false);
   deferred_non_nestable_work_queue_.push(pending_task);
 }
 
 // Possibly called on a background thread!
 void MessageLoop::PostTask_Helper(
     const tracked_objects::Location& from_here, Task* task, int delay_ms,
     bool nestable) {
+
+#ifdef MOZ_TASK_TRACER
+  task = mozilla::tasktracer::CreateTracedTask(task);
+#endif
+
   task->SetBirthPlace(from_here);
 
   PendingTask pending_task(task, nestable);
 
   if (delay_ms > 0) {
     pending_task.delayed_run_time =
         TimeTicks::Now() + TimeDelta::FromMilliseconds(delay_ms);
   } else {
--- a/ipc/chromium/src/base/thread.cc
+++ b/ipc/chromium/src/base/thread.cc
@@ -6,16 +6,20 @@
 
 #include "base/lazy_instance.h"
 #include "base/string_util.h"
 #include "base/thread_local.h"
 #include "base/waitable_event.h"
 #include "GeckoProfiler.h"
 #include "mozilla/IOInterposer.h"
 
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracer.h"
+#endif
+
 namespace base {
 
 // This task is used to trigger the message loop to exit.
 class ThreadQuitTask : public Task {
  public:
   virtual void Run() {
     MessageLoop::current()->Quit();
     Thread::SetThreadWasQuitProperly(true);
@@ -167,14 +171,18 @@ void Thread::ThreadMain() {
   CleanUp();
 
   // Assert that MessageLoop::Quit was called by ThreadQuitTask.
   DCHECK(GetThreadWasQuitProperly());
 
   mozilla::IOInterposer::UnregisterCurrentThread();
   profiler_unregister_thread();
 
+#ifdef MOZ_TASK_TRACER
+  mozilla::tasktracer::FreeTraceInfo();
+#endif
+
   // We can't receive messages anymore.
   message_loop_ = NULL;
   thread_id_ = 0;
 }
 
 }  // namespace base
--- a/ipc/chromium/src/chrome/common/ipc_channel_posix.cc
+++ b/ipc/chromium/src/chrome/common/ipc_channel_posix.cc
@@ -27,16 +27,21 @@
 #include "base/singleton.h"
 #include "base/stats_counters.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/file_descriptor_set_posix.h"
 #include "chrome/common/ipc_logging.h"
 #include "chrome/common/ipc_message_utils.h"
 #include "mozilla/ipc/ProtocolUtils.h"
 
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracerImpl.h"
+using namespace mozilla::tasktracer;
+#endif
+
 namespace IPC {
 
 // IPC channels on Windows use named pipes (CreateNamedPipe()) with
 // channel ids as the pipe names.  Channels on POSIX use anonymous
 // Unix domain sockets created via socketpair() as pipes.  These don't
 // quite line up.
 //
 // When creating a child subprocess, the parent side of the fork
@@ -589,16 +594,24 @@ bool Channel::ChannelImpl::ProcessIncomi
           m.file_descriptor_set()->SetDescriptors(
               &fds[fds_i], m.header()->num_fds);
           fds_i += m.header()->num_fds;
         }
 #ifdef IPC_MESSAGE_DEBUG_EXTRA
         DLOG(INFO) << "received message on channel @" << this <<
                       " with type " << m.type();
 #endif
+
+#ifdef MOZ_TASK_TRACER
+        AutoSaveCurTraceInfo saveCurTraceInfo;
+        SetCurTraceInfo(m.header()->source_event_id,
+                        m.header()->parent_task_id,
+                        m.header()->source_event_type);
+#endif
+
         if (m.routing_id() == MSG_ROUTING_NONE &&
             m.type() == HELLO_MESSAGE_TYPE) {
           // The Hello message contains only the process id.
           listener_->OnChannelConnected(MessageIterator(m).NextInt());
 #if defined(OS_MACOSX)
         } else if (m.routing_id() == MSG_ROUTING_NONE &&
                    m.type() == RECEIVED_FDS_MESSAGE_TYPE) {
           DCHECK(m.fd_cookie() != 0);
@@ -682,16 +695,21 @@ bool Channel::ChannelImpl::ProcessOutgoi
           reinterpret_cast<int*>(CMSG_DATA(cmsg)));
       msgh.msg_controllen = cmsg->cmsg_len;
 
       msg->header()->num_fds = num_fds;
 #if defined(OS_MACOSX)
       msg->set_fd_cookie(++last_pending_fd_id_);
 #endif
     }
+#ifdef MOZ_TASK_TRACER
+    GetCurTraceInfo(&msg->header()->source_event_id,
+                    &msg->header()->parent_task_id,
+                    &msg->header()->source_event_type);
+#endif
 
     size_t amt_to_write = msg->size() - message_send_bytes_written_;
     DCHECK(amt_to_write != 0);
     const char *out_bytes = reinterpret_cast<const char*>(msg->data()) +
         message_send_bytes_written_;
 
     struct iovec iov = {const_cast<char*>(out_bytes), amt_to_write};
     msgh.msg_iov = &iov;
--- a/ipc/chromium/src/chrome/common/ipc_message.cc
+++ b/ipc/chromium/src/chrome/common/ipc_message.cc
@@ -5,30 +5,42 @@
 #include "chrome/common/ipc_message.h"
 
 #include "base/logging.h"
 #include "build/build_config.h"
 
 #if defined(OS_POSIX)
 #include "chrome/common/file_descriptor_set_posix.h"
 #endif
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracer.h"
+#endif
+
+#ifdef MOZ_TASK_TRACER
+using namespace mozilla::tasktracer;
+#endif
 
 namespace IPC {
 
 //------------------------------------------------------------------------------
 
 Message::~Message() {
 }
 
 Message::Message()
     : Pickle(sizeof(Header)) {
   header()->routing = header()->type = header()->flags = 0;
 #if defined(OS_POSIX)
   header()->num_fds = 0;
 #endif
+#ifdef MOZ_TASK_TRACER
+  header()->source_event_id = 0;
+  header()->parent_task_id = 0;
+  header()->source_event_type = SourceEventType::UNKNOWN;
+#endif
   InitLoggingVariables();
 }
 
 Message::Message(int32_t routing_id, msgid_t type, PriorityValue priority,
                  MessageCompression compression, const char* const name)
     : Pickle(sizeof(Header)) {
   header()->routing = routing_id;
   header()->type = type;
@@ -39,28 +51,38 @@ Message::Message(int32_t routing_id, msg
   header()->num_fds = 0;
 #endif
   header()->interrupt_remote_stack_depth_guess = static_cast<uint32_t>(-1);
   header()->interrupt_local_stack_depth = static_cast<uint32_t>(-1);
   header()->seqno = 0;
 #if defined(OS_MACOSX)
   header()->cookie = 0;
 #endif
+#ifdef MOZ_TASK_TRACER
+  header()->source_event_id = 0;
+  header()->parent_task_id = 0;
+  header()->source_event_type = SourceEventType::UNKNOWN;
+#endif
   InitLoggingVariables(name);
 }
 
 Message::Message(const char* data, int data_len) : Pickle(data, data_len) {
   InitLoggingVariables();
 }
 
 Message::Message(const Message& other) : Pickle(other) {
   InitLoggingVariables(other.name_);
 #if defined(OS_POSIX)
   file_descriptor_set_ = other.file_descriptor_set_;
 #endif
+#ifdef MOZ_TASK_TRACER
+  header()->source_event_id = other.header()->source_event_id;
+  header()->parent_task_id = other.header()->parent_task_id;
+  header()->source_event_type = other.header()->source_event_type;
+#endif
 }
 
 void Message::InitLoggingVariables(const char* const name) {
   name_ = name;
 #ifdef IPC_MESSAGE_LOG_ENABLED
   received_time_ = 0;
   dont_log_ = false;
   log_data_ = NULL;
@@ -68,16 +90,21 @@ void Message::InitLoggingVariables(const
 }
 
 Message& Message::operator=(const Message& other) {
   *static_cast<Pickle*>(this) = other;
   InitLoggingVariables(other.name_);
 #if defined(OS_POSIX)
   file_descriptor_set_ = other.file_descriptor_set_;
 #endif
+#ifdef MOZ_TASK_TRACER
+  header()->source_event_id = other.header()->source_event_id;
+  header()->parent_task_id = other.header()->parent_task_id;
+  header()->source_event_type = other.header()->source_event_type;
+#endif
   return *this;
 }
 
 #ifdef IPC_MESSAGE_LOG_ENABLED
 void Message::set_sent_time(int64_t time) {
   DCHECK((header()->flags & HAS_SENT_TIME_BIT) == 0);
   header()->flags |= HAS_SENT_TIME_BIT;
   WriteInt64(time);
--- a/ipc/chromium/src/chrome/common/ipc_message.h
+++ b/ipc/chromium/src/chrome/common/ipc_message.h
@@ -5,16 +5,20 @@
 #ifndef CHROME_COMMON_IPC_MESSAGE_H__
 #define CHROME_COMMON_IPC_MESSAGE_H__
 
 #include <string>
 
 #include "base/basictypes.h"
 #include "base/pickle.h"
 
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracer.h"
+#endif
+
 #ifndef NDEBUG
 #define IPC_MESSAGE_LOG_ENABLED
 #endif
 
 #if defined(OS_POSIX)
 #include "base/ref_counted.h"
 #endif
 
@@ -331,16 +335,21 @@ class Message : public Pickle {
 
       // For RPC and Urgent messages, a transaction ID for message ordering.
       int32_t txid;
     };
     // The actual local stack depth.
     uint32_t interrupt_local_stack_depth;
     // Sequence number
     int32_t seqno;
+#ifdef MOZ_TASK_TRACER
+    uint64_t source_event_id;
+    uint64_t parent_task_id;
+    mozilla::tasktracer::SourceEventType source_event_type;
+#endif
   };
 
   Header* header() {
     return headerT<Header>();
   }
   const Header* header() const {
     return headerT<Header>();
   }
--- a/tools/profiler/GeckoProfilerImpl.h
+++ b/tools/profiler/GeckoProfilerImpl.h
@@ -12,16 +12,20 @@
 #include <stdarg.h>
 #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"
+#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
 
 // Make sure that we can use std::min here without the Windows headers messing with us.
@@ -49,22 +53,28 @@ extern bool stack_key_initialized;
 # else
 #  define SAMPLE_FUNCTION_NAME __func__  // defined in C99, supported in various C++ compilers. Just raw function name.
 # endif
 #endif
 
 static inline
 void profiler_init(void* stackTop)
 {
+#ifdef MOZ_TASK_TRACER
+  mozilla::tasktracer::InitTaskTracer();
+#endif
   mozilla_sampler_init(stackTop);
 }
 
 static inline
 void profiler_shutdown()
 {
+#ifdef MOZ_TASK_TRACER
+  mozilla::tasktracer::ShutdownTaskTracer();
+#endif
   mozilla_sampler_shutdown();
 }
 
 static inline
 void profiler_start(int aProfileEntries, int aInterval,
                        const char** aFeatures, uint32_t aFeatureCount,
                        const char** aThreadNameFilters, uint32_t aFilterCount)
 {
--- a/xpcom/threads/TimerThread.cpp
+++ b/xpcom/threads/TimerThread.cpp
@@ -413,16 +413,21 @@ int32_t TimerThread::AddTimerInternal(ns
   TimerAdditionComparator c(now, aTimer);
   nsTimerImpl** insertSlot = mTimers.InsertElementSorted(aTimer, c);
 
   if (!insertSlot)
     return -1;
 
   aTimer->mArmed = true;
   NS_ADDREF(aTimer);
+
+#ifdef MOZ_TASK_TRACER
+  aTimer->DispatchTracedTask();
+#endif
+
   return insertSlot - mTimers.Elements();
 }
 
 bool TimerThread::RemoveTimerInternal(nsTimerImpl *aTimer)
 {
   if (!mTimers.RemoveElement(aTimer))
     return false;
 
--- a/xpcom/threads/nsThread.cpp
+++ b/xpcom/threads/nsThread.cpp
@@ -54,16 +54,21 @@
 #if defined(NS_FUNCTION_TIMER) && defined(_MSC_VER)
 #include "nsTimerImpl.h"
 #include "nsStackWalk.h"
 #endif
 #ifdef NS_FUNCTION_TIMER
 #include "nsCRT.h"
 #endif
 
+#ifdef MOZ_TASK_TRACER
+#include "GeckoTaskTracer.h"
+using namespace mozilla::tasktracer;
+#endif
+
 using namespace mozilla;
 
 #ifdef PR_LOGGING
 static PRLogModuleInfo *
 GetThreadLog()
 {
   static PRLogModuleInfo *sLog;
   if (!sLog)
@@ -338,16 +343,20 @@ nsThread::ThreadFunc(void *arg)
 
   // Dispatch shutdown ACK
   event = new nsThreadShutdownAckEvent(self->mShutdownContext);
   self->mShutdownContext->joiningThread->Dispatch(event, NS_DISPATCH_NORMAL);
 
   // Release any observer of the thread here.
   self->SetObserver(nullptr);
 
+#ifdef MOZ_TASK_TRACER
+  FreeTraceInfo();
+#endif
+
   NS_RELEASE(self);
 }
 
 //-----------------------------------------------------------------------------
 
 #ifdef MOZ_CANARY
 int sCanaryOutputFD = -1;
 #endif
@@ -440,25 +449,30 @@ nsThread::DispatchInternal(nsIRunnable *
 {
   if (NS_WARN_IF(!event))
     return NS_ERROR_INVALID_ARG;
 
   if (gXPCOMThreadsShutDown && MAIN_THREAD != mIsMainThread && !target) {
     return NS_ERROR_ILLEGAL_DURING_SHUTDOWN;
   }
 
+#ifdef MOZ_TASK_TRACER
+  nsRefPtr<nsIRunnable> tracedRunnable = CreateTracedRunnable(event);
+  event = tracedRunnable;
+#endif
+
   if (flags & DISPATCH_SYNC) {
     nsThread *thread = nsThreadManager::get()->GetCurrentThread();
     if (NS_WARN_IF(!thread))
       return NS_ERROR_NOT_AVAILABLE;
 
     // XXX we should be able to do something better here... we should
     //     be able to monitor the slot occupied by this event and use
     //     that to tell us when the event has been processed.
- 
+
     nsRefPtr<nsThreadSyncDispatch> wrapper =
         new nsThreadSyncDispatch(thread, event);
     if (!wrapper)
       return NS_ERROR_OUT_OF_MEMORY;
     nsresult rv = PutEvent(wrapper, target);
     // Don't wait for the event to finish if we didn't dispatch it...
     if (NS_FAILED(rv))
       return rv;
--- a/xpcom/threads/nsTimerImpl.cpp
+++ b/xpcom/threads/nsTimerImpl.cpp
@@ -499,16 +499,20 @@ NS_IMETHODIMP nsTimerImpl::SetTarget(nsI
 
 void nsTimerImpl::Fire()
 {
   if (mCanceled)
     return;
 
   PROFILER_LABEL("Timer", "Fire");
 
+#ifdef MOZ_TASK_TRACER
+  mozilla::tasktracer::AutoRunFakeTracedTask runTracedTask(mTracedTask);
+#endif
+
 #ifdef DEBUG_TIMERS
   TimeStamp now = TimeStamp::Now();
   if (PR_LOG_TEST(GetTimerLog(), PR_LOG_DEBUG)) {
     TimeDuration   a = now - mStart; // actual delay in intervals
     TimeDuration   b = TimeDuration::FromMilliseconds(mDelay); // expected delay in intervals
     TimeDuration   delta = (a > b) ? a - b : b - a;
     uint32_t       d = delta.ToMilliseconds(); // delta in ms
     sDeltaSum += d;
@@ -530,17 +534,17 @@ void nsTimerImpl::Fire()
     // Precise repeating timers advance mTimeout by mDelay without fail before
     // calling Fire().
     timeout -= TimeDuration::FromMilliseconds(mDelay);
   }
 
   if (mCallbackType == CALLBACK_TYPE_INTERFACE)
     mTimerCallbackWhileFiring = mCallback.i;
   mFiring = true;
-  
+
   // Handle callbacks that re-init the timer, but avoid leaking.
   // See bug 330128.
   CallbackUnion callback = mCallback;
   unsigned callbackType = mCallbackType;
   if (callbackType == CALLBACK_TYPE_INTERFACE)
     NS_ADDREF(callback.i);
   else if (callbackType == CALLBACK_TYPE_OBSERVER)
     NS_ADDREF(callback.o);
--- a/xpcom/threads/nsTimerImpl.h
+++ b/xpcom/threads/nsTimerImpl.h
@@ -13,16 +13,20 @@
 #include "nsIObserver.h"
 
 #include "nsCOMPtr.h"
 
 #include "prlog.h"
 #include "mozilla/TimeStamp.h"
 #include "mozilla/Attributes.h"
 
+#ifdef MOZ_TASK_TRACER
+#include "TracedTaskCommon.h"
+#endif
+
 #if defined(PR_LOGGING)
 extern PRLogModuleInfo *GetTimerLog();
 #define DEBUG_TIMERS 1
 #else
 #undef DEBUG_TIMERS
 #endif
 
 #define NS_TIMER_CID \
@@ -57,16 +61,23 @@ public:
   nsresult PostTimerEvent();
   void SetDelayInternal(uint32_t aDelay);
 
   NS_DECL_THREADSAFE_ISUPPORTS
   NS_DECL_NSITIMER
 
   int32_t GetGeneration() { return mGeneration; }
 
+#ifdef MOZ_TASK_TRACER
+  void DispatchTracedTask()
+  {
+    mTracedTask = mozilla::tasktracer::CreateFakeTracedTask(*(int**)(this));
+  }
+#endif
+
 private:
   ~nsTimerImpl();
   nsresult InitCommon(uint32_t aType, uint32_t aDelay);
 
   void ReleaseCallback()
   {
     // if we're the last owner of the callback object, make
     // sure that we don't recurse into ReleaseCallback in case
@@ -124,16 +135,20 @@ private:
   // The generation number of this timer, re-generated each time the timer is
   // initialized so one-shot timers can be canceled and re-initialized by the
   // arming thread without any bad race conditions.
   int32_t               mGeneration;
 
   uint32_t              mDelay;
   TimeStamp             mTimeout;
 
+#ifdef MOZ_TASK_TRACER
+  nsAutoPtr<mozilla::tasktracer::FakeTracedTask> mTracedTask;
+#endif
+
 #ifdef DEBUG_TIMERS
   TimeStamp             mStart, mStart2;
   static double         sDeltaSum;
   static double         sDeltaSumSquared;
   static double         sDeltaNum;
 #endif
 
 };