asm_sysvec_apic_timer_interrupt attributed wrongly to arbitrary stack trace?

[jfrantzius]

Hi,
when profiling a Quarkus benchmark (using Docker on a Linux x86 box), the native stack frame asm_sysvec_apic_timer_interrupt and its included frames are attributed to seemingly arbitrary Java stack traces, and with each profiling session to a different one, e.g.

The affected stack traces are attributed ~3% execution time, but only when asm_sysvec_apic_timer_interrupt shows up on top of them. asm_sysvec_apic_timer_interrupt shows up only on a single stack trace per profiling session, and has by itself only a fraction of its allegedly calling stack frame (0.02%).

As asm_sysvec_apic_timer_interrupt handles APIC timer interrupts, the code executed within is very likely not at all related to the stack trace that async-profiler associates it with. In effect, a ~3% CPU time bubble pops up in random places, once per profiling session.

I have no clue whether async-profiler already discerns Linux-specific stack frames, but my intuition here would be that it would be more appropriate if asm_sysvec_apic_timer_interrupt would turn up as a stack trace of its own in flame graphs?

(Related discussion at Quarkus, where I already mistook those 3% to be caused by the Java stack trace: Techempower benchmark spends 4% of time in volatile field access? #30473

[franz1981]

Just FYI a similar stack trace appear in a very old but still good ap issue -> #14 (comment)

[jfrantzius]

This seems to be a problem only with flamegraphs. In an HTML dump (also taken with -cycles) , asm_sysvec_apic_timer_interrupt occurs ~800 times, and seemingly only with truncated deeper stack frames like this (with or without "..." elipsis):

[jfrantzius]

OK, by looking at the HTML sourcecode of the flamegraphs I found out that asm_sysvec_apic_timer_interrupt is all over the place there as well, and I just wasn't able to find it using the HTML dump's search function. It seems that HTML dump truncates anything below it, probably on purpose, while flamegraph shows it.

The phenomenon then is that across both flamegraph and HTML dumps taken, there is a ~3%-7% bubble moving around below a common call tree ancestor (io/netty/buffer/PoolThreadCache$MemoryRegionCache.allocate) , and with each profiling session, async-profiler attributes it to a different subtree of that. I retried with half of the profiling interval (-i 5ms), but with same result.

[apangin]

It's true that an interrupt handler may run in the context of an arbitrary thread at an arbitrary point of time.
If an interrupt occurs when the application is running function "A", from the application perspective it will seem as if the function "A" runs longer for the duration of the interrupt handler. Therefore I don't think async-profiler should behave any differently: it currently shows the actual state of the things, even though it may be difficult to interpret.

[franz1981]

Thanks Andrei and I 👍 on it. In the mentioned Quarkus discussion I've said

APIC timers should be used by the hrtimer setup by perf (by async profiler engine, actually) in order to collect call chain perf events...

Hence, this is wrong? The apic irqs are not related ap?
Anyway, thanks for your time

[jfrantzius]

Thank you for your answer @apangin . Sorry for the confusion, but I now think the phenomenon isn't related to APIC timer interrupts at all. I had jumped to that conclusion earlier because the flamegraphs show native stack traces within asm_sysvec_apic_timer_interrupt that I never saw in the HTML dumps, likely because they are simply cut off there, and I wasn't able to find it using the flamegraphs' search function (but then I found a lot of them in the flamegraphs' HTML sourcecode).

The remaining phenomenon, though, is a mysterious 3% - 4% that is attributed to a different Java method with each profiling session for the same workload. The tiny orange spot on the right is 0.01% for asm_sysvec_apic_timer_interrupt, with most of the stack frame not showing any details of activity:

(Using -e cycles:)

E.g. the first method looks like this:

To me it remains totally unclear what it is actually spending time on, and similarly for the other methods. The only thing they seem to have in common is their call tree ancestor io/netty/buffer/PoolThreadCache$MemoryRegionCache.allocate.

Do you per chance have an idea as to what might cause this phenomenon?

[franz1981]

We've already spoken about it in the quarkus discussion: prior to the spRefElement, the JCTools queue is using a lock cas to update the producer sequence and is very likely the instruction to be blamed, which inlining of methods right next to him confuse the profiler, making it to pass unnoticed.

[jfrantzius]

If by "lock cas" you are referring to MpscArrayQueueProducerIndexField.casProducerIndex(), then this could be true for lvProducerLimit(), as both are called during BaseMpscLinkedArrayQueue.offer(). But spRefElement() is called during MpscArrayQueue.poll(), which doesn't call casProducerIndex()?

[franz1981]

In that case, it can be due to card marking, but requires print ASM and perf to find the guilty line of code.I think this is outside this discussion here, anyway :)

[jfrantzius]

OK, I now caught two of the three candidates in the same flamegraph. Previously it was always only one of them, and that's what I found so suspicious.

It turns out that all three candidates are somewhere close to volatile field accesses that prevent CPU register and cache usage, which explains the long bars without further details in the flamegraphs:

• lvProducerLimit() - returns a volatile field
• LongAdder.add() - ends up in VarHandle.compareAndSet() , which has memory semantics of setVolatile()
• spRefElement() - its invocation in poll() is followed by soConsumerIndex() that ends up in Unsafe.putOrderedLong() , which behaves like volatile field access

@franz1981 pointed out that it is due to method inlining and "skidding" that async-profiler cannot attribute cycles e.g. to Unsafe.putOrderedLong() in the last candidate, and instead attributes it to a method invocation in a previous line of code:

public E poll()
    {
        [..]
        spRefElement(buffer, offset, null);  // CPU cycles attributed here in flamegraph
        soConsumerIndex(cIndex + 1);         // inlined method invocation with volatile field access via Unsafe.putOrderedLong() 
                                             // where CPU cycles are *actually* spent

This is described in section "Error Margin: Skidding + inlining" in The Pros and Cons of AsyncGetCallTrace Profilers and "A Confusing Reality" in How Inlined Code Makes For Confusing Profiles:

Sure, the profiler pointed to line A, but any fool can see the problem is line B... silly little hobbit.