1365719 - Collect a telemetry probe for how long we spend processing sync IPC messages

Status: RESOLVED FIXED

(Core :: IPC, enhancement)

Description

[Nika Layzell [:nika] (ni? for response)]

We already have a telemetry probe for how much time we spend waiting on sync IPC messages in the sender process on the main thread, but we don't yet have a probe for how long we spend on the receiving end actually processing these messages. 

This patch adds a new probe, IPC_SYNC_MAIN_PROCESS_MS which records how long it takes to process a sync IPC on the receiving end. This will help us figure out how much of the sync IPC latency for a particular message is caused by overhead of round-trips and waiting for the main thread to become free, versus actual processing time in the remote process.

Comment 1

[Nika Layzell [:nika] (ni? for response)]

Attachment: Add a IPC_SYNC_MAIN_PROCESS_MS probe to record time taken to process sync IPC messages in the target process

This patch should add the probe in the simplest place I could think of, within MessageChannel::DispatchSyncMessage.

This doesn't cover interrupt messages, but neither does the IPC_SYNC_MAIN_LATENCY_MS probe, so I figure that that is OK.

Not the biggest fan of the name, but it works.

MozReview-Commit-ID: 4TOlSFX68Vn

Comment 3

[(no longer active)]

Comment on attachment 8868721 [details] [diff] [review]
Add a IPC_SYNC_MAIN_PROCESS_MS probe to record time taken to process sync IPC messages in the target process

Review of attachment 8868721 [details] [diff] [review]:
-----------------------------------------------------------------

::: ipc/glue/MessageChannel.cpp
@@ +2013,5 @@
>          rv = mListener->OnMessageReceived(aMsg, aReply);
>      }
>  
> +    uint32_t latencyMs = round((TimeStamp::Now() - start).ToMilliseconds());
> +    if (NS_IsMainThread() && latencyMs >= kMinTelemetrySyncIPCLatencyMs) {

Two points here:

1. See my comment about the main-thread-ness here.  I think we shouldn't check that here at all.  No matter what thread the receiving end is on, we should be collecting this telemetry, I think.  (It would've been nice if we could know where the source is coming from, but that requires too much magic!)

2. Do you mind changing the comment for kMinTelemetrySyncIPCLatencyMs to make it say that the constant also controls what happens on the receiving end?

::: toolkit/components/telemetry/Histograms.json
@@ +13001,5 @@
>      "n_buckets": 100,
>      "bug_numbers": [1345540],
>      "description": "Time (ms) for the APZ handled wheel event spent in handlers."
> +  },
> +  "IPC_SYNC_MAIN_PROCESS_MS": {

How about calling it IPC_SYNC_RECEIVE_MS?  One thing to note is that for this probe, we can't really detect whether the source of the message was the main thread or some other thread, so dropping the MAIN from the name is probably a good idea.

@@ +13002,5 @@
>      "bug_numbers": [1345540],
>      "description": "Time (ms) for the APZ handled wheel event spent in handlers."
> +  },
> +  "IPC_SYNC_MAIN_PROCESS_MS": {
> +    "record_in_processes": ["main", "content"],

The target of these messages can be any process, for example the GPU process.

@@ +13009,5 @@
> +    "expires_in_version": "60",
> +    "kind": "exponential",
> +    "low": 32,
> +    "high": 750,
> +    "n_buckets": 40,

I'd assume you're using the same bucketing as the send probe?

Comment 4

[Nika Layzell [:nika] (ni? for response)]

Attachment: Add a IPC_SYNC_MAIN_PROCESS_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

MozReview-Commit-ID: 4TOlSFX68Vn

Comment 5

[Nika Layzell [:nika] (ni? for response)]

(In reply to :Ehsan Akhgari (super long backlog, slow to respond) from comment #3)
> I'd assume you're using the same bucketing as the send probe?

yes, this is the same bucketing as IPC_SYNC_MAIN_LATENCY_MS

Comment 6

[(no longer active)]

Comment on attachment 8868761 [details] [diff] [review]
Add a IPC_SYNC_MAIN_PROCESS_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

Review of attachment 8868761 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks!

::: toolkit/components/telemetry/Histograms.json
@@ +13001,5 @@
>      "n_buckets": 100,
>      "bug_numbers": [1345540],
>      "description": "Time (ms) for the APZ handled wheel event spent in handlers."
> +  },
> +  "IPC_SYNC_PROCESS_MS": {

I still think you should call this IPC_SYNC_RECEIVE_MS.  :-)

Comment 7

[Nika Layzell [:nika] (ni? for response)]

Attachment: Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

MozReview-Commit-ID: 4TOlSFX68Vn

Comment 8

[Benjamin Smedberg]

Comment on attachment 8869086 [details] [diff] [review]
Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

data-r=me I did not review the code

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/5e31f2562eb2
Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg, r=ehsan

Comment 10

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/5e31f2562eb2

Comment 11

[(no longer active)]

Any chance you could backport this to beta please?

Comment 12

[Nika Layzell [:nika] (ni? for response)]

Attachment: BETA - Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

Rebased on beta

MozReview-Commit-ID: 4TOlSFX68Vn

Comment 13

[Nika Layzell [:nika] (ni? for response)]

Comment on attachment 8874487 [details] [diff] [review]
BETA - Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

Approval Request Comment
[Feature/Bug causing the regression]: None
[User impact if declined]: Less telemetry collection on beta
[Is this code covered by automated tests?]: No
[Has the fix been verified in Nightly?]: Yes
[Needs manual test from QE? If yes, steps to reproduce]: No
[List of other uplifts needed for the feature/fix]: None
[Is the change risky?]: No
[Why is the change risky/not risky?]:only adds a telemetry probe which has already been in Nightly for a while
[String changes made/needed]: None.

Comment 14

[Gerry Chang [:gchang]]

We've already built RC build for 54 today and this is too late for 54. Mark 54 won't fix.

Comment 15

[Gerry Chang [:gchang]]

Comment on attachment 8874487 [details] [diff] [review]
BETA - Add a IPC_SYNC_RECEIVE_MS probe to record time taken to process sync IPC messages in the target process, dr=bsmedberg

Per comment #14, Beta54-.