1733810 - On macOS, profiler label frames are incorrectly inserted as the "caller" of the function that pushes the label frame

Status: NEW

(Core :: Gecko Profiler, defect, P3)

Description

[Markus Stange [:mstange]]

Profile: https://share.firefox.dev/3l0rkz0

The label "XRE_InitChildProcess" is pushed by the function with the same name. I would expect to see the function frame "on the outside", and the label frame on the inside, as a child of the function frame. However, the label frame is on the outside.

This is a bit confusing. It can also cause a single function call to show up as multiple different call nodes, depending on what profiler labels inside that call were on the stack at the time the function was sampled. For example, if function A pushes label frame B and label frame C (inside B), we might collect the following stacks (stack frames ordered from outside to inside):

• A (parts of function A executing which are outside any label frame)
• B, A (B incorrectly on the outside)
• B, C, A (both B and C incorrectly on the outside)

More examples:

• https://share.firefox.dev/3uyDRN6 has multiple nsLayoutUtils::PaintFrame(...) call nodes and multiple mozilla::layers::WebRenderLayerManager::EndTransactionWithoutLayer call nodes
• https://share.firefox.dev/3uATCmA has many mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal call nodes

Comment 1

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

That's certainly confusing.

Given that:

• MergeStacks (which merges native, label, and other stacks) is platform-independent,
• Labels use the stack pointer of their on-stack object, so there's no real way this could be wrong(?),

Does it mean that stack-walking gives us mismatching stack & instruction pointers?
I have vague memories of discussing this with you, but I can't find relevant bugs/comments about that (quick search, I may have missed something).
To be investigated further...

Comment 2

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

(In reply to Gerald Squelart [:gerald] (he/him) from comment #1)

• Labels use the stack pointer of their on-stack object, so there's no real way this could be wrong(?),

Actually. I'm not so sure anymore!
The compiler could "optimize" the stack as it sees fit, and allocate stack space for objects in a different order from their order of creation in the function.
Also inline and tail functions probably make things more complex.

As an experiment, it may be interesting to see what would happen if we could record the actual current stack pointer at the time the label is created, instead of using this, in AutoProfilerLabel::Push().

Comment 3

[Markus Stange [:mstange]]

(In reply to Gerald Squelart [:gerald] (he/him) from comment #1)

Does it mean that stack-walking gives us mismatching stack & instruction pointers?

This would be my first guess, too. It's definitely possible that frame pointer stack walking has the stack pointer "one behind" (or "one ahead" of) the instruction pointer.

Comment 4

[Markus Stange [:mstange]]

I've thought about this some and have come to the counter-intuitive conclusion that the current stack merging behavior may actually be "correct", and that this is something we may want to fix in the front-end instead.

The key thing to remember is that stack walking doesn't give us functions - it gives us frame addresses. Frame addresses describe a place in the middle of a function. So let's say you have a function like this:

void myFunction() {
  some->code();
  {
    pushProfilerLabelFrame();
    more->code();
    this->line = gets + sampled; // <---
    more->code();
    popProfilerLabelFrame();
  }
  more->code();
}

The address for the sampled instruction could be considered "inside" the profiler label here.
It's only during symbolication that this address now resolves to the function name. So really, this is the step where we move from "something that describes a place inside the function" to "something that describes the entire function".

Comment 5

[Markus Stange [:mstange]]

And you're totally right, if there's inlining, we do not currently have enough information to get the ordering correct.

Here's one way we could get it correct:

1. When pushing a profiler label, also record the current instruction pointer value. (This will increase the label frame size by one pointer, and might have some effect on code size as well.)
2. Put this instruction pointer value into the profile JSON, associated with the label frame.
3. During symbolication, get the inline stack for "the place where the label frame was pushed". Then, have a merging step where the stacks get reordered in such a way that everything looks correct.

For example, if we have the following stack, from inside to outside:

0x1234
"Label frame" (pushed at 0x1200)
...

Symbolication gives us the following inline stack for those two addresses:

0x1234: InnerInlinedFunction, MidLevelInlinedFunction, OuterFunction
0x1200: MidLevelInlinedFunction, OuterFunction

Then we could create a stack like this, from inside to outside:

InnerInlinedFunction
Label frame
MidLevelInlinedFunction
OuterFunction
...

Comment 6

[Julien Wajsberg [:julienw]]

I've seen that on Linux too: Label Frame nsJSContext::RunCycleCollectorSlice calling into nsJSContext::RunCycleCollectorSlice(...) native stack for example.

Comment 7

[Markus Stange [:mstange]]

I'm reducing the priority and severity of this because the path forward is unclear and it's easy to work around.