Add queued_time_ms trace for events in message loop

base/tracked_objects.cc

Index: base/tracked_objects.cc
diff --git a/base/tracked_objects.cc b/base/tracked_objects.cc
index c45276b04d42e2588b447890fdfa9a4c8985ee06..2698dfad4f3ca3b993a5d43a95f5106b3edf3a7d 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();
+    TrackedTime expected_run_time(completed_task.ExpectedRunTime());

[jar (doing other things), 2013/07/08 17:08:33]

Can you move across the comment that was deleted on line 468-473?

[Xianzhu, 2013/07/08 18:51:39]

Done.

+    queue_duration = (start_of_run - expected_run_time).InMilliseconds();

[jar (doing other things), 2013/07/08 17:08:33]

I'm not sure if this is a better name.

I would think "expected_run_time" would be the "time of posting" plus the
"expected queuing delay."  Sadly, that is not the intent.

This variable is more like "post time," except for the fact that the posting
time for delayed tasks was looooong ago, and not significant to calculating
queueing delay.

IMO, effective_post_time is a better name for the variable, and probably for the
method call "completed_task.EffectivePostTime()".

It might also be listed as "zero_queue_time_execution_time," but that is pretty
long... and probably more confusing.

Perhaps you have other better suggestions for the name?

[Xianzhu, 2013/07/08 18:51:39]

Realized I had missed "expected queuing delay" :)
Now use EffectiveTimePosted() to be consistent with TrackingInfo::time_posted.

     if (!end_of_run.is_null())
       run_duration = (end_of_run - start_of_run).InMilliseconds();
   }