Trace PostTasks from post to run

base/message_loop.cc

 // 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.
 
 #include "base/message_loop.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/compiler_specific.h"
@@ skipping 73 matching lines @@
   VALUE_TO_NUMBER_AND_NAME(kTaskRunEvent)
   VALUE_TO_NUMBER_AND_NAME(kTimerEvent)
 
   {-1, NULL}  // The list must be null terminated, per API to histogram.
 };
 
 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
 
 //------------------------------------------------------------------------------
 
 #if defined(OS_WIN)
 
 // Upon a SEH exception in this thread, it restores the original unhandled
 // exception filter.
 static int SEHFilter(LPTOP_LEVEL_EXCEPTION_FILTER old_filter) {
   ::SetUnhandledExceptionFilter(old_filter);
@@ skipping 323 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_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());
   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 28 matching lines @@
     return true;
   }
 
   // We couldn't run the task now because we're in a nested message loop
   // and the task isn't nestable.
   deferred_non_nestable_work_queue_.push(pending_task);
   return false;
 }
 
 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() {
   // We can improve performance of our loading tasks from incoming_queue_ to
   // work_queue_ by waiting until the last minute (work_queue_ is empty) to
   // load.  That reduces the number of locks-per-task significantly when our
   // queues get large.
   if (!work_queue_.empty())
     return;  // Wait till we *really* need to lock and load.
 
@@ skipping 77 matching lines @@
 // Possibly called on a background thread!
 void MessageLoop::AddToIncomingQueue(PendingTask* pending_task) {
   // Warning: Don't try to short-circuit, and handle this thread's tasks more
   // directly, as it could starve handling of foreign threads.  Put every task
   // into this queue.
 
   scoped_refptr<base::MessagePump> pump;
   {
     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();
     if (!was_empty)
       return;  // Someone else should have started the sub-pump.
 
     pump = pump_;
   }
   // Since the incoming_queue_ may contain a task that destroys this message
   // loop, we cannot exit incoming_queue_lock_ until we are done with |this|.
@@ skipping 169 matching lines @@
                                            Watcher *delegate) {
   return pump_libevent()->WatchFileDescriptor(
       fd,
       persistent,
       static_cast<base::MessagePumpLibevent::Mode>(mode),
       controller,
       delegate);
 }
 
 #endif