1348426 - Add profiler labels that include the message name for RecvAsyncMessage and friends

Status: RESOLVED FIXED

(Core :: DOM: Content Processes, enhancement)

Description

[Markus Stange [:mstange]]

Attachment: screenshot of a profile with those labels

Comment 1

[Markus Stange [:mstange]]

Attachment: Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

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

Comment 2

[Markus Stange [:mstange]]

This patch is based on top of the one in bug 1339897.

Bill, what would be a good testcase to measure performance overhead on? The only measurable overhead should be coming from the string conversion, but I'd expect that to be minor because those strings are quite short.

Comment 3

[Markus Stange [:mstange]]

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

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

Comment 4

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

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

https://reviewboard.mozilla.org/r/121562/#review124064

It's kind of weird that you're annoting the two Send calls in TabChild, but no other Send calls. I think we should do all of them or none.

As far as a performance test, you could try sending lots of message manager messages back and forth (a ping-pong test) and measuring the rate at which they're sent. We used to have a test like this in the tree but I think it was removed. A more real-world test would probably be an add-on, but I can't think of a good one to test with.

Comment 5

[Markus Stange [:mstange]]

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

https://reviewboard.mozilla.org/r/121562/#review124064

I agree, I got a bit confused when I was instrumenting the Send calls. I'm going to drop the DoSendAsyncMessage instrumentation.
I think we should annotate sync send calls though, so I'm going to keep the annotation in DoSendBlockingMessage.
Does that sound ok?

Comment 6

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

Unfortunately you're still missing sync sends through PContent. Have a look at the patch in bug 1348113 for a good place to instrument.

Comment 7

[Markus Stange [:mstange]]

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

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

Comment 8

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

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

https://reviewboard.mozilla.org/r/121562/#review126434

Comment 9

[Markus Stange [:mstange]]

I wrote the ping-pong test and took a profile. It turns out that NS_LossyConvertUTF16toASCII is in fact an auto string, so moving that string into the SamplerStackFrameDynamicRAII's mDynamicStorage field allocates memory and does a copy.
I'm going back to having an NS_LossyConvertUTF16toASCII local variable outside of the PROFILER_LABEL_DYNAMIC call.

With that change, we spend 0.1% of my ping-pong test's time doing UTF16->ASCII conversion, and 1.7% waiting on the profiler lock in profiler_is_active_and_not_in_privacy_mode().
I'm going to file a new bug to get rid of the latter.

Comment 10

[Markus Stange [:mstange]]

Comment on attachment 8848661 [details]
Bug 1348426 - Add profiler labels to RecvSync/Async/RpcMessage that include the message name.

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

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/42d542898d80
Add profiler labels to RecvSync/Async/RpcMessage that include the message name. r=billm

Comment 12

[Markus Stange [:mstange]]

(In reply to Markus Stange [:mstange] from comment #9)
> and 1.7% waiting on the profiler lock in
> profiler_is_active_and_not_in_privacy_mode().
> I'm going to file a new bug to get rid of the latter.

I've filed bug 1351920. With that bug, the only overhead from this patch that I see in the profile is the NS_LossyConvertUTF16toASCII call, which seems to be taking 180ns per call on average, for a string of length 54.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/42d542898d80

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

I hope we are not taking the overhead when profiler isn't active...
but looks like we are.
Could we possible make the string conversion only if needed. I'm mostly worried about the extra function/ctor call there. And string dtors tend to show up in profiles too.

(Sorry, I'm right now doing bunch of micro-optimizations elsewhere in the codebase and explicitly adding useless stuff feels bad.)