Add queued_time_ms trace for events in message loop

base/message_loop/message_loop.cc

Index: base/message_loop/message_loop.cc
diff --git a/base/message_loop/message_loop.cc b/base/message_loop/message_loop.cc
index 9e33a426eb9f1241be625c25aee1a1585898c6fc..b4d72a4461b5335f0c556ec2ab97d61153b77833 100644
--- a/base/message_loop/message_loop.cc
+++ b/base/message_loop/message_loop.cc
@@ -456,8 +456,12 @@ bool MessageLoop::ProcessNextDelayedNonNestableTask() {
 }
 
 void MessageLoop::RunTask(const PendingTask& pending_task) {
-  TRACE_EVENT_FLOW_END0("task", "MessageLoop::PostTask",
-      TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)));
+  TRACE_EVENT_FLOW_END1("task", "MessageLoop::PostTask",
+      TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)),
+      "queue_duration",
+      (tracked_objects::TrackedTime::Now() -

[jar (doing other things), 2013/07/09 16:50:53]

I believe that we get the value of Now() on line 483 below.  If you relocated
this pair of events down to line 485, you could use that value directly.

In truth, you've switched to use the TrackedTime flavor of Now(), so it is not
as expensive as Time::Now().

On the other hand, I don't see any time consuming functions that you'd be
bypassing.... and using the same value of Now() will cause your stats to align
with the profiler's.

I might also be convinced to move line 483 up above line 459, to give you access
to it another way.

[Xianzhu, 2013/07/09 17:22:43]

Done.

I had been afraid that sometimes TrackedObject::Now() would return null before
you confirmed that the profiler will be always on.

+          tracked_objects::TrackedTime(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());