1342635 - Add telemetry for IPC serialization/deserialization time

Status: RESOLVED FIXED

(Core :: IPC, defect)

Description

[(no longer active)]

See bug 1342632 for an example.  We should probably add some telemetry for this stuff to see if there are bad ones one the parent process main thread.

Comment 1

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

Do you mean async? PHttpChannelConstructor is an async message.

Comment 2

[(no longer active)]

(In reply to Bill McCloskey (:billm) from comment #1)
> Do you mean async? PHttpChannelConstructor is an async message.

Reading it from PNeckoParent::Read() still happens synchronously on the main thread.  I doubt the sync/async keyword in the IPDL syntax matters here.

Comment 3

[(no longer active)]

Thanks for rephrasing.  :-)

Comment 4

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

Attachment: Part 1: Add a telemetry probe for IPDL IPC deserialization time

This is my first pass at trying to add a telemetry probe to the IPC logic.

The way I ended up implementing it feels super gross to me, but it felt better at the time then modifying the IPDL generator to directly generate the telemetry generation code in every callsite. If that is preferable I can also easily change the code to do that.

I also tried to match local style where possible, but that seems kinda hard because it seems very inconsistent.

MozReview-Commit-ID: 8XWFWoRECrC

Comment 5

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

Attachment: Part 2: Add a telemetry probe for IPDL IPC serialzation time

MozReview-Commit-ID: Gyx4QO8f5yx

Comment 6

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

I should note that this code reports this latency on all threads. It should be easy to limit to the main thread if we want to.

Comment 7

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

Comment on attachment 8844686 [details] [diff] [review]
Part 1: Add a telemetry probe for IPDL IPC deserialization time

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

::: ipc/ipdl/ipdl/lower.py
@@ +4189,5 @@
>                                           msgexpr, ExprAddrOf(itervar),
>                                           errfn, "'%s'" % p.bareType(side).name,
>                                           sentinelKey=p.name)
>                          for p in md.params[start:] ]
> +            + [ self.endRead(msgvar, itervar, md.prettyMsgName()) ]))

Can you pass the message type instead and then use StringFromIPCMessageType to turn it to a string. That way we're guaranteed to use the exact same message name everywhere, which saves space in the binary.

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/c41ed10a2c05
Part 1: Add a telemetry probe for IPDL IPC deserialization time, r=billm
https://hg.mozilla.org/integration/mozilla-inbound/rev/2c2abaaf7529
Part 2: Add a telemetry probe for IPDL IPC serialzation time, r=billm

Comment 9

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

Comment on attachment 8844686 [details] [diff] [review]
Part 1: Add a telemetry probe for IPDL IPC deserialization time

retroactive data review because I goofed.

Comment 10

[Benjamin Smedberg]

Comment on attachment 8844686 [details] [diff] [review]
Part 1: Add a telemetry probe for IPDL IPC deserialization time

Whenever you have a keyed histogram you need to describe the key value in the histogram description. I'm guessing that this is the IPDL message name like IPC_MESSAGE_SIZE, but that needs to be explicit. Also it would be/would have been better to put this near the other IPC_MESSAGE* declarations instead of at the end.

data-r=me if this indeed the IPDL message name and you fix the description. Otherwise please I'd like to see this again.

Comment 11

[Benjamin Smedberg]

Comment on attachment 8844687 [details] [diff] [review]
Part 2: Add a telemetry probe for IPDL IPC serialzation time

ditto commentary here.

Comment 12

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

Attachment: Part 3: Update descrption of probes to mention meaning of key

MozReview-Commit-ID: DaeS4NxJyUW

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/7f6c7d78dad3
Part 3: Update descrption of probes to mention meaning of key, r=bsmedberg

Comment 14

[(no longer active)]

These probes aren't main thread only either, are they?  If not, can I be a pain and ask you to make them so?  :-)  Sorry, I thought I had mentioned it on the bug but apparently not...

Comment 15

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c41ed10a2c05
https://hg.mozilla.org/mozilla-central/rev/2c2abaaf7529
https://hg.mozilla.org/mozilla-central/rev/7f6c7d78dad3

Comment 16

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

Oops - I've filed bug 1346866 to fix that.

Comment 17

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

Comment on attachment 8844686 [details] [diff] [review]
Part 1: Add a telemetry probe for IPDL IPC deserialization time

Approval Request Comment
[Feature/Bug causing the regression]: N/A
[User impact if declined]: Not collecting useful telemetry from beta/aurora
[Is this code covered by automated tests?]: No
[Has the fix been verified in Nightly?]: In nightly
[Needs manual test from QE? If yes, steps to reproduce]: No  
[List of other uplifts needed for the feature/fix]: bug 1346866 must be uplifted after this bug
[Is the change risky?]: No
[Why is the change risky/not risky?]: Just adds a telemetry probe
[String changes made/needed]: None

Comment 18

[Gerry Chang [:gchang]]

Hi :mystor,
Just to be sure, is part1 the only patch you want uplift?

Comment 19

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

(In reply to Gerry Chang [:gchang] from comment #18)
> Hi :mystor,
> Just to be sure, is part1 the only patch you want uplift?

No, I was hoping to uplift all of the patches on this bug. In a previous bug someone complained about me adding too many flags to all of the patches on the bug so I tried to avoid doing this this time around.

Sorry that wasn't clear.

Comment 20

[Sylvestre Ledru [:Sylvestre]]

Are you sure it applies correctly, I am getting in the uplift simulation ?

Merge failed for commit c41ed10a2c05 (parent 77fdb54e3df6)

grafting 385104:c41ed10a2c05 "Bug 1342635 - Part 1: Add a telemetry probe for IPDL IPC deserialization time, r=billm"
merging ipc/chromium/src/base/pickle.cc
merging toolkit/components/telemetry/Histograms.json
warning: conflicts while merging toolkit/components/telemetry/Histograms.json! (edit, then use 'hg resolve --mark')
abort: unresolved conflicts, can't continue
(use 'hg resolve' and 'hg graft --continue')

Comment 21

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

Attachment: AURORA Part 1: Add a telemetry probe for IPDL IPC deserialization time

MozReview-Commit-ID: 8XWFWoRECrC

Comment 22

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

Attachment: AURORA Part 2: Add a telemetry probe for IPDL IPC serialzation time

MozReview-Commit-ID: Gyx4QO8f5yx

Comment 23

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

Attachment: AURORA Part 3: Update descrption of probes to mention meaning of key

MozReview-Commit-ID: DaeS4NxJyUW

Comment 24

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

Attachment: BETA Part 1: Add a telemetry probe for IPDL IPC deserialization time

MozReview-Commit-ID: 8XWFWoRECrC

Comment 25

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

Attachment: BETA Part 2: Add a telemetry probe for IPDL IPC serialzation time

MozReview-Commit-ID: Gyx4QO8f5yx

Comment 26

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

Attachment: BETA Part 3: Update descrption of probes to mention meaning of key

MozReview-Commit-ID: DaeS4NxJyUW

Comment 27

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

The rebase was very simple (I was just adding histograms to Histograms.json, and the set of histograms in aurora/beta is different than nightly). I've attached and flagged branch specific versions of each commit.

Comment 28

[Gerry Chang [:gchang]]

Comment on attachment 8848162 [details] [diff] [review]
AURORA Part 1: Add a telemetry probe for IPDL IPC deserialization time

For better collecting telemetry data. Aurora54+.

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b89e465af4d1
https://hg.mozilla.org/releases/mozilla-aurora/rev/93684501abf2
https://hg.mozilla.org/releases/mozilla-aurora/rev/cc3b9a4c673e

Comment 30

[Liz Henry (:lizzard Please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8848166 [details] [diff] [review]
BETA Part 1: Add a telemetry probe for IPDL IPC deserialization time

Sounds useful for diagnosing perf or other issues. Has data review. 
OK to uplift for the beta 6 build.

Comment 31

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-beta/rev/129cd2f7ede3
https://hg.mozilla.org/releases/mozilla-beta/rev/d2e02635c4b7
https://hg.mozilla.org/releases/mozilla-beta/rev/8710cce7e0b8