koute / not-perf

A sampling CPU profiler for Linux
Apache License 2.0
868 stars 40 forks source link

Flamegraph backtrace discrepancy #31

Closed bkchr closed 1 year ago

bkchr commented 1 year ago

Looking at the following flamegraph: flaminggraph.zip

The follow_finalized_head is appearing twice as part of tokio-runtime-w [THREAD=96]. The appearing after std::sys::unix::thread::Thread::new::thread_start [khala-node] is also having much more samples. I would have assumed that the one originated from the raw poll is having more samples.

So, my question. Is everything working as expected or is there maybe some bug?

koute commented 1 year ago

@bkchr The issue here in the flamegraph is basically that for some samples the whole backtrace was gathered (the one column where it goes all the way to thread_start) and for some samples it wasn't (the one column where it goes only up to raw::poll), so the backtraces are technically different, so it didn't collate them together.

This is normal.

Technically this could be some subtle bug that it can't gather the full backtrace, although it's probably not. When sampling out-of-process the profiler has two limitations that it must deal with:

1) It doesn't have access to the whole stack, so if the program uses too much stack space the profiler physically can't unwind the whole stack. Linux's perf_event_open events can contain only up to several kilobytes of stack, so unlike Bytehound I can't guarantee that the whole stack will be unwinded as long as I'm using perf_event_open. (Investigating alternative means of profiling so that I'm not bound by this limitation is on my TODO list somewhere. :P) 2) Sometimes the program counter can land somewhere from where unwinding is not possible. (The unwinding tables sometimes only contain enough information to unwind from places from where the program could unwind by itself at runtime, the stack base pointer could be omitted, etc.)

So going back to your flamegraphs, in the truncated stack traces I can see e.g. TableFile::read_at so my random guess would be that perhaps this is the case of it allocating a big buffer on the stack and using it to read the file or something, and that's why it's truncated? Either way I'm fairly sure the bottom of those two traces should be the same.

bkchr commented 1 year ago

Okay!

Yeah I also already assumed that this isn't a real issue and more a limitation. Just wanted to be sure!

Thank you!

bjorn3 commented 1 year ago

Would it be possible to if the stack is truncated try to match the backtrace with backtrace of the previous sample to see if a postfix of the truncated backtrace matches with a part of the full backtrace and if so reconstruct the truncated backtrace based on the full backtrace?

koute commented 1 year ago

Would it be possible to if the stack is truncated try to match the backtrace with backtrace of the previous sample to see if a postfix of the truncated backtrace matches with a part of the full backtrace and if so reconstruct the truncated backtrace based on the full backtrace?

Hm, that's an interesting idea! I think, yes, however unfortunately this is not guaranteed to be correct (the part of the backtrace which is missing could be different after all, so it could match it to the wrong one), but I would consider adding this as an optional feature under a flag.