Add queued_time_ms trace for events in message loop

base/tracking_info.h

Index: base/tracking_info.h
diff --git a/base/tracking_info.h b/base/tracking_info.h
index dacbcea1d2b9d83a4734b5c5b21216f4cac004f7..ad9d93d86e0d7af56fb1c2848a13b0f9a98c25fd 100644
--- a/base/tracking_info.h
+++ b/base/tracking_info.h
@@ -27,6 +27,14 @@ struct BASE_EXPORT TrackingInfo {
                base::TimeTicks delayed_run_time);
   ~TrackingInfo();
 
+  base::TimeTicks ExpectedRunTime() const {
+    return delayed_run_time.is_null() ? time_posted : delayed_run_time;
+  }
+
+  base::TimeDelta DurationSinceExpectedRunTime() const {
+    return TimeTicks::Now() - ExpectedRunTime();

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

nit: Now() is generally considered an expensive call. This is not only because
it calls 64bit library code (on windows), and grabs a lock.  The lock is also a
shared lock across all threads, and can routinely cause contention (potentially
blocking a thread, increasing queueing delay... which is I think what you're
after measuring).

Usually we "try hard" to not call this repeatedly in a pass through the message
loop.  That said, I think this extra call is limited to cases where we're
Trace()ing.... so it may all be an issue only for your code.

I think that you could probably get the info you needed by hooking into the
profiler a tad deeper, and then you woudln't need to call Now().

YMMV.

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

Changed to use TrackedTime to avoid lock on Windows. Is that a correct way?

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

Yeah... that will go a lot faster.  It uses a truncated 32-bit timer... which is
more than enough to track queue delay. It gets you up around 4K seconds, or
around an hour... which is way beyond plausible queueing delay on a thread.

+  }
+
   // Record of location and thread that the task came from.
   tracked_objects::Births* birth_tally;