Trace PostTasks from post to run

base/message_loop.cc

Index: base/message_loop.cc
diff --git a/base/message_loop.cc b/base/message_loop.cc
index 32994bf6527a45a4b0dea4cbdc2a8322fd848914..268c2b1d7f7ac52868525294c4e50c7e7b18f999 100644
--- a/base/message_loop.cc
+++ b/base/message_loop.cc
@@ -91,6 +91,12 @@ bool enable_histogrammer_ = false;
 
 MessageLoop::MessagePumpFactory* message_pump_for_ui_factory_ = NULL;
 
+// Create a process-wide unique ID to represent this task in trace events.
+uint64 GetTaskTraceID(const PendingTask& task, MessageLoop* loop) {
+  return (static_cast<uint64>(task.sequence_num) << 32) |
+         static_cast<uint64>(reinterpret_cast<intptr_t>(loop));

[jar (doing other things), 2012/09/13 02:14:49]

Have you considered that message loops might generally be allocated in the same
place in multiple processes?  You can hope for randomness... but most threads
start up very sequentially (while nearly single threaded), and with TCMalloc,
certain sized objects are allocated in a span for a specific size class... and
they all get allocated from the  thread local cache of the spawning thread (UI
thread?)... so... they might all be very similar, or nearly const (for a
specfiic thread, across all processes).

YMMV :-/

[jbates, 2012/09/13 17:07:01]

Yep, that's definitely a concern. To deal with pointer collisions, the process
ID is xor'd with the return value of this function (see TRACE_ID_MANGLE below).
I updated the comment on this function to make that clear.

+}
+
 }  // namespace
 
 //------------------------------------------------------------------------------
@@ -434,6 +440,8 @@ bool MessageLoop::ProcessNextDelayedNonNestableTask() {
 }
 
 void MessageLoop::RunTask(const PendingTask& pending_task) {
+  TRACE_EVENT_ASYNC_END0("base", "MessageLoop::PostTask",
+      TRACE_ID_MANGLE(GetTaskTraceID(pending_task, this)));

[jar (doing other things), 2012/09/13 02:14:49]

... and just checking... when tracing is off, this GetTaskTraceID() is *not*
called. Correct?

[jbates, 2012/09/13 17:07:01]

Exactly.

   TRACE_EVENT2("task", "MessageLoop::RunTask",
                "src_file", pending_task.posted_from.file_name(),
                "src_func", pending_task.posted_from.function_name());
@@ -482,13 +490,8 @@ bool MessageLoop::DeferOrRunPendingTask(const PendingTask& pending_task) {
 }
 
 void MessageLoop::AddToDelayedWorkQueue(const PendingTask& pending_task) {
-  // Move to the delayed work queue.  Initialize the sequence number
-  // before inserting into the delayed_work_queue_.  The sequence number
-  // is used to faciliate FIFO sorting when two tasks have the same
-  // delayed_run_time value.
-  PendingTask new_pending_task(pending_task);

[jbates, 2012/09/13 01:36:32]

Bonus: one less copy of the PendingTask struct.

-  new_pending_task.sequence_num = next_sequence_num_++;
-  delayed_work_queue_.push(new_pending_task);
+  // Move to the delayed work queue.
+  delayed_work_queue_.push(pending_task);
 }
 
 void MessageLoop::ReloadWorkQueue() {
@@ -586,6 +589,14 @@ void MessageLoop::AddToIncomingQueue(PendingTask* pending_task) {
   {
     base::AutoLock locked(incoming_queue_lock_);
 
+    // Initialize the sequence number. The sequence number is used for delayed
+    // tasks (to faciliate FIFO sorting when two tasks have the same
+    // delayed_run_time value) and for identifying the task in about:tracing.
+    pending_task->sequence_num = next_sequence_num_++;

[jar (doing other things), 2012/09/13 02:14:49]

:-) 
Cute!  You're using the incoming_queue_lock_, rather than the apartment_model
which used to restrict access to this next_sequence_num_ to take place only on
the owning thread. 

Please change the header to indicate that this is now protected by the lock.

[jbates, 2012/09/13 17:07:01]

Done.

+
+    TRACE_EVENT_ASYNC_BEGIN0("base", "MessageLoop::PostTask",
+        TRACE_ID_MANGLE(GetTaskTraceID(*pending_task, this)));
+
     bool was_empty = incoming_queue_.empty();
     incoming_queue_.push(*pending_task);
     pending_task->task.Reset();