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
--- 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,