Bug 1365719 - Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg, r=ehsan
authorMichael Layzell <michael@thelayzells.com>
Wed, 17 May 2017 15:38:59 -0400
changeset 409081 5e31f2562eb265f189df39ae27c81f00f91d7cf3
parent 409080 94a6ef48ce1ab09cb328d8745ba18c167ea64a28
child 409082 01e588f75f63f44b4ba599450d495751dcc64877
push id7391
push usermtabara@mozilla.com
push dateMon, 12 Jun 2017 13:08:53 +0000
treeherdermozilla-beta@2191d7f87e2e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersehsan
bugs1365719
milestone55.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 1365719 - Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg, r=ehsan MozReview-Commit-ID: 4TOlSFX68Vn
ipc/glue/MessageChannel.cpp
toolkit/components/telemetry/Histograms.json
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -133,16 +133,18 @@ namespace ipc {
 static const uint32_t kMinTelemetryMessageSize = 4096;
 
 // 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.
+// This is used for both the sending and receiving side telemetry for sync IPC,
+// (IPC_SYNC_MAIN_LATENCY_MS and IPC_SYNC_RECEIVE_MS).
 static const uint32_t kMinTelemetrySyncIPCLatencyMs = 1;
 
 const int32_t MessageChannel::kNoTimeout = INT32_MIN;
 
 // static
 bool MessageChannel::sIsPumpingMessages = false;
 
 enum Direction
@@ -2014,32 +2016,41 @@ MessageChannel::DispatchMessage(Message 
     }
 }
 
 void
 MessageChannel::DispatchSyncMessage(const Message& aMsg, Message*& aReply)
 {
     AssertWorkerThread();
 
+    mozilla::TimeStamp start = TimeStamp::Now();
+
     int nestedLevel = aMsg.nested_level();
 
     MOZ_RELEASE_ASSERT(nestedLevel == IPC::Message::NOT_NESTED || NS_IsMainThread());
 #ifdef MOZ_TASK_TRACER
     AutoScopedLabel autolabel("sync message %s", aMsg.name());
 #endif
 
     MessageChannel* dummy;
     MessageChannel*& blockingVar = mSide == ChildSide && NS_IsMainThread() ? gParentProcessBlocker : dummy;
 
     Result rv;
     {
         AutoSetValue<MessageChannel*> blocked(blockingVar, this);
         rv = mListener->OnMessageReceived(aMsg, aReply);
     }
 
+    uint32_t latencyMs = round((TimeStamp::Now() - start).ToMilliseconds());
+    if (latencyMs >= kMinTelemetrySyncIPCLatencyMs) {
+        Telemetry::Accumulate(Telemetry::IPC_SYNC_RECEIVE_MS,
+                              nsDependentCString(aMsg.name()),
+                              latencyMs);
+    }
+
     if (!MaybeHandleError(rv, aMsg, "DispatchSyncMessage")) {
         aReply = new Message();
         aReply->set_sync();
         aReply->set_nested_level(aMsg.nested_level());
         aReply->set_reply();
         aReply->set_reply_error();
     }
     aReply->set_seqno(aMsg.seqno());
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13228,10 +13228,22 @@
     "alert_emails": ["jwwang@mozilla.com"],
     "expires_in_version": "57",
     "kind": "exponential",
     "low": 1000,
     "high": 100000,
     "n_buckets": 100,
     "bug_numbers": [1366640],
     "description": "Time (ms) VideoFrameContainer::ClearFutureFrames spent holding a lock."
+  },
+  "IPC_SYNC_RECEIVE_MS": {
+    "record_in_processes": ["main", "content", "gpu"],
+    "alert_emails": ["michael@thelayzells.com"],
+    "bug_numbers": [1365719],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "low": 32,
+    "high": 750,
+    "n_buckets": 40,
+    "keyed": true,
+    "description": "Measures the number of milliseconds we spend processing sync IPC messages in the receiving process, keyed by message name. Note: only messages that take over 500 microseconds are included in this probe."
   }
 }