Bug 1333489 - Record time spent waiting on sync IPC. r=billm, r?francois draft
authorChris Pearce <cpearce@mozilla.com>
Tue, 31 Jan 2017 21:28:41 +1300
changeset 468648 500224a626167b446c7e3c91c7572c4d591853aa
parent 468386 676e948dc06935f4304c7fd63f42b03d5c8d4c48
child 544028 853615edcf2b22e1fd312356ad44e47bc302548e
push id43549
push usercpearce@mozilla.com
push dateTue, 31 Jan 2017 22:58:21 +0000
reviewersbillm, francois
bugs1333489
milestone54.0a1
Bug 1333489 - Record time spent waiting on sync IPC. r=billm, r?francois We're curious how long we spend waiting on sync IPCs to complete. So this patch adds telemetry which reports that, on a per message basis, so we can identify problem messages. MozReview-Commit-ID: CB4UaitPBeq
ipc/glue/MessageChannel.cpp
toolkit/components/telemetry/Histograms.json
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -12,20 +12,22 @@
 
 #include "mozilla/Assertions.h"
 #include "mozilla/DebugOnly.h"
 #include "mozilla/Move.h"
 #include "mozilla/SizePrintfMacros.h"
 #include "mozilla/Sprintf.h"
 #include "mozilla/Telemetry.h"
 #include "mozilla/Logging.h"
+#include "mozilla/TimeStamp.h"
 #include "nsAutoPtr.h"
 #include "nsDebug.h"
 #include "nsISupportsImpl.h"
 #include "nsContentUtils.h"
+#include <math.h>
 
 #ifdef MOZ_TASK_TRACER
 #include "GeckoTaskTracer.h"
 using namespace mozilla::tasktracer;
 #endif
 
 using mozilla::Move;
 
@@ -123,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 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;
 
 enum Direction
 {
     IN_MESSAGE,
@@ -1067,16 +1073,17 @@ MessageChannel::ProcessPendingRequests(A
             ProcessPendingRequest(Move(*it));
         }
     }
 }
 
 bool
 MessageChannel::Send(Message* aMsg, Message* aReply)
 {
+    mozilla::TimeStamp start = TimeStamp::Now();
     if (aMsg->size() >= kMinTelemetryMessageSize) {
         Telemetry::Accumulate(Telemetry::IPC_MESSAGE_SIZE,
                               nsDependentCString(aMsg->name()), aMsg->size());
     }
 
     nsAutoPtr<Message> msg(aMsg);
 
     // Sanity checks.
@@ -1248,32 +1255,39 @@ MessageChannel::Send(Message* aMsg, Mess
     }
 
     if (transact.IsError()) {
         IPC_LOG("Error: seqno=%d, xid=%d", seqno, transaction);
         mLastSendError = SyncSendError::ReplyError;
         return false;
     }
 
-    IPC_LOG("Got reply: seqno=%d, xid=%d", seqno, transaction);
+    uint32_t latencyMs = round((TimeStamp::Now() - start).ToMilliseconds());
+    IPC_LOG("Got reply: seqno=%d, xid=%d, msgName=%s, latency=%ums",
+            seqno, transaction, msgName, latencyMs);
 
     nsAutoPtr<Message> reply = transact.GetReply();
 
     MOZ_RELEASE_ASSERT(reply);
     MOZ_RELEASE_ASSERT(reply->is_reply(), "expected reply");
     MOZ_RELEASE_ASSERT(!reply->is_reply_error());
     MOZ_RELEASE_ASSERT(reply->seqno() == seqno);
     MOZ_RELEASE_ASSERT(reply->type() == replyType, "wrong reply type");
     MOZ_RELEASE_ASSERT(reply->is_sync());
 
     *aReply = Move(*reply);
     if (aReply->size() >= kMinTelemetryMessageSize) {
         Telemetry::Accumulate(Telemetry::IPC_REPLY_SIZE,
                               nsDependentCString(msgName), aReply->size());
     }
+
+    if (latencyMs >= kMinTelemetrySyncIPCLatencyMs) {
+      Telemetry::Accumulate(Telemetry::IPC_SYNC_LATENCY_MS,
+                            nsDependentCString(msgName), latencyMs);
+    }
     return true;
 }
 
 bool
 MessageChannel::Call(Message* aMsg, Message* aReply)
 {
     nsAutoPtr<Message> msg(aMsg);
     AssertWorkerThread();
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -10233,16 +10233,26 @@
     "bug_numbers": [1264820],
     "expires_in_version": "55",
     "kind": "exponential",
     "high": 8000000,
     "n_buckets": 50,
     "keyed": true,
     "description": "Measures the size of IPC messages by message name"
   },
+  "IPC_SYNC_LATENCY_MS": {
+    "alert_emails": ["cpearce@mozilla.com"],
+    "bug_numbers": [1333489],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 2000,
+    "n_buckets": 10,
+    "keyed": true,
+    "description": "Measures the number of milliseconds we spend waiting for sync IPC messages to finish sending, keyed by message name. Note: only messages that wait for more than 500 microseconds are included in this probe."
+  },
   "MESSAGE_MANAGER_MESSAGE_SIZE2": {
     "alert_emails": ["wmccloskey@mozilla.com","amccreight@mozilla.com"],
     "bug_numbers": [1260908],
     "expires_in_version": "55",
     "kind": "exponential",
     "low": 8192,
     "high": 8000000,
     "n_buckets": 50,