Add queued_time_ms trace for events in message loop

base/tracking_info.h

 // Copyright (c) 2012 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.
 
 // This is a simple struct with tracking information that is stored
 // with a PendingTask (when message_loop is handling the task).
 // Only the information that is shared with the profiler in tracked_objects
 // are included in this structure.
 
 
 #ifndef BASE_TRACKING_INFO_H_
 #define BASE_TRACKING_INFO_H_
 
 #include "base/time/time.h"
 
 namespace tracked_objects {
 class Location;
 class Births;
 }
 
 namespace base {
 
 // This structure is copied around by value.
 struct BASE_EXPORT TrackingInfo {
   TrackingInfo();
   TrackingInfo(const tracked_objects::Location& posted_from,
                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;
 
   // Time when the related task was posted.
   base::TimeTicks time_posted;
 
   // The time when the task should be run.
   base::TimeTicks delayed_run_time;
 };
 
 }  // namespace base
 
 #endif  // BASE_TRACKING_INFO_H_