When I measure the run time of my Go program with Linux's time utility, I get the following output:
real 1m9.177s
user 7m1.788s
sys 0m39.016s
When I look at the output of the same exact program execution in Go's pprof CPU profiler, I get the following output:
Entering interactive mode (type "help" for commands)
(pprof) top
143.32s of 176s total (81.43%)
Where is the pprof getting this 176s figure from? It is neither the clock time nor the CPU time. I am running this program with GOMAXPROCS set to 8, and I have a feeling this has something to do with it. How exactly does pprof measure run time, and why is it different from linux's time?
The time utility and the pprof tool operate in different ways and should be used in different ways. Don't try to reconcile them. time measures near exact times for the program; pprof measures relative times for functions and methods. pprof is an intrusive statistical sample. When CPU profiling is enabled, the Go program stops about 100 times per second and records a sample consisting of the program counters on the currently executing goroutine's stack. Sampling has a cost and the results are estimates of the actual population.
Use time to measure the overall actual CPU time for the program, that is absolute time. Use pprof to estimate where most of the time was spent in the functions and methods using relative time percentages. pprof identifies the bottlenecks. For actual CPU times, use Go testing package benchmarks.
For an example, see Profiling Go Programs:
By using Go's profiling tools to identify and correct specific bottlenecks, we can make the Go loop finding program run an order of magnitude faster and use 6x less memory.