Labels mismatch

[korniltsev]

Describe the bug you encountered:

I run this script https://gist.github.com/korniltsev/e0299332cf4dfd6e07e3558b53f7d621 And get this: https://flamegraph.com/share/4193c6bf-2d41-11ed-9d2d-c2ecbb62e6f1 Strange stacktraces, mismatch tags Also see ruby code under rust code

What did you expect to happen instead?

...

[dalehamel]

Ran into this in https://github.com/grafana/pyroscope/issues/2072 and got all the way through debugging it before realizing it was probably actually this bug, thanks @korniltsev for referring it to me, per him:

Maybe just link your newly created issue there. It is much more clear and explained and does not look like a brain dump

[omarabid]

@dalehamel This is the expected and correct behavior. The reporting will have a margin of error. At the time, I couldn't think of any other solution that wouldn't stop the execution of the program until the reporting is completed (beside doing a filtering by time).

[dalehamel]

At the time, I couldn't think of any other solution that wouldn't stop the execution of the program until the reporting is completed (beside doing a filtering by time).

Can you elaborate on this further? I'm not sure I understand what you mean by "stop the execution". Is rbspy not using the ptrace API that pauses before taking snapshots? Or is this something inherently racy that leads to the "tag skew"?

This is the expected and correct behavior. The reporting will have a margin of error.

@omarabid I'm not sure I understand how it can be considered the correct behaviour - in the example I link, which uses Pyroscope's own ruby example as the source, you can see how a basic set of tags have a significant number of samples mislabeled.

This might be acceptable for extremely course-grain filtering of samples with labels, but appears to me to be a very serious defect since it will lead to false conclusions, and mis-attribution if attempting to filter by label. For the sake of disclosure, a caveat or warning should probably be placed in the documentation to indicate that there is an expected lack of precision. In a multi-threaded web server like Puma, I could see this causing a great deal of confusion, including samples for unrelated requests and controller actions...

In the case of Ruby, it should be possible to obtain the correct set of tags using rb_profile_frames, and reading the tag values from the active thread synchronously while an interrupt triggered by an itimer is being processed like stackprof does. Perhaps this is what you mean by "stop execution"? Thus, a "more correct" implementation is at least possible in theory. I'm not sure if this problem is inherent to any libraries using pyroscope-rs, or specific to the Ruby implementation and how tags are applied asynchronously.

[omarabid]

@dalehamel think about it this way. You have the following code:

..code 1
-> set tag
..code 2

You have two solutions here. Solution 1: send the "set_tag" command to a separate thread without blocking code 2; or Solution 2: "set_tag" is executing within the same thread, the collection bucket is changed and the operation carries on executing code 2.

Solution 2 is more accurate. Solution 1, however, doesn't block execution. It was a design compromise.

[dalehamel]

FYI @omarabid mostly inspired by this issue, I worked on https://github.com/tmm1/stackprof/pull/203 to see if I could overcome this deficiency in tagging by using stackprof, which wrap's ruby's own rb_profile_frames call. So far I have not been able to reproduce the tag skew issues, and it has a number of advantages over the pyroscope client:

• It is guaranteed to be on-CPU via itimer and the SIGPROF implementation, whereas the rbspy wrapper this isn't guaranteed just "seems to work"
• It can provide the class and module information, which rbspy cannot provide
• The tagging is low overhead and appears to be more accurate, as the tags are recorded while the VM is "paused" to handle the interrupt, and thus this should guarantee that it is synchronous and correct

The PR hasn't been accepted yet but at least shows some promise, thought I'd share for the sake of visibility.

[omarabid]

@dalehamel I didn't have the time to take a deeper look into stackprof but one of the downsides of pyroscope/rbspy is that it lacks integration with the Ruby VM. It basically tries to peek into the process and decode it. If you can run the profiler from inside the Ruby program, you'd have more control and better accuracy. Your solution wouldn't be universal, however. It was a design compromise.

By the way, if I remember correctly, the compromise was done because such accuracy was not needed most of the time. Unless you are profiling really small time frames and switching tags super fast, the inaccuracy is unlikely to show up.

[dalehamel]

Thanks for your reply and thoughts @omarabid

Unless you are profiling really small time frames and switching tags super fast, the inaccuracy is unlikely to show up.

The ruby sample code for pyroscope is able to show this problem, even at 100hz. In a situation with multiple threads and each having different tag sets, I would assume this problem is exacerbated. Since it seems like the tag accounting is racy, it can be hard to reason about the results when you are trying to account for these race conditions. I'll admit though I never tried it on a real app once I saw that the sample code was able to show rather substantial skew already.

In general at Shopify we've been sampling at about 500-1000hz, and stackprof is able to manage this well though we don't sample as continuously or as broadly as pyroscope does since the backend (phlare) cannot handle so much data anyways.

Your solution wouldn't be universal, however.

Yeah, it only works for ruby, but since pyroscope's ruby client uses this library, I thought I'd mention it. In general i think it is fair to assume that something inside the VM with runtime context will be able to provide more accurate information (and probably, for cheaper / lower overhead most of the time?) than something trying to observe and understand it from the outside, though I'd love to be proven wrong about this.

It was a design compromise

The solution I offered up is open source and written in C, so a Rust library doing something similar and calling rb_profile_frames could also be done, but maybe the Pyroscope Ruby userbase isn't big enough to justify another client? Alternatively, maybe we can open source something via our existing repo that wraps stackprof...

[omarabid]

@dalehamel

In general at Shopify we've been sampling at about 500-1000hz, and stackprof is able to manage this well though we don't sample as continuously or as broadly as pyroscope does since the backend (phlare) cannot handle so much data anyways.

The sampling rate does not matter but the rate at which you switch tags. If your tagged operation takes long enough, then it'll register to a higher degree of accuracy. If your operation is too short (a few frames for example), then you'll switch tags before the frames are recorded to the correct tag.

In a situation with multiple threads and each having different tag sets, I would assume this problem is exacerbated.

The current design should be able to handle multiple threads. The only limitation (am aware of) as explained above is if the time of the tagged operation is too short.

(and probably, for cheaper / lower overhead most of the time?)

Not necessarily. The compromise was done, in part, not to block the execution of your Ruby code. The profiler and Pyroscope runs on different threads. If your program is single threaded and you have available CPU on extra-cores, this can make it a lower overhead solution. Take note that any accurate solution will theoretically have more "overhead" since it'll stop execution to record the frames in the correct tag.

The solution I offered up is open source and written in C, so a Rust library doing something similar and calling rb_profile_frames could also be done, but maybe the Pyroscope Ruby userbase isn't big enough to justify another client? Alternatively, maybe we can open source something via our existing repo that wraps stackprof...

The Ruby client is just an FFI wrapper around the Pyroscope client which supports "plugins" like rbspy/pyspy. If you can pipe data from your solution to it, then you should be able to use it. It's all data piping at the end of the day :)