Closed Bug 1348426 Opened 3 years ago Closed 3 years ago

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

Categories

(Core :: DOM: Content Processes, enhancement)

enhancement
Not set

Tracking

()

RESOLVED FIXED
mozilla55
Tracking Status
firefox55 --- fixed

People

(Reporter: mstange, Assigned: mstange)

References

(Blocks 1 open bug)

Details

Attachments

(2 files)

No description provided.
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 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 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?
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 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
Attachment #8848661 - Flags: review?(wmccloskey) → review+
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.
Pushed by mstange@themasta.com:
https://hg.mozilla.org/integration/autoland/rev/42d542898d80
Add profiler labels to RecvSync/Async/RpcMessage that include the message name. r=billm
(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.
https://hg.mozilla.org/mozilla-central/rev/42d542898d80
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
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.)
You need to log in before you can comment on or make changes to this bug.