Bug 1342635 - Part 2: Add a telemetry probe for IPDL IPC serialzation time, r=billm a=lizzard
authorMichael Layzell <michael@thelayzells.com>
Thu, 16 Mar 2017 11:12:00 +0100
changeset 379211 d2e02635c4b74fca297926bb6a9e5e114faef4cb
parent 379210 129cd2f7ede3c7b3bc36aa802be201d07bc154c7
child 379212 8710cce7e0b851707e209b11c3c9c9108426d6b9
push id1419
push userjlund@mozilla.com
push dateMon, 10 Apr 2017 20:44:07 +0000
treeherdermozilla-release@5e6801b73ef6 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbillm, lizzard
bugs1342635
milestone53.0
Bug 1342635 - Part 2: Add a telemetry probe for IPDL IPC serialzation time, r=billm a=lizzard MozReview-Commit-ID: Gyx4QO8f5yx
ipc/chromium/src/chrome/common/ipc_message.cc
ipc/chromium/src/chrome/common/ipc_message.h
ipc/glue/MessageChannel.cpp
ipc/ipdl/ipdl/lower.py
toolkit/components/telemetry/Histograms.json
--- a/ipc/chromium/src/chrome/common/ipc_message.cc
+++ b/ipc/chromium/src/chrome/common/ipc_message.cc
@@ -50,17 +50,17 @@ Message::Message()
                     &_header->parent_task_id,
                     &_header->source_event_type);
   }
 #endif
   InitLoggingVariables();
 }
 
 Message::Message(int32_t routing_id, msgid_t type, NestedLevel nestedLevel, PriorityValue priority,
-                 MessageCompression compression, const char* const aName)
+                 MessageCompression compression, const char* const aName, bool recordWriteLatency)
     : Pickle(MSG_HEADER_SZ) {
   MOZ_COUNT_CTOR(IPC::Message);
   header()->routing = routing_id;
   header()->type = type;
   header()->flags = nestedLevel;
   if (priority == HIGH_PRIORITY)
     header()->flags |= PRIO_BIT;
   if (compression == COMPRESSION_ENABLED)
@@ -80,16 +80,19 @@ Message::Message(int32_t routing_id, msg
   if (UseTaskTracerHeader()) {
     header()->flags |= TASKTRACER_BIT;
     HeaderTaskTracer* _header = static_cast<HeaderTaskTracer*>(header());
     GetCurTraceInfo(&_header->source_event_id,
                     &_header->parent_task_id,
                     &_header->source_event_type);
   }
 #endif
+  if (recordWriteLatency) {
+    create_time_ = mozilla::TimeStamp::Now();
+  }
   InitLoggingVariables(aName);
 }
 
 #ifndef MOZ_TASK_TRACER
 #define MSG_HEADER_SZ_DATA sizeof(Header)
 #else
 #define MSG_HEADER_SZ_DATA                                            \
   (reinterpret_cast<const Header*>(data)->flags & TASKTRACER_BIT ?  \
--- a/ipc/chromium/src/chrome/common/ipc_message.h
+++ b/ipc/chromium/src/chrome/common/ipc_message.h
@@ -6,16 +6,17 @@
 
 #ifndef CHROME_COMMON_IPC_MESSAGE_H__
 #define CHROME_COMMON_IPC_MESSAGE_H__
 
 #include <string>
 
 #include "base/basictypes.h"
 #include "base/pickle.h"
+#include "mozilla/TimeStamp.h"
 
 #ifdef MOZ_TASK_TRACER
 #include "GeckoTaskTracer.h"
 #endif
 
 #if defined(OS_POSIX)
 #include "nsAutoPtr.h"
 #endif
@@ -56,22 +57,26 @@ class Message : public Pickle {
   };
 
   virtual ~Message();
 
   Message();
 
   // Initialize a message with a user-defined type, priority value, and
   // destination WebView ID.
+  //
+  // NOTE: `recordWriteLatency` is only passed by IPDL generated message code,
+  // and is used to trigger the IPC_WRITE_LATENCY_MS telemetry.
   Message(int32_t routing_id,
           msgid_t type,
           NestedLevel nestedLevel = NOT_NESTED,
           PriorityValue priority = NORMAL_PRIORITY,
           MessageCompression compression = COMPRESSION_NONE,
-          const char* const name="???");
+          const char* const name="???",
+          bool recordWriteLatency=false);
 
   Message(const char* data, int data_len);
 
   Message(const Message& other) = delete;
   Message(Message&& other);
   Message& operator=(const Message& other) = delete;
   Message& operator=(Message&& other);
 
@@ -193,16 +198,20 @@ class Message : public Pickle {
   const char* name() const {
     return name_;
   }
 
   void set_name(const char* const aName) {
     name_ = aName;
   }
 
+  const mozilla::TimeStamp& create_time() const {
+    return create_time_;
+  }
+
 #if defined(OS_POSIX)
   uint32_t num_fds() const;
 #endif
 
   template<class T>
   static bool Dispatch(const Message* msg, T* obj, void (T::*func)()) {
     (obj->*func)();
     return true;
@@ -391,16 +400,18 @@ class Message : public Pickle {
   }
   const FileDescriptorSet* file_descriptor_set() const {
     return file_descriptor_set_.get();
   }
 #endif
 
   const char* name_;
 
+  mozilla::TimeStamp create_time_;
+
 };
 
 class MessageInfo {
 public:
     typedef uint32_t msgid_t;
 
     explicit MessageInfo(const Message& aMsg)
         : mSeqno(aMsg.seqno()), mType(aMsg.type()) {}
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -125,16 +125,20 @@ using mozilla::MonitorAutoUnlock;
 
 static MessageChannel* gParentProcessBlocker;
 
 namespace mozilla {
 namespace ipc {
 
 static const uint32_t kMinTelemetryMessageSize = 8192;
 
+// Note: we round the time we spend to the nearest millisecond. So a min value
+// of 1 ms actually captures from 500us and above.
+static const uint32_t kMinTelemetryIPCWriteLatencyMs = 1;
+
 // Note: we round the time we spend waiting for a response to the nearest
 // millisecond. So a min value of 1 ms actually captures from 500us and above.
 static const uint32_t kMinTelemetrySyncIPCLatencyMs = 1;
 
 const int32_t MessageChannel::kNoTimeout = INT32_MIN;
 
 // static
 bool MessageChannel::sIsPumpingMessages = false;
@@ -776,16 +780,28 @@ MessageChannel::Echo(Message* aMsg)
 bool
 MessageChannel::Send(Message* aMsg)
 {
     if (aMsg->size() >= kMinTelemetryMessageSize) {
         Telemetry::Accumulate(Telemetry::IPC_MESSAGE_SIZE,
                               nsDependentCString(aMsg->name()), aMsg->size());
     }
 
+    // If the message was created by the IPC bindings, the create time will be
+    // recorded. Use this information to report the IPC_WRITE_LATENCY_MS (time
+    // from message creation to it being sent).
+    if (aMsg->create_time()) {
+        uint32_t latencyMs = round((mozilla::TimeStamp::Now() - aMsg->create_time()).ToMilliseconds());
+        if (latencyMs >= kMinTelemetryIPCWriteLatencyMs) {
+            mozilla::Telemetry::Accumulate(mozilla::Telemetry::IPC_WRITE_LATENCY_MS,
+                                           nsDependentCString(aMsg->name()),
+                                           latencyMs);
+        }
+    }
+
     MOZ_RELEASE_ASSERT(!aMsg->is_sync());
     MOZ_RELEASE_ASSERT(aMsg->nested_level() != IPC::Message::NESTED_INSIDE_SYNC);
 
     CxxStackFrame frame(*this, OUT_MESSAGE, aMsg);
 
     nsAutoPtr<Message> msg(aMsg);
     AssertWorkerThread();
     mMonitor->AssertNotCurrentThreadOwns();
--- a/ipc/ipdl/ipdl/lower.py
+++ b/ipc/ipdl/ipdl/lower.py
@@ -1751,17 +1751,19 @@ def _generateMessageConstructor(clsname,
 
     func.addstmt(
         StmtReturn(ExprNew(Type('IPC::Message'),
                            args=[ routingId,
                                   ExprVar(msgid),
                                   ExprVar(nestedEnum),
                                   ExprVar(prioEnum),
                                   compression,
-                                  ExprLiteral.String(prettyName) ])))
+                                  ExprLiteral.String(prettyName),
+                                  # Pass `true` to recordWriteLatency to collect telemetry
+                                  ExprLiteral.TRUE ])))
 
     return func
 
 ##--------------------------------------------------
 
 class _ComputeTypeDeps(TypeVisitor):
     '''Pass that gathers the C++ types that a particular IPDL type
 (recursively) depends on.  There are two kinds of dependencies: (i)
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -10962,10 +10962,20 @@
     "alert_emails": ["mlayzell@mozilla.com"],
     "bug_numbers": [1342635],
     "expires_in_version": "60",
     "kind": "exponential",
     "high": 500,
     "n_buckets": 20,
     "keyed": true,
     "description": "Measures the number of milliseconds we spend waiting for IPC messages to deserialize their parameters. Note: only messages that take more than 500 microseconds are included in this probe."
+  },
+  "IPC_WRITE_LATENCY_MS": {
+    "alert_emails": ["mlayzell@mozilla.com"],
+    "bug_numbers": [1342635],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 500,
+    "n_buckets": 20,
+    "keyed": true,
+    "description": "Measures the number of milliseconds we spend waiting for IPC messages to serialize their parameters. Note: only messages that take more than 500 microseconds are included in this probe."
   }
 }