hyangah
commented
4 years ago Will it be available to non-linux OSes? If so, that's great. Previously, we've suggested Linux perf (that can use PMU events, right?) as an alternative to runtime/pprof to work around the known limitation of runtime/pprof. The pprof tool can interpret Linux perf output. If this proposal makes it possible to help non-Linux users and to allow extra information such as labels, etc while not introducing too much complexity to the runtime, that will be super.
@aclements @rsc @dvyukov @rhysh
chabbimilind
josharian
networkimprov
gopherbot
rsc
songlh
ianlancetaylor
egonelbre
rasky
rhysh
What version of Go are you using (
go version)?Does this issue reproduce with the latest release?
Yes; tested on
go version devel +74d366f484 Mon Jan 27 20:45:39 2020 +0000 linux/amd64What operating system and processor architecture are you using (
go env)?go envOutputWhat did you do?
The following experiments demonstrate that pprof CPU profiles lack accuracy (closeness to the ground truth) and precision (repeatability across different runs). The tests are highly predictive in nature and involve little runtime overheads (allocation, GC, system call, etc.). They are carefully designed so that we can compare pprof CPU profiles against our expectations. The evaluation shows a wide difference from expectation. One should not confuse this to be a runtime issue; the issue is with the use of OS timers used for sampling; OS timers are coarse-grained and have a high skid. In a proposal/design document that will follow, I will propose a design to extend CPU profiling by sampling CPU Performance Monitoring Unit (PMU) aka hardware performance counters. PMU event-based sampling is a mature technology available on almost all modern CPUs. PMU as a sampling agent offers many benefits (in no particular priority order):
There are two test cases
goroutine.goandserial.goin this issue.test 1 (parallel)
Download the first test case,
goroutine.goprogram, from https://github.com/chabbimilind/GoPprofDemo/blob/master/goroutine.go It has ten exactly the same goroutines:f1-f10and I use pprof to collect the CPU profiles. Run the following command several times and notice that each time, pprof reports a different amount of time spent in each of the ten routines.go run goroutine.go && go tool pprof -top goroutine_proftest 2 (serial)
Download the second test case,
serial.gogo program, from https://github.com/chabbimilind/GoPprofDemo/blob/master/serial.go: It has ten functions (A_expect_1_82-J_expect_18_18). The functionA_expect_1_82is expected to consume 1.82% of the total execution time andJ_expect_18_18is expected to consume 18.18% of the execution time, and so on. The code is serial and there is complete data dependence between each function and each iteration of the loop in the functions to avoid any hardware-level optimizations. Run the following command several times.go run serial.go && go tool pprof -top serial_profWhat did you expect to see?
For
goroutine.go, each function (f1-10) should be attributed with exactly (or almost exactly) 10% of the execution time on each run.For
serial.gothe time attribution should roughly follow the distribution shown below in each run.What did you see instead?
test 1 (parallel)
Run 1, 2, and 3, shown below, respectively show the
pprof -topoutput ofgoroutine.go. You will notice in a single run (say Run 1),f1-f10have a wide variance in the time attributed to them; the expectation is that each of them gets 10% execution time. There is up to6xdifference in time attributed to the function with the highest amount if attribution (main.f7,4210ms, inRun 1) vs. the function with the lowest a amount of attribution (main.f9,700ms, inRun 1). This shows a poor accuracy (deviation from the ground truth) of pprof timer-based profiles.Furthermore, the time attributed to a function widely varies from run to run. Notice how the top-10 ordering changes. In
Run 1,main.f7is shown to run for4210ms, whereas inRun 2it is shown to run for only520ms. The expectation is that the measurements remain the same from run to run. This shows a poor precision (unpredictability of measurement) of pprof timer-based profiles.goroutine.go/Run 1:
goroutine.go/Run 2:
goroutine.go/Run 3:
test 2 (serial)
The output for
go run serial.go && go tool pprof -top serial_proffor three runs is shown below. Comparing the flat% (or cum%) against the expected percentage for each function shows a large difference. For example,main.H_expect_14_546, which is expected to have 14.546% execution time, is attributed 25% of the execution time in Run 1. Furthermore, run to run, there is a lack of precision, for example,main.I_expect_16_36is attributed 6.25% (20ms) execution time in Run 1, whereas it is attributed 21.88% (70ms) execution time in Run 2.serial.go/Run 1:
serial.go/Run 2:
serial.go/Run 3:
Improved results with PMU-based profiling.
In a prototype PMU-based profiling implementation, below are the pprof profiles for CPU cycles hardware performance counter for the same
goroutine.goprogram. Notice that each functions gets the same (or almost the same) CPU cycles attribution within a single run and across runs.goroutine.go/Run 1:
goroutine.go/Run 2:
Below are the pprof profiles for CPU cycles hardware performance counter for the same
serial.goprogram. Notice that each function gets close to expected CPU cycles attribution within a single run and across runs.serial.go/Run 1:
serial.go/Run 2:
Dependence on the number of cores and length of test execution:
The results of
goroutine.gotest depend on the number of CPU cores available. On a multi-core CPU, if you setGOMAXPROCS=1,goroutine.gowill not show a huge variation, since each goroutine runs for several seconds. However, if you setGOMAXPROCSto a larger value, say 4, you will notice a significant measurement attribution problem. One reason for this problem is that the itimer samples on Linux are not guaranteed to be delivered to the thread whose timer expired.The results of
serial.gocan change based on the time of execution of each function. By passing the-m=<int>to the program, you can make the program run for longer or shorter. By making it run longer, the profiles can be made more accurate, but when a function runs for less than 100ms, the accuracy is often low.