Add async trace events to trace progress of IPC messages

BUG=79942

Review URL: https://chromiumcodereview.appspot.com/10919023

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@154840 0039d316-1c4b-4281-b951-d872f2087c98

7 files changed, 45 insertions, 9 deletions

diff --git a/ipc/ipc_channel_nacl.cc b/ipc/ipc_channel_nacl.cc
index 628b8a1..0d50a57 100644
--- a/ipc/ipc_channel_nacl.cc
+++ b/ipc/ipc_channel_nacl.cc
@@ -193,6 +193,7 @@ bool Channel::ChannelImpl::Send(Message* message) {
   Logging::GetInstance()->OnSendMessage(message_ptr.get(), "");
 #endif  // IPC_MESSAGE_LOG_ENABLED
 
+  message->TraceMessageStep();
   output_queue_.push_back(linked_ptr<Message>(message_ptr.release()));
   if (!waiting_connect_)
     return ProcessOutgoingMessages();
diff --git a/ipc/ipc_channel_posix.cc b/ipc/ipc_channel_posix.cc
index 3e39534..37bc7e4 100644
--- a/ipc/ipc_channel_posix.cc
+++ b/ipc/ipc_channel_posix.cc
@@ -631,6 +631,7 @@ bool Channel::ChannelImpl::Send(Message* message) {
   Logging::GetInstance()->OnSendMessage(message, "");
 #endif  // IPC_MESSAGE_LOG_ENABLED
 
+  message->TraceMessageStep();
   output_queue_.push(message);
   if (!is_blocked_on_write_ && !waiting_connect_) {
     return ProcessOutgoingMessages();
diff --git a/ipc/ipc_channel_proxy.cc b/ipc/ipc_channel_proxy.cc
index 0b2338c..630b0cf 100644
--- a/ipc/ipc_channel_proxy.cc
+++ b/ipc/ipc_channel_proxy.cc
@@ -351,6 +351,7 @@ void ChannelProxy::Close() {
 
 bool ChannelProxy::Send(Message* message) {
   DCHECK(did_init_);
+  message->TraceMessageStep();
   if (outgoing_message_filter())
     message = outgoing_message_filter()->Rewrite(message);
 
diff --git a/ipc/ipc_channel_reader.cc b/ipc/ipc_channel_reader.cc
index a8761cd..8e8b6a65 100644
--- a/ipc/ipc_channel_reader.cc
+++ b/ipc/ipc_channel_reader.cc
@@ -69,6 +69,7 @@ bool ChannelReader::DispatchInputData(const char* input_data,
       if (!WillDispatchInputMessage(&m))
         return false;
 
+      m.TraceMessageStep();
       if (IsHelloMessage(m))
         HandleHelloMessage(m);
       else
diff --git a/ipc/ipc_channel_win.cc b/ipc/ipc_channel_win.cc
index c4098f0..77ea64c 100644
--- a/ipc/ipc_channel_win.cc
+++ b/ipc/ipc_channel_win.cc
@@ -88,6 +88,7 @@ bool Channel::ChannelImpl::Send(Message* message) {
   Logging::GetInstance()->OnSendMessage(message, "");
 #endif
 
+  message->TraceMessageStep();
   output_queue_.push(message);
   // ensure waiting to write
   if (!waiting_connect_) {
diff --git a/ipc/ipc_message.cc b/ipc/ipc_message.cc
index 9908bc7..cf3a65e 100644
--- a/ipc/ipc_message.cc
+++ b/ipc/ipc_message.cc
@@ -4,6 +4,7 @@
 
 #include "ipc/ipc_message.h"
 
+#include "base/atomicops.h"
 #include "base/logging.h"
 #include "build/build_config.h"
 
@@ -11,6 +12,26 @@
 #include "ipc/file_descriptor_set_posix.h"
 #endif
 
+namespace {
+
+base::subtle::Atomic32 g_ref_num = 0;
+
+// Create a reference number for identifying IPC messages in traces. The return
+// values has the reference number stored in the upper 24 bits, leaving the low
+// 8 bits set to 0 for use as flags.
+inline uint32 GetRefNumUpper24() {
+  base::debug::TraceLog* trace_log = base::debug::TraceLog::GetInstance();
+  int32 pid = trace_log ? trace_log->process_id() : 0;
+  int32 count = base::subtle::NoBarrier_AtomicIncrement(&g_ref_num, 1);
+  // The 24 bit hash is composed of 14 bits of the count and 10 bits of the
+  // Process ID. With the current trace event buffer cap, the 14-bit count did
+  // not appear to wrap during a trace. Note that it is not a big deal if
+  // collisions occur, as this is only used for debugging and trace analysis.
+  return ((pid << 14) | (count & 0x3fff)) << 8;
+}
+
+}  // namespace
+
 namespace IPC {
 
 //------------------------------------------------------------------------------
@@ -20,7 +41,8 @@ Message::~Message() {
 
 Message::Message()
     : Pickle(sizeof(Header)) {
-  header()->routing = header()->type = header()->flags = 0;
+  header()->routing = header()->type = 0;
+  header()->flags = GetRefNumUpper24();
 #if defined(OS_POSIX)
   header()->num_fds = 0;
   header()->pad = 0;
@@ -32,7 +54,8 @@ Message::Message(int32 routing_id, uint32 type, PriorityValue priority)
     : Pickle(sizeof(Header)) {
   header()->routing = routing_id;
   header()->type = type;
-  header()->flags = priority;
+  DCHECK((priority & 0xffffff00) == 0);
+  header()->flags = priority | GetRefNumUpper24();
 #if defined(OS_POSIX)
   header()->num_fds = 0;
   header()->pad = 0;
diff --git a/ipc/ipc_message.h b/ipc/ipc_message.h
index 4603f09..1a2a45c 100644
--- a/ipc/ipc_message.h
+++ b/ipc/ipc_message.h
@@ -8,6 +8,7 @@
 #include <string>
 
 #include "base/basictypes.h"
+#include "base/debug/trace_event.h"
 #include "base/pickle.h"
 #include "ipc/ipc_export.h"
 
@@ -49,14 +50,16 @@ class IPC_EXPORT Message : public Pickle {
   };
 
   // Bit values used in the flags field.
+  // Upper 24 bits of flags store a reference number, so this enum is limited to
+  // 8 bits.
   enum {
-    PRIORITY_MASK     = 0x0003,  // Low 2 bits of store the priority value.
-    SYNC_BIT          = 0x0004,
-    REPLY_BIT         = 0x0008,
-    REPLY_ERROR_BIT   = 0x0010,
-    UNBLOCK_BIT       = 0x0020,
-    PUMPING_MSGS_BIT  = 0x0040,
-    HAS_SENT_TIME_BIT = 0x0080,
+    PRIORITY_MASK     = 0x03,  // Low 2 bits of store the priority value.
+    SYNC_BIT          = 0x04,
+    REPLY_BIT         = 0x08,
+    REPLY_ERROR_BIT   = 0x10,
+    UNBLOCK_BIT       = 0x20,
+    PUMPING_MSGS_BIT  = 0x40,
+    HAS_SENT_TIME_BIT = 0x80,
   };
 
   virtual ~Message();
@@ -221,6 +224,11 @@ class IPC_EXPORT Message : public Pickle {
   bool dont_log() const { return dont_log_; }
 #endif
 
+  // Called at various points between send and receive to track message.
+  void TraceMessageStep() {
+    TRACE_EVENT_ASYNC_BEGIN_STEP0("ipc", "IPC", header()->flags, NULL);
+  }
+
  protected:
   friend class Channel;
   friend class MessageReplyDeserializer;