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

RESOLVED FIXED in Firefox 55

Status

()

Core
IPC
RESOLVED FIXED
a month ago
23 days ago

People

(Reporter: mystor, Assigned: mystor)

Tracking

(Blocks: 1 bug)

unspecified
mozilla55
Points:
---

Firefox Tracking Flags

(firefox54 wontfix, firefox55 fixed)

Details

(Whiteboard: [qf:p1])

Attachments

(2 attachments, 2 obsolete attachments)

(Assignee)

Description

a month ago
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.
(Assignee)

Comment 1

a month ago
Created 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

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
Attachment #8868721 - Flags: review?(ehsan)
Attachment #8868721 - Flags: review?(benjamin)
(Assignee)

Updated

a month ago
Whiteboard: [qf]
Duplicate of this bug: 1365697
Blocks: 1331674
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?
Attachment #8868721 - Flags: review?(ehsan) → review-
(Assignee)

Comment 4

a month ago
Created 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

MozReview-Commit-ID: 4TOlSFX68Vn
Attachment #8868761 - Flags: review?(ehsan)
Attachment #8868761 - Flags: review?(benjamin)
(Assignee)

Updated

a month ago
Attachment #8868721 - Attachment is obsolete: true
Attachment #8868721 - Flags: review?(benjamin)
(Assignee)

Comment 5

a month ago
(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 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.  :-)
Attachment #8868761 - Flags: review?(ehsan) → review+
(Assignee)

Comment 7

a month ago
Created 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

MozReview-Commit-ID: 4TOlSFX68Vn
Attachment #8869086 - Flags: review?(benjamin)
(Assignee)

Updated

a month ago
Attachment #8868761 - Attachment is obsolete: true
Attachment #8868761 - Flags: review?(benjamin)
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
Attachment #8869086 - Flags: review?(benjamin) → review+
Whiteboard: [qf] → [qf:p1]

Comment 9

a month ago
Pushed by michael@thelayzells.com:
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
https://hg.mozilla.org/mozilla-central/rev/5e31f2562eb2
Status: NEW → RESOLVED
Last Resolved: a month ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Any chance you could backport this to beta please?
Flags: needinfo?(michael)
(Assignee)

Comment 12

23 days ago
Created 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

Rebased on beta

MozReview-Commit-ID: 4TOlSFX68Vn
(Assignee)

Comment 13

23 days ago
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.
Flags: needinfo?(michael)
Attachment #8874487 - Flags: approval-mozilla-beta?
We've already built RC build for 54 today and this is too late for 54. Mark 54 won't fix.
status-firefox54: --- → wontfix
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-.
Attachment #8874487 - Flags: approval-mozilla-beta? → approval-mozilla-beta-
You need to log in before you can comment on or make changes to this bug.