3 ms·
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
by jrockway 6y 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 6y agoThought 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 6y agoA 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 6y agoYup, 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 6y agoVery 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?
- jrockway 6y agoThere's a CompareAndSwap to do a quick acquire when there isn't contention: https://github.com/golang/go/blob/master/src/sync/mutex.go#L72 https://github.com/golang/go/blob/master/src/sync/mutex.go#L... If you look at the slow path, there are many interesting paths that a lock can take in there. They are all potentially interesting when you're debugging contention.