12 ms·

Pprof++: A Go Profiler with Hardware Performance Monitoring

240 points by vquemener 5y ago

jrockway 5y ago
I've also used `perf` to profile Go apps, and the results can be pretty interesting. For example, the Go profiler doesn't continue out of the process and into the kernel, so are your I/O waits on the network, or are they on the local filesystem? `perf` can show you the difference. (And it does come up in the real world; you can often have Go functions that operate on io.Readers that are connected to the network, or are connected to disk files. A profile that extends into the kernel can show you which case is slow.) I've been consistently disappointed by Go's mutex profiling. It is kind of useful if you can synthesize the contention, but less useful if the contention isn't obvious. For my most recent contention debugging issue, I was very close to modifying the runtime (mostly sync.Mutex) to emit events that perf could sample on, and build a flame graph for cases like "took the fast path on sync.Mutex". What takes the fast path under synthetic load could easily take the slow path under different load, and that would let you identify the bottlenecks before they occur. I ended up not needing it, so didn't do it, but it's interesting to me that other people have run into the case where the built-in profiles aren't quite enough. There are definitely a lot of improvements to be made here. (Getting ahead of lock contention has come up a lot in my Go career. When I was at Google, I had an application that computed metrics over hundreds of thousands of concurrent network streams. I used the standard library for metrics, which synchronized on sync.RWMutex, and it was just too slow to synchronize millions of events per second. This sort of bottleneck will be obvious to anyone, probably; you simply can't block all metric-increments on reads every 15 seconds and expect to fully utilize use 96vCPUs that are trying to write ;) No profile ever pointed me at the culprit in a straightforward manner; I had to dig into the time-per-assembly-instruction profile and noticed inordinate amount of time being spent in an instruction incidental to the implementation of sync.Mutex. I ended up switching to atomic.AddInt64, which solved my problem. I think the overhead of a write barrier is actually too heavy and wouldn't do that today; I'd just maintain goroutine-local counters and synchronize them occasionally. You can still fall behind, of course, but your program can easily detect that case and log a message like "we're too slow, buy another computer!" in that branch. Easier than reading the profiles.)
- jrockway 5y ago
  Thought it might also be helpful to add that I usually invoke perf like this: perf record --call-graph dwarf -e cycles --switch-events --sample-cpu -p $(pidof my-go-process) And then view the results in hotspot (https://github.com/KDAB/hotspot https://github.com/KDAB/hotspot). I played a little with off-cpu profiling (-e sched:sched_switch), but Go kind of outsmarts that by doing its own scheduling (taking Goroutines off Machines when it thinks it's going to block inside a syscall, so the resulting flamegraphs are usually rooted in runtime.park_m; though if the runtime gets something wrong, you'd be able to see it here.)
- jeffbee 5y ago
  A lot of people don’t grok the contention profiler, even people who work on service performance full-time. The problem is the docs. What you’re getting from the contention profile is samples of call stacks for contended releases, that is when a lock is released and there are waiters. This isn’t explained anywhere, to my recollection.
  - felixge 5y ago
    Yup, there is an upstream issue to improve this: https://github.com/golang/go/issues/44920 https://github.com/golang/go/issues/44920 FWIW I'm planning to work on the problem from downstream as well by adding more docs here: https://github.com/felixge/go-profiler-notes https://github.com/felixge/go-profiler-notes . I haven't gotten to the mutex profile yet, but I've covered the block profile in great detail. It actually overlaps with the mutex profile for contention, but it tracks Lock() rather than Unlock() which is subtly different like you pointed out!
- felixge 5y ago
  Very interesting points about mutex profiles. When you say fast path, do you mean spin locks? For analyzing I/O via perf and looking at kernel stacks, I'm surprised that would work. I'd think that perf will not show you much waiting on the network, because the netpoller implementation in Go uses epoll and friends to make that non-blocking under the hood. For disk I/O it probably works. Maybe I'm missing something?
akshayshah 5y ago
Full disclosure: I used to work in Uber's infrastructure group. I'm always happy to see improvements to Go's profiling - the standard library's profiling is good, but it hasn't improved much since Go 1.0 (it took years just to get flame graphs integrated, and it's still near-impossible to get a usable dump of the in-memory object graph). That said, I'm _very_ wary of tools that require a fork of the compiler and/or runtime. Uber's programming language research group is small (though mighty) and has a lot of demands on their time. Even over the medium term, it'll be hard to allocate time to keep this project current. In the Go issue tracker, there's a long discussion [1] of the formal proposal [2] for these improvements. My understanding of the feedback is that the changes introduce too many Linux and x86-specific APIs. I'd love to see the author narrow the proposal to just improve timer fidelity when the OS exposes the PMU, without any new APIs. The more controversial proposal to collect richer platform- and architecture-specific data can be discussed separately. Discussion [1]: https://github.com/golang/go/issues/36821 https://github.com/golang/go/issues/36821 Proposal [2]: https://go.googlesource.com/proposal/+/refs/changes/08/219508/2/design/36821-perf-counter-pprof.md https://go.googlesource.com/proposal/+/refs/changes/08/21950...
- dvfjsdhgfv 5y ago
  Forgive my ignorance, but I have a very general question. The article says Go runs on millions of cores at Uber. Obviously, the company is interested in maximizing the performance, hence the Pprof++ project. My experience with Go is very limited, but in my tests it was always slower than C. Sometimes just a bit, sometimes 2-5 times. So my question is: looking back, don't you guys regret choosing this language? Please don't misunderstand me, I don't intend to start any flamewars, but it seems like you're very much focused on CPU-bound performance, and the choice of language is not neutral in this case.
  - domano 5y ago
    I think finding a good balance between performance and development time & risks is important and C does not seem like a very good choice regarding the second part. At least for web stuff.
  - 5y ago
petethepig 5y ago
This is really cool stuff, we're at Pyroscope [1] would love to add support for it. Too bad it's a fork of Go runtime. As @akshayshah mentioned, it seems like Go team is hesitant about straight up merging this. I wonder if a better approach would be to open up Go runtime apis so that this can be a module instead of a whole fork. I think opening up these APIs would also enable more innovation in profiling space. [1]: https://github.com/pyroscope-io/pyroscope https://github.com/pyroscope-io/pyroscope
- rob74 5y ago
  "Modularizing" the runtime sounds like a good idea, but also adds new constraints: they would have to document the interfaces between the various modules and then either keep them unchanged, which would hinder further development; or if they change the module interfaces, the modules will have to be updated nevertheless, so having modules won't be much of an advantage...
felixge 5y ago
I think this is great work. Hopefully this can motivate upstream to reconsider the proposal for it. In the long run I don't think anybody wants to run with a forked version of Go for better profiling. > The ability to monitor go programs with a very high sampling frequency — up to 10s of microseconds I'm curious about the overhead of this and will probably try to measure. This work certainly overcomes the limitations of setitimer(2) for sampling rate, but faster sampling is going to increase the performance overhead significantly. In particular Go's built-in stack unwinding APIs use gopclntab (which is Go's Plan9 inspired version of eh_frame). This is rather slow compared to frame pointer unwinding (up to 55x in my testing). I think on average you can expect to spend at least 1 microsecond on unwinding, and then some additional time hashing the stack and updating the in-memory profile (perhaps another microsecond? I haven't measured this part yet). I've started writing some of this up here [1] but it's still WIP. Anyway, based on the above, sampling every 10usec will likely slow the target program by ~20%. This is probably a very optimistic estimate because it doesn't take into account all the CPU cache thrashing that will happen. As I said, I'll try to take a closer look later, but if anybody has some insights/comments here I'd be very interested. [1] https://github.com/DataDog/go-profiler-notes/blob/main/stack-traces.md https://github.com/DataDog/go-profiler-notes/blob/main/stack... Disclaimer: I work at Datadog on Continuous Go Profiling, but I'm here speaking for myself.
- akshayshah 5y ago
  I suspect you're right about overhead. 10us seems much more aggressive than even the author is actually suggesting, though - the motivating example was a service with latencies in the 10s of ms, so sampling every few ms would be sufficient. Also, if anyone reading isn't familiar with sampling profilers, Felix gave a great talk explaining them: https://github.com/felixge/talks/blob/master/fgprof/ https://github.com/felixge/talks/blob/master/fgprof/
  - felixge 5y ago
    Yeah, decent sampling for requests that last 10s of ms seems absolutely feasible with this approach, unlike the current setitimer(2) stuff. I'm really looking forward to taking it for a spin soon and see how far the sampling rate can be pushed without introducing noticeable overhead in practice!
jeffbee 5y ago
Trying to figure out how this would be of use to anyone else, in practice. You need a hacked up runtime and a privileged process to use the PMU. Compared to just using perf, it seems like a hassle.
- jrockway 5y ago
  I'm happy to rebuild the binary when I'm stuck on a performance problem. Obviously, the best case is having all the instrumentation on the production system that is experiencing problems, of course. I've run into problems that only manifest themselves after running for several hours, so the debugging cycle is slow when you aren't collecting what you need to debug the issue. In other cases, I've had bugs where a test case can reproduce them immediately, but the profiler still provides more targeted guesses than randomly changing something to see if it improves the outcome (even if the edit/test cycle is fast enough to support this). That's the case where this sounds helpful.
  - ahh 5y ago
    Yeah, but you know what also works? Running perf and running that through normal pprof...
- donio 5y ago
  The examples seem to run fine and report counters without any special privileges. Building the toolchain and then building your own code with the toolchain is trivial too, I was up and running in 10 minutes, much of which was waiting for the builds.
  - jeffbee 5y ago
    That suggests your system has a liberal setting of /proc/sys/kernel/perf_event_paranoid or your process is privileged, running as root or with either CAP_SYS_ADMIN or CAP_PERFMON. Generally unprivileged processes cannot access the PMU, because the PMU can be used to take over the system.
avinassh 5y ago
On a similar note, is there any similar tool exists for Rust?
- ithkuil 5y ago
  I know one crate that offers a Go-like pprof experience: https://github.com/tikv/pprof-rs https://github.com/tikv/pprof-rs But that crate doesn't (yet?) Use the hardware based perf counters, so this may not answer your actual question.
Veserv 5y ago
It is so odd that companies with such immense engineering budgets and computational costs continue to use low resolution profiling techniques such as sampling instead of modern high resolution tracing based solutions. The gap in insight you can get between seeing some things and literally everything is similar to the gap between no profiler and a sampling profiler. You can actually trace the direct causes of slowness instead of just the symptoms. It is so massive that every time we move a system that was optimized using a sampling profiler to a tracing profiler we learn just how little we knew about how it worked and how stupid the program was behaving and routinely see 30%-50% speedups from those insights on even heavily optimized code. The only real downsides to tracing over sampling is that the overhead is higher than low resolution sampling down to ~100 usecs per sample (single-digit to low double digit overhead) and that any performant solution basically requires instrumentation and thus results in small overhead if you want it to be runtime toggleable and requires tooling support to inject. However, given the immense benefits, it is baffling that companies continue to struggle with such minimal tooling and platforms that only have such tooling available.
- gok 5y ago
  That is...so the opposite of my experience. Sampling has the critical benefit of not biasing the profiling towards frequent-but-fast spots. Tracing profilers give you very precise but inaccurate information on your hotspots.
hodgesds 5y ago
Nice to see Milind and the rest of the team are still making progress! One of the alternatives explored in the original proposal was using a go library that wraps perf, which I explored quite a bit previously. I haven't had time to continue that work, but it is possible to use a perf library within benchmarks (ex: https://github.com/hodgesds/compressbench https://github.com/hodgesds/compressbench) to some success. Getting this profiler merged into runtime would be really nice. Alternatively, if someone wants to extend a perf library that is able to resolve runtime stacks using eBPF that could be an interesting alternative.
etep 5y ago
I'm curious about the results under the section titled "Demonstration." The author claims that ground truth is that each goroutine utilizes 10% of the CPU time (so stipulated that this should be the case). But, what if the results shown are accurate, i.e. that the results are the actual CPU time (because of idiosyncrasies of scheduling between the OS, the go runtime, and anything else happening on that system). Does running the new profiler show less variance in the results from that initial experiment? Showing this result would strengthen the claim that the "out of the box" solution is inaccurate.

240 points by vquemener 5y ago

I've also used `perf` to profile Go apps, and the results can be pretty interesting. For example, the Go profiler doesn't continue out of the process and into the kernel, so are your I/O waits on the network, or are they on the local filesystem? `perf` can show you the difference. (And it does come up in the real world; you can often have Go functions that operate on io.Readers that are connected to the network, or are connected to disk files. A profile that extends into the kernel can show you which case is slow.) I've been consistently disappointed by Go's mutex profiling. It is kind of useful if you can synthesize the contention, but less useful if the contention isn't obvious. For my most recent contention debugging issue, I was very close to modifying the runtime (mostly sync.Mutex) to emit events that perf could sample on, and build a flame graph for cases like "took the fast path on sync.Mutex". What takes the fast path under synthetic load could easily take the slow path under different load, and that would let you identify the bottlenecks before they occur. I ended up not needing it, so didn't do it, but it's interesting to me that other people have run into the case where the built-in profiles aren't quite enough. There are definitely a lot of improvements to be made here. (Getting ahead of lock contention has come up a lot in my Go career. When I was at Google, I had an application that computed metrics over hundreds of thousands of concurrent network streams. I used the standard library for metrics, which synchronized on sync.RWMutex, and it was just too slow to synchronize millions of events per second. This sort of bottleneck will be obvious to anyone, probably; you simply can't block all metric-increments on reads every 15 seconds and expect to fully utilize use 96vCPUs that are trying to write ;) No profile ever pointed me at the culprit in a straightforward manner; I had to dig into the time-per-assembly-instruction profile and noticed inordinate amount of time being spent in an instruction incidental to the implementation of sync.Mutex. I ended up switching to atomic.AddInt64, which solved my problem. I think the overhead of a write barrier is actually too heavy and wouldn't do that today; I'd just maintain goroutine-local counters and synchronize them occasionally. You can still fall behind, of course, but your program can easily detect that case and log a message like "we're too slow, buy another computer!" in that branch. Easier than reading the profiles.)

jrockway 5y ago
Thought it might also be helpful to add that I usually invoke perf like this: perf record --call-graph dwarf -e cycles --switch-events --sample-cpu -p $(pidof my-go-process) And then view the results in hotspot (https://github.com/KDAB/hotspot https://github.com/KDAB/hotspot). I played a little with off-cpu profiling (-e sched:sched_switch), but Go kind of outsmarts that by doing its own scheduling (taking Goroutines off Machines when it thinks it's going to block inside a syscall, so the resulting flamegraphs are usually rooted in runtime.park_m; though if the runtime gets something wrong, you'd be able to see it here.)
jeffbee 5y ago
A lot of people don’t grok the contention profiler, even people who work on service performance full-time. The problem is the docs. What you’re getting from the contention profile is samples of call stacks for contended releases, that is when a lock is released and there are waiters. This isn’t explained anywhere, to my recollection.
- felixge 5y ago
  Yup, there is an upstream issue to improve this: https://github.com/golang/go/issues/44920 https://github.com/golang/go/issues/44920 FWIW I'm planning to work on the problem from downstream as well by adding more docs here: https://github.com/felixge/go-profiler-notes https://github.com/felixge/go-profiler-notes . I haven't gotten to the mutex profile yet, but I've covered the block profile in great detail. It actually overlaps with the mutex profile for contention, but it tracks Lock() rather than Unlock() which is subtly different like you pointed out!
felixge 5y ago
Very interesting points about mutex profiles. When you say fast path, do you mean spin locks? For analyzing I/O via perf and looking at kernel stacks, I'm surprised that would work. I'd think that perf will not show you much waiting on the network, because the netpoller implementation in Go uses epoll and friends to make that non-blocking under the hood. For disk I/O it probably works. Maybe I'm missing something?

akshayshah 5y ago

Full disclosure: I used to work in Uber's infrastructure group. I'm always happy to see improvements to Go's profiling - the standard library's profiling is good, but it hasn't improved much since Go 1.0 (it took years just to get flame graphs integrated, and it's still near-impossible to get a usable dump of the in-memory object graph). That said, I'm _very_ wary of tools that require a fork of the compiler and/or runtime. Uber's programming language research group is small (though mighty) and has a lot of demands on their time. Even over the medium term, it'll be hard to allocate time to keep this project current. In the Go issue tracker, there's a long discussion [1] of the formal proposal [2] for these improvements. My understanding of the feedback is that the changes introduce too many Linux and x86-specific APIs. I'd love to see the author narrow the proposal to just improve timer fidelity when the OS exposes the PMU, without any new APIs. The more controversial proposal to collect richer platform- and architecture-specific data can be discussed separately. Discussion [1]: https://github.com/golang/go/issues/36821 https://github.com/golang/go/issues/36821 Proposal [2]: https://go.googlesource.com/proposal/+/refs/changes/08/219508/2/design/36821-perf-counter-pprof.md https://go.googlesource.com/proposal/+/refs/changes/08/21950...

dvfjsdhgfv 5y ago
Forgive my ignorance, but I have a very general question. The article says Go runs on millions of cores at Uber. Obviously, the company is interested in maximizing the performance, hence the Pprof++ project. My experience with Go is very limited, but in my tests it was always slower than C. Sometimes just a bit, sometimes 2-5 times. So my question is: looking back, don't you guys regret choosing this language? Please don't misunderstand me, I don't intend to start any flamewars, but it seems like you're very much focused on CPU-bound performance, and the choice of language is not neutral in this case.
- domano 5y ago
  I think finding a good balance between performance and development time & risks is important and C does not seem like a very good choice regarding the second part. At least for web stuff.
- 5y ago

petethepig 5y ago

This is really cool stuff, we're at Pyroscope [1] would love to add support for it. Too bad it's a fork of Go runtime. As @akshayshah mentioned, it seems like Go team is hesitant about straight up merging this. I wonder if a better approach would be to open up Go runtime apis so that this can be a module instead of a whole fork. I think opening up these APIs would also enable more innovation in profiling space. [1]: https://github.com/pyroscope-io/pyroscope https://github.com/pyroscope-io/pyroscope

rob74 5y ago
"Modularizing" the runtime sounds like a good idea, but also adds new constraints: they would have to document the interfaces between the various modules and then either keep them unchanged, which would hinder further development; or if they change the module interfaces, the modules will have to be updated nevertheless, so having modules won't be much of an advantage...

felixge 5y ago

I think this is great work. Hopefully this can motivate upstream to reconsider the proposal for it. In the long run I don't think anybody wants to run with a forked version of Go for better profiling. > The ability to monitor go programs with a very high sampling frequency — up to 10s of microseconds I'm curious about the overhead of this and will probably try to measure. This work certainly overcomes the limitations of setitimer(2) for sampling rate, but faster sampling is going to increase the performance overhead significantly. In particular Go's built-in stack unwinding APIs use gopclntab (which is Go's Plan9 inspired version of eh_frame). This is rather slow compared to frame pointer unwinding (up to 55x in my testing). I think on average you can expect to spend at least 1 microsecond on unwinding, and then some additional time hashing the stack and updating the in-memory profile (perhaps another microsecond? I haven't measured this part yet). I've started writing some of this up here [1] but it's still WIP. Anyway, based on the above, sampling every 10usec will likely slow the target program by ~20%. This is probably a very optimistic estimate because it doesn't take into account all the CPU cache thrashing that will happen. As I said, I'll try to take a closer look later, but if anybody has some insights/comments here I'd be very interested. [1] https://github.com/DataDog/go-profiler-notes/blob/main/stack-traces.md https://github.com/DataDog/go-profiler-notes/blob/main/stack... Disclaimer: I work at Datadog on Continuous Go Profiling, but I'm here speaking for myself.

akshayshah 5y ago
I suspect you're right about overhead. 10us seems much more aggressive than even the author is actually suggesting, though - the motivating example was a service with latencies in the 10s of ms, so sampling every few ms would be sufficient. Also, if anyone reading isn't familiar with sampling profilers, Felix gave a great talk explaining them: https://github.com/felixge/talks/blob/master/fgprof/ https://github.com/felixge/talks/blob/master/fgprof/
- felixge 5y ago
  Yeah, decent sampling for requests that last 10s of ms seems absolutely feasible with this approach, unlike the current setitimer(2) stuff. I'm really looking forward to taking it for a spin soon and see how far the sampling rate can be pushed without introducing noticeable overhead in practice!

jeffbee 5y ago

Trying to figure out how this would be of use to anyone else, in practice. You need a hacked up runtime and a privileged process to use the PMU. Compared to just using perf, it seems like a hassle.

jrockway 5y ago
I'm happy to rebuild the binary when I'm stuck on a performance problem. Obviously, the best case is having all the instrumentation on the production system that is experiencing problems, of course. I've run into problems that only manifest themselves after running for several hours, so the debugging cycle is slow when you aren't collecting what you need to debug the issue. In other cases, I've had bugs where a test case can reproduce them immediately, but the profiler still provides more targeted guesses than randomly changing something to see if it improves the outcome (even if the edit/test cycle is fast enough to support this). That's the case where this sounds helpful.
- ahh 5y ago
  Yeah, but you know what also works? Running perf and running that through normal pprof...
donio 5y ago
The examples seem to run fine and report counters without any special privileges. Building the toolchain and then building your own code with the toolchain is trivial too, I was up and running in 10 minutes, much of which was waiting for the builds.
- jeffbee 5y ago
  That suggests your system has a liberal setting of /proc/sys/kernel/perf_event_paranoid or your process is privileged, running as root or with either CAP_SYS_ADMIN or CAP_PERFMON. Generally unprivileged processes cannot access the PMU, because the PMU can be used to take over the system.

avinassh 5y ago

On a similar note, is there any similar tool exists for Rust?

ithkuil 5y ago
I know one crate that offers a Go-like pprof experience: https://github.com/tikv/pprof-rs https://github.com/tikv/pprof-rs But that crate doesn't (yet?) Use the hardware based perf counters, so this may not answer your actual question.

Veserv 5y ago

It is so odd that companies with such immense engineering budgets and computational costs continue to use low resolution profiling techniques such as sampling instead of modern high resolution tracing based solutions. The gap in insight you can get between seeing some things and literally everything is similar to the gap between no profiler and a sampling profiler. You can actually trace the direct causes of slowness instead of just the symptoms. It is so massive that every time we move a system that was optimized using a sampling profiler to a tracing profiler we learn just how little we knew about how it worked and how stupid the program was behaving and routinely see 30%-50% speedups from those insights on even heavily optimized code. The only real downsides to tracing over sampling is that the overhead is higher than low resolution sampling down to ~100 usecs per sample (single-digit to low double digit overhead) and that any performant solution basically requires instrumentation and thus results in small overhead if you want it to be runtime toggleable and requires tooling support to inject. However, given the immense benefits, it is baffling that companies continue to struggle with such minimal tooling and platforms that only have such tooling available.

gok 5y ago
That is...so the opposite of my experience. Sampling has the critical benefit of not biasing the profiling towards frequent-but-fast spots. Tracing profilers give you very precise but inaccurate information on your hotspots.

hodgesds 5y ago

Nice to see Milind and the rest of the team are still making progress! One of the alternatives explored in the original proposal was using a go library that wraps perf, which I explored quite a bit previously. I haven't had time to continue that work, but it is possible to use a perf library within benchmarks (ex: https://github.com/hodgesds/compressbench https://github.com/hodgesds/compressbench) to some success. Getting this profiler merged into runtime would be really nice. Alternatively, if someone wants to extend a perf library that is able to resolve runtime stacks using eBPF that could be an interesting alternative.

etep 5y ago

I'm curious about the results under the section titled "Demonstration." The author claims that ground truth is that each goroutine utilizes 10% of the CPU time (so stipulated that this should be the case). But, what if the results shown are accurate, i.e. that the results are the actual CPU time (because of idiosyncrasies of scheduling between the OS, the go runtime, and anything else happening on that system). Does running the new profiler show less variance in the results from that initial experiment? Showing this result would strengthen the claim that the "out of the box" solution is inaccurate.