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..23f877f31841c79727d45e4484d1beeac76dea98 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()) {

[jar (doing other things), 2013/07/08 23:14:19]

I think that start_of_run is probably now always set (i.e., I suspect that this
was written when I had thought of turning on profiling, rather than leaving it
on all the time).  If however this is still an issue, you probably need to take
corresponding precautions as you generate your queue_duration externally.

If you wanted to avoid repeating similar logic, you *could* change this method
to return queue_duration... and propagate that up to the message loop... and
just snag that value.

Looking at how you do all this in the message loop... it looks like you really
wanted the queueing_time calculated sooner (when you used the macro), so that
might not work.  I'm not sure what other options you have... but it wouldn't
surprise me if there was a flavor of the macro that allowed you to augment an
event (being tallied) with the additional info (queueing_time).

If you decide not to do this... you should probably add a DCHECK() to validate
the assumption that we always have a start_of_run time that is real.  (...and
you could probably assign a bug for me to cleanup up profiling, now that it is
always on... I just left the code in place to allow me to test the impact (on vs
off)).

[Xianzhu, 2013/07/09 00:39:08]

Yes, we can use TRACE_EVENT_BEGIN and TRACE_EVENT_END and set the argument in
TRACE_EVENT_END. However, I just noticed the TRACE_EVENT_FLOW_END0("task",
"MessageLoop::PostTask"...) at the top of MessageLoop::RunTask. It seems better
to add the queueing_time argument to that event than TRACE_EVENT2("task",
"MessageLoop:RunTask") because the queuing_time is more related the flow between
PostTask to RunTask instead of RunTask itself. Using the TRACE_EVENT_FLOW_END we
must calculate the queueing_time there so it seems impossible to combine the
calculation with the profiler.

The small repeating similar logic looks ok to me.

Uploaded a much simpler change set as we don't need to compact the location into
one argument.
I'll file a bug for you :)

-    queue_duration = (start_of_run - effective_post_time).InMilliseconds();
+    TrackedTime effective_time_posted(completed_task.EffectiveTimePosted());
+    queue_duration = (start_of_run - effective_time_posted).InMilliseconds();
     if (!end_of_run.is_null())
       run_duration = (end_of_run - start_of_run).InMilliseconds();
   }