Can't get golang pprof to work
I tried to profile some golang apps, but I couldn't work like this, I followed these two tutorials:
- http://blog.golang.org/profiling-go-programs
- http://saml.rilspace.org/profiling-and-creating-call-graphs-for-go-programs-with-go-tool-pprof
Both say that after adding some lines of code to your application, you need to execute your application, I did this and I got the following message on the screen:
2015/06/16 12:04:00 profile: cpu profiling enabled, / var / folders / kg / 4fxym1sn0bx02zl_2sdbmrhr9wjvqt / T / profile680799962 / cpu.pprof
So my understanding is that profiling is done by sending information to a file.
But when I see the file size, there is always 64 bytes in any program under test.
When I try to open the cpu.pprof file with pprof and I execute the "top10" command, I see that there is nothing in the file:
("./fact" is my application)
go tool pprof./fact / var / folders / kg / 4fxym1sn0bx02zl_2sdbmrhr9wjvqt / T / profile680799962 / cpu.pprof
top10 →
(pprof) top10 0 out of 0 total (0%) flat flat% sum% cum cum%
So, it is as if nothing happens when I profile.
I tested it on mac (this example) and on ubuntu with 3 different programs.
Do you know that I am doing wrong?
Then the example program is very simple, this is the code (this is a very simple factorial program that I am taking from the internet):
import "fmt"
import "github.com/davecheney/profile"
func fact(n int) int {
if n == 0 {
return 1
}
return n * fact(n-1)
}
func main() {
defer profile.Start(profile.CPUProfile).Stop()
fmt.Println(fact(30))
}
Thanks, Fer
source to share
As mentioned, your code is executing too fast. The reason is that pprof works by repeatedly halting your program during its execution, looking at which function is running at a given time and recording it (along with the entire function call stack). Pprof samples at 100 samples per second. This is hardcoded in runtime / pprof / pprof.go as you can easily check (see https://golang.org/src/runtime/pprof/pprof.go line 575 and comment above):
func StartCPUProfile(w io.Writer) error {
// The runtime routines allow a variable profiling rate,
// but in practice operating systems cannot trigger signals
// at more than about 500 Hz, and our processing of the
// signal is not cheap (mostly getting the stack trace).
// 100 Hz is a reasonable choice: it is frequent enough to
// produce useful data, rare enough not to bog down the
// system, and a nice round number to make it easy to
// convert sample counts to seconds. Instead of requiring
// each client to specify the frequency, we hard code it.
const hz = 100
// Avoid queueing behind StopCPUProfile.
// Could use TryLock instead if we had it.
if cpu.profiling {
return fmt.Errorf("cpu profiling already in use")
}
cpu.Lock()
defer cpu.Unlock()
if cpu.done == nil {
cpu.done = make(chan bool)
}
// Double-check.
if cpu.profiling {
return fmt.Errorf("cpu profiling already in use")
}
cpu.profiling = true
runtime.SetCPUProfileRate(hz)
go profileWriter(w)
return nil
}
The longer your program runs, the more samples can be made, and the more likely it is that short functions will be sampled. If your program ends before the first sample is made than the generated cpu.pprof file will be empty.
As you can see from the above code, the sampling rate is set using
runtime.SetCPUProfileRate(..)
If you call runtime.SetCPUProfileRate () with a different value before , you call StartCPUProfile (), you can override the sample rate. During the execution of your program, you will receive a warning message that "runtime: cannot set the speed of the processor profile until the end of the previous profile." which you can ignore. This is because pprof.go calls SetCPUProfileRate () again. Since you have already set the value, pprof will be ignored.
Also, Dave Cheney has released a new version of his profiling tool, you can find it here: https://github.com/pkg/profile . There, among other changes, you can specify the path where cpu.pprof is written to:
defer profile.Start(profile.CPUProfile, profile.ProfilePath(".")).Stop()
You can read about it here: http://dave.cheney.net/2014/10/22/simple-profiling-package-moved-updated
By the way, your fact () function will overflow quickly even if you take int64 as a parameter and return value. thirty! roughly 2 * 10 ^ 32 and int64 only stores values up to 2 ^ 63-1, which is roughly 9 * 10 18.
source to share