Closed Bug 1365719 Opened 8 years ago Closed 7 years ago

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

Categories

(Core :: IPC, enhancement)

enhancement
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla55
Performance Impact high
Tracking Status
firefox54 --- wontfix
firefox55 --- fixed

People

(Reporter: nika, Assigned: nika)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 2 obsolete files)

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.
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)
Whiteboard: [qf]
Blocks: SyncIPC
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-
Attachment #8868721 - Attachment is obsolete: true
Attachment #8868721 - Flags: review?(benjamin)
(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+
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]
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
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Any chance you could backport this to beta please?
Flags: needinfo?(michael)
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.
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-
Performance Impact: --- → P1
Whiteboard: [qf:p1]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: