Add queued_time_ms trace for events in message loop

base/message_loop/message_loop.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/message_loop/message_loop.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/compiler_specific.h"
@@ skipping 438 matching lines @@
     return false;
 
   PendingTask pending_task = deferred_non_nestable_work_queue_.front();
   deferred_non_nestable_work_queue_.pop();
 
   RunTask(pending_task);
   return true;
 }
 
 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());
   DCHECK(nestable_tasks_allowed_);
   // Execute the task and assume the worst: It is probably not reentrant.
   nestable_tasks_allowed_ = false;
 
   // Before running the task, store the program counter where it was posted
   // and deliberately alias it to ensure it is on the stack if the task
   // crashes. Be careful not to assume that the variable itself will have the
@@ skipping 354 matching lines @@
       fd,
       persistent,
       mode,
       controller,
       delegate);
 }
 
 #endif
 
 }  // namespace base