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 198426 2e0304d75739a923301d8f11759fed14113f7000
parent 198425 587ca014fdf038130f50406c7ac75805b940b4c6
child 198427 3064ab64f06ad6aedb84e326603b12a96f922eab
push id3624
push userasasaki@mozilla.com
push dateMon, 09 Jun 2014 21:49:01 +0000
treeherdermozilla-beta@b1a5da15899a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerskhuey
bugs908995
milestone31.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 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
 
 };