Can't get golang pprof working

Question

I have tried to profile some golang applications but I couldn't have that working, I have 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 says that after adding some code lines to the application, you have to execute your app, I did that and I receiveed the following message in the screen:

2015/06/16 12:04:00 profile: cpu profiling enabled, /var/folders/kg/4fxym1sn0bx02zl_2sdbmrhr9wjvqt/T/profile680799962/cpu.pprof

So, I understand that the profiling is being executed, sending info to the file.

But, when I see the file size, in any program that I test, it is always 64bytes.

When I try to open the cpu.pprof file with pprof, and I execute the "top10" command, I see that nothing is in the file:

("./fact" is my app)

go tool pprof ./fact /var/folders/kg/4fxym1sn0bx02zl_2sdbmrhr9wjvqt/T/profile680799962/cpu.pprof

top10 -->

(pprof) top10 0 of 0 total ( 0%) flat flat% sum% cum cum%

So, it is like nothing is happening when I am profiling.

I have tested it in mac (this example) and in ubuntu, with three different programs.

Do you know that I am doing wrong?

Then example program is very simple, this is the code (is a very simple factorial program that I take from 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

Answer 1

The problem is that your function is running too fast and pprof can't sample it. Try adding a loop around the fact call and sum the result to artificially prolong the program.

Answer 2

I struggled with empty pprof files, until I realized that I followed outdated blog articles.

The upstream docs are good: https://pkg.go.dev/runtime/pprof

Write a test which you want to profile, then:

go test -cpuprofile cpu.prof -memprofile mem.prof -bench .

this creates cpu.prof and mem.prof.

You can analyze them like this:

go tool pprof cpu.prof

This gives you a command-line. The "top" and "web" commands are used often.

Same for memory:

go tool pprof mem.prof

Answer 3

As inf mentioned already, your code executes too fast. The reason is that pprof works by repeatedly halting your program during its execution, looking at which function is running at that moment in time and writing that down (together with the whole function call stack). Pprof samples with a rate of 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 the comment above it):

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 probable it will become that also short running functions will be sampled. If your program finishes before even the first sample is made, than the generated cpu.pprof will be empty.

As you can see from the code above, the sampling rate is set with

runtime.SetCPUProfileRate(..)

If you call runtime.SetCPUProfileRate() with another value before you call StartCPUProfile(), you can override the sampling rate. You will receive a warning message during execution of your program telling you "runtime: cannot set cpu profile rate until previous profile has finished." which you can ignore. It results since pprof.go calls SetCPUProfileRate() again. Since you have already set the value, the one from 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, you can, among other changes, specify the path where the 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 quickly overflow, even if you take int64 as parameter and return value. 30! is roughly 2*10^32 and an int64 stores values only up to 2^63-1 which is roughly 9*10^18.