1333489 - Record sync IPC message timing in telemetry

Status: RESOLVED FIXED

(Core :: IPC, defect)

Description

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

We should have a histogram keyed on the message name for how long we wait for a sync IPC message.

Comment 1

[(no longer active)]

Andrew, can we please find an owner for this?  Thanks!

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

I volunteer!

Comment 3

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Just FYI, you should be able to insert instrumentation in the MessageChannel::Send overload that has two arguments. It'll probably look something like this:
http://searchfox.org/mozilla-central/source/ipc/glue/MessageChannel.cpp#1076

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Bug 1333489 - Record time spent waiting on sync IPC.

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 merancois

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.

Review commit: https://reviewboard.mozilla.org/r/108426/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/108426/

Comment 5

[François Marier [:francois]]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

https://reviewboard.mozilla.org/r/108426/#review109672

It seems like you had a copy/paste accident when you wrote the commit message :)

Comment 6

[François Marier [:francois]]

What are the possible values for the message string (i.e. the key)?

Comment 7

[(no longer active)]

The names of each IPC message.  See the IPC_MESSAGE_SIZE probe for an example.

Comment 8

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to François Marier [:francois] from comment #6)
> What are the possible values for the message string (i.e. the key)?

Stringification of function names corresponding to IPC messages. Some examples I just pulled out of the MOZ_LOG logging this patch adds:

PAPZCTreeManager::Msg_ReceiveMouseInputEvent
PAPZCTreeManager::Msg_TransformEventRefPoint
PBrowser::Msg_NotifyIMEFocus
PBrowser::Msg_SyncMessage
PCompositorBridge::Msg_FlushRendering
PCompositorBridge::Msg_PLayerTransactionConstructor
PCompositorBridge::Msg_WillClose
PContent::Msg_ClipboardHasType
PContent::Msg_GetGfxInfoFeatureStatus
PContent::Msg_GetGfxVars
PContent::Msg_GetGraphicsDeviceInitData
PContent::Msg_GetProcessAttributes
PContent::Msg_GetXPCOMProcessAttributes
PContent::Msg_PCrashReporterConstructor
PContent::Msg_PScreenManagerConstructor
PContent::Msg_ReadPermissions
PContent::Msg_ReadPrefsArray
PContent::Msg_SyncMessage
PGMPService::Msg_GetGMPNodeId
PGMPService::Msg_LaunchGMP
PGPU::Msg_AddLayerTreeIdMapping
PImageBridge::Msg_WillClose
PLayerTransaction::Msg_Update
PLayerTransaction::Msg_Update
PLayerTransaction::Msg_Update
PLayerTransaction::Msg_Update
PLayerTransaction::Msg_Update
PScreenManager::Msg_GetPrimaryScreen

Comment 9

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/108426/diff/1-2/

Comment 10

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

https://reviewboard.mozilla.org/r/108426/#review109702

::: ipc/glue/MessageChannel.cpp:133
(Diff revision 2)
>  namespace mozilla {
>  namespace ipc {
>  
>  static const uint32_t kMinTelemetryMessageSize = 8192;
>  
> +static const uint32_t kMinTelemetrySyncIPCLatency = 1;

I guess the actual cutoff is 500us due to the rounding. Might want to mention that somewhere in a comment.

::: ipc/glue/MessageChannel.cpp:1280
(Diff revision 2)
>                                nsDependentCString(msgName), aReply->size());
>      }
> +
> +    uint32_t ms = round((TimeStamp::Now() - start).ToMilliseconds());
> +    if (ms >= kMinTelemetrySyncIPCLatency) {
> +      IPC_LOG("Sent Sync IPC '%s', seqno=%d, xid=%d, in %ums", msgName,

Did you add this for a reason? Aside from the timing, it's redundant with other logging we do. If you want to keep it, I'd rather consolidate with this logging:
http://searchfox.org/mozilla-central/rev/4e0c5c460318fb9ef7d92b129ac095ce04bc4795/ipc/glue/MessageChannel.cpp#1256

::: toolkit/components/telemetry/Histograms.json:10247
(Diff revision 2)
> +    "alert_emails": ["[e-mail]"],
> +    "bug_numbers": [1333489],
> +    "expires_in_version": "60",
> +    "kind": "exponential",
> +    "high": 60000,
> +    "n_buckets": 50,

It might be nice to have fewer buckets (more like 10) to keep the ping size lower. This one measurement is going to trigger a lot of histograms (one per message). You could compensate for the loss of resolution by lowering the "high" end to something like 2 seconds. We'll still have an overflow bucket that counts the excess.

::: toolkit/components/telemetry/Histograms.json:10249
(Diff revision 2)
> +    "expires_in_version": "60",
> +    "kind": "exponential",
> +    "high": 60000,
> +    "n_buckets": 50,
> +    "keyed": true,
> +    "description": "Measures the number of milliseconds we spend waiting for sync IPC messages to finish sending, keyed by message name."

Please mention that we omit messages where the response was received in < 500us. This is important because it means we can't use this histogram to count the total number of sync messages sent.

Comment 11

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/108426/diff/2-3/

Comment 12

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

https://reviewboard.mozilla.org/r/108426/#review109702

> Did you add this for a reason? Aside from the timing, it's redundant with other logging we do. If you want to keep it, I'd rather consolidate with this logging:
> http://searchfox.org/mozilla-central/rev/4e0c5c460318fb9ef7d92b129ac095ce04bc4795/ipc/glue/MessageChannel.cpp#1256

I'll consolidate it with the existing logging.

Comment 13

[François Marier [:francois]]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

https://reviewboard.mozilla.org/r/108426/#review109778

(In reply to Chris Pearce (:cpearce) from comment #8)
> (In reply to François Marier [:francois] from comment #6)
> > What are the possible values for the message string (i.e. the key)?
> 
> Stringification of function names corresponding to IPC messages. Some
> examples I just pulled out of the MOZ_LOG logging this patch adds:

Ok good. I wanted to make sure it would not include any parameters since they could be derived from user input.

datareview+

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0ec2488aebbd
Record time spent waiting on sync IPC. r=billm,francois

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0ec2488aebbd

Comment 17

[(no longer active)]

Chris, I think we should backport this to beta to start getting telemetry data on sync IPCs more quickly.  Do you have time to prepare for an uplift?  (Michael is also in the process of changing this.... Maybe we should do both at the same time?)

Comment 18

[Chris Pearce [:cpearce (Not reading bugmail)]]

Doing both at the same time makes sense to me, given that we're renaming the probe. Can Michael do the uplift here and in bug 1337073?

Comment 19

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

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

Approval Request Comment
[Feature/Bug causing the regression]: N/a
[User impact if declined]: We would collect less important telemetry on sync IPC delays.
[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]: We would uplift this alongside bug 1337073 and bug 1343729 to get better data from the probe in beta. 
[Is the change risky?]: No
[Why is the change risky/not risky?]: Only adds a non-invasive telemetry probe to sync IPC code.
[String changes made/needed]: None

Comment 20

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8831959 [details]
Bug 1333489 - Record time spent waiting on sync IPC.

This patch should land first, then the one from bug 1343729, then bug 1337073. 
Tweaking sync telemetry for better diagnostic info.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/e7c5970badab

Comment 22

[Andrei Vaida [:avaida]]

Setting qe-verify- based on Michael's assessment on manual testing needs (see Comment 19).