1829395 - There are some slow profiler markers in PresShell::DoFlushPendingNotifications

Status: NEW

(Core :: Gecko Profiler, enhancement, P1)

Description

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

https://searchfox.org/mozilla-central/rev/a4fb94aab371d8650d194558c77879f5b8842380/layout/base/PresShell.cpp#4193,4217-4224,4338-4339
(you may need to scroll down a bit to see the AutoProfilerStyleMarker, which has implementation which seems to call TimeStamp::Now() always)

The markers show up in non-Firefox-profiler-profiles. They shouldn't.

Comment 1

[Julien Wajsberg [:julienw]]

You highlighted some frame labels as well, is that also appearing in your non Firefox profiler profiles?

Comment 2

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

AUTO_PROFILER_LABEL_DYNAMIC_CSTR_NONSENSITIVE is less clear, but at least based on code inspection, it does non-trivial things, so if the other part is optimized out, I'd optimize also that, if it is easy.

Comment 3

[Julien Wajsberg [:julienw]]

Hey Olli,
we'll fix the AutoProfilerStyleMarker for sure, but we're not sure about the other things you highlighted. It doesn't look like they're doing a lot of work. Can you pinpoint the code that you think isn't trivial?

Comment 4

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Hey Adam, could you take a look at this bug? Here are some examples: Bug 1807015 and Bug 1807011

Comment 5

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

AutoProfilerStyleMarker is probably the slowest one, but also AUTO_PROFILER_MARKER_TEXT seems to do things like assigning a string value. It would be nice if markers did nothing when the profiler isn't running.

Comment 6

[Markus Stange [:mstange]]

This shows up in the "Editor-CodeMirror" test under Node.insertBefore: https://share.firefox.dev/3Y11exq

Comment 7

[Florian Quèze [:florian]]

(In reply to Markus Stange [:mstange] from comment #6)

This shows up in the "Editor-CodeMirror" test under Node.insertBefore: https://share.firefox.dev/3Y11exq

Thanks for the profile!

Most of the cost is in allocating and freeing the nsCString. If instead of assigning the mText member of AutoProfilerTextMarker here we did it within the profiler_is_active_and_unpaused() block, that would likely save most of the time, and not just for this specific marker.

Alternatively, we could change mText to be on the stack (nsAutoCString instead of nsCString), that would also remove the allocation.

Looking at this specific marker, the profile also shows 3 samples in nsTDependentString::nsTDependentString, which is https://searchfox.org/mozilla-central/rev/8d43262674d6c6d469b821cca579b1240ebb42a5/layout/base/PresShell.cpp#4209.
We could save that too by using a custom marker schema, that would take the flush type as a parameter, instead of the string of the flush type name.

Markus, do you have a preference?

Comment 8

[Markus Stange [:mstange]]

Thanks for taking a look! I prefer the second option for this particular case, because it'll remove more samples. But your first suggestion sounds like something we could be doing as a follow-up to catch other cases.

Comment 9

[Markus Stange [:mstange]]

Actually, the third option (custom marker schema) sounds even better than stack-allocating the string.

Comment 10

[Markus Stange [:mstange]]

Another thing we could do (in addition to the other suggested fixes) is to put the marker inside the if (isSafeToFlush) { ... } block. Once we're in there, we know we're going ahead with the actual flush, and doing so is usually more expensive than adding the marker anyway.

In the profile from comment 6, we do not enter that if branch (afaik), so the marker overhead becomes noticeable because we're not actually flushing.