1764944 - Some markers can be expensive enough to distort profiles

Status: NEW

(Core :: Gecko Profiler, defect, P3)

Description

[Alex Thayer [:alexical] (she/her)]

I am working on the performance of the webconsole right now, and one of my cases that I'm trying to improve is logging large numbers of cheap messages. Here is a profile of logging 100k numbers, for reference: https://share.firefox.dev/37PKrr8

I noticed that when the profiler is active, 75% of the time is accounted for by this line. You can't see this in the linked profile, but removing that line yielded a 75% reduction in execution time. It would be nice if we could improve the performance of this, but from my perspective I would be more interested in just having the option to disable markers. While markers typically have a lower overhead than samples, the problem is that samples are mostly uniform, while markers are not, so the relative timings of things are often intact under sampling, but distorted with markers, if there is an expensive marker on a hot code path.

Comment 1

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

There has been quite a bit of work in the last year to reduce marker overhead, especially when capturing a stack. But as experienced here, overused markers can still have a significant impact.
I believe the biggest contributor is the MarkerStack::Capture(), as this requires locking, accessing a shared stack-walking buffer, performing the stack walk, and storing a lot of data in the profiler buffer.

Doug, if possible could you please try replacing MarkerStack::Capture() with MarkerStack::NoStack(), and see if that has (almost) the same benefits?

if I'm correct, solutions include:

• Add an option to prevent stack-walking from markers.
• Remove this one Capture() if it can be triggered that much.

But if markers are still a problem even without the Capture(), other solutions include:

• Add an option to disable all markers (similar to the existing no-periodic-sampling option).
• Remove this too-busy marker.

There could be other things to try, like dynamically disabling stacks or even markers when the profiler notices they skew the profile too much, but it seems more complex and could make the resulting profiles less useful.
Other suggestions welcome.

Comment 2

[Florian Quèze [:florian]]

When I look at the profile, I'm under the impression that there's a lot of time spent creating and destroying profiler buffer chunks: https://share.firefox.dev/3O8mpZr Is this expected? Shouldn't chunks be re-used, or preallocated?

Comment 3

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

(In reply to Florian Quèze [:florian] from comment #2)

When I look at the profile, I'm under the impression that there's a lot of time spent creating and destroying profiler buffer chunks: https://share.firefox.dev/3O8mpZr Is this expected? Shouldn't chunks be re-used, or preallocated?

Yes, I see that in this case, the intent of bug 1734867 was to preallocate buffers for main-thread marker stacks...
However I've just noticed that this buffer is only allocated on the main thread but the call is done from locked_profiler_start... which is called off the main thread in child processes. 🤦‍♂️

So I'll work on a fix for this obvious issue, and it should remove the main cause of Doug's initial issue. We can file other bugs if there are still bad overheads in this code after that -- my suggestions in comment 1 could still be interesting to explore...

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

After re-reading comment 0, I've decided to move the issue&fix (for main-thread marker stacks in child processes) to new bug 1765922, because it doesn't really answer the initial request to turn off markers completely. While I'm hoping bug 1765922 will make this need less urgent, I think it may still be a good idea in some situations.
So first I'll work on bug 1765922, then we can revisit this bug here, and see how important it becomes then...

Comment 5

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Doug: Bug 1765922 landed a few days ago, it should massively reduce the overhead you experienced in your situation. If possible, could you please try again? (You may have moved on already, so "no can do" is a valid reply.)

We may still want to eventually implement options from comment 1, so I'll keep this bug open, but with a lower priority (until it becomes more urgent again).

Comment 6

[Alex Thayer [:alexical] (she/her)]

Hmm. It's certainly better, but it still really doesn't seem to like it. Here's a new profile: https://share.firefox.dev/3OLxYGf.