Add queued_time_ms trace for events in message loop

These trace can be useful for examining the status of message loop
queues when debugging some performance issues.

BUG=none

Review URL: https://chromiumcodereview.appspot.com/18083015

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@210880 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 22 insertions, 16 deletions

diff --git a/base/message_loop/message_loop.cc b/base/message_loop/message_loop.cc
index 9e33a42..96192a7 100644
--- a/base/message_loop/message_loop.cc
+++ b/base/message_loop/message_loop.cc
@@ -456,11 +456,17 @@ bool MessageLoop::ProcessNextDelayedNonNestableTask() {
 }
 
 void MessageLoop::RunTask(const PendingTask& pending_task) {
-  TRACE_EVENT_FLOW_END0("task", "MessageLoop::PostTask",
-      TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)));
+  tracked_objects::TrackedTime start_time =
+      tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
+
+  TRACE_EVENT_FLOW_END1("task", "MessageLoop::PostTask",
+      TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)),
+      "queue_duration",
+      (start_time - pending_task.EffectiveTimePosted()).InMilliseconds());
   TRACE_EVENT2("task", "MessageLoop::RunTask",
                "src_file", pending_task.posted_from.file_name(),
                "src_func", pending_task.posted_from.function_name());
+
   DCHECK(nestable_tasks_allowed_);
   // Execute the task and assume the worst: It is probably not reentrant.
   nestable_tasks_allowed_ = false;
@@ -476,9 +482,6 @@ void MessageLoop::RunTask(const PendingTask& pending_task) {
 
   HistogramEvent(kTaskRunEvent);
 
-  tracked_objects::TrackedTime start_time =
-      tracked_objects::ThreadData::NowForStartOfRun(pending_task.birth_tally);
-
   FOR_EACH_OBSERVER(TaskObserver, task_observers_,
                     WillProcessTask(pending_task));
   pending_task.task.Run();
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index c45276b..cc00ce6 100644
--- a/base/tracked_objects.cc
+++ b/base/tracked_objects.cc
@@ -465,16 +465,6 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
   if (!current_thread_data)
     return;
 
-  // To avoid conflating our stats with the delay duration in a PostDelayedTask,
-  // we identify such tasks, and replace their post_time with the time they
-  // were scheduled (requested?) to emerge from the delayed task queue. This
-  // means that queueing delay for such tasks will show how long they went
-  // unserviced, after they *could* be serviced.  This is the same stat as we
-  // have for non-delayed tasks, and we consistently call it queueing delay.
-  TrackedTime effective_post_time = completed_task.delayed_run_time.is_null()
-      ? tracked_objects::TrackedTime(completed_task.time_posted)
-      : tracked_objects::TrackedTime(completed_task.delayed_run_time);
-
   // Watch out for a race where status_ is changing, and hence one or both
   // of start_of_run or end_of_run is zero.  In that case, we didn't bother to
   // get a time value since we "weren't tracking" and we were trying to be
@@ -483,7 +473,8 @@ void ThreadData::TallyRunOnNamedThreadIfTracking(
   int32 queue_duration = 0;
   int32 run_duration = 0;
   if (!start_of_run.is_null()) {
-    queue_duration = (start_of_run - effective_post_time).InMilliseconds();
+    queue_duration = (start_of_run - completed_task.EffectiveTimePosted())
+        .InMilliseconds();
     if (!end_of_run.is_null())
       run_duration = (end_of_run - start_of_run).InMilliseconds();
   }
diff --git a/base/tracking_info.h b/base/tracking_info.h
index dacbcea..ba9585e 100644
--- a/base/tracking_info.h
+++ b/base/tracking_info.h
@@ -11,6 +11,7 @@
 #ifndef BASE_TRACKING_INFO_H_
 #define BASE_TRACKING_INFO_H_
 
+#include "base/profiler/tracked_time.h"
 #include "base/time/time.h"
 
 namespace tracked_objects {
@@ -27,6 +28,17 @@ struct BASE_EXPORT TrackingInfo {
                base::TimeTicks delayed_run_time);
   ~TrackingInfo();
 
+  // To avoid conflating our stats with the delay duration in a PostDelayedTask,
+  // we identify such tasks, and replace their post_time with the time they
+  // were scheduled (requested?) to emerge from the delayed task queue. This
+  // means that queuing delay for such tasks will show how long they went
+  // unserviced, after they *could* be serviced.  This is the same stat as we
+  // have for non-delayed tasks, and we consistently call it queuing delay.
+  tracked_objects::TrackedTime EffectiveTimePosted() const {
+    return tracked_objects::TrackedTime(
+        delayed_run_time.is_null() ? time_posted : delayed_run_time);
+  }
+
   // Record of location and thread that the task came from.
   tracked_objects::Births* birth_tally;