Bug 1333489 - Record time spent waiting on sync IPC. r=billm,francois
authorChris Pearce <cpearce@mozilla.com>
Tue, 31 Jan 2017 21:28:41 +1300
changeset 331904 0ec2488aebbd2f493cb72b99086bf080337189d9
parent 331903 931cbdebf471a80bddf8d834093c5ea6601e87c5
child 331905 be78084e5b72d1f118dc9419a0303072d6cd9ae0
push id31290
push usercbook@mozilla.com
push dateWed, 01 Feb 2017 12:11:06 +0000
treeherdermozilla-central@ae91b2b5bb69 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersbillm, francois
bugs1333489
milestone54.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1333489 - Record time spent waiting on sync IPC. r=billm,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
@@ -10310,16 +10310,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,