Go profiling profile is empty

Question

I'm following this tutorial on Go profiling and did as advised:

flag.Parse()
if *cpuprofile != "" {
    f, err := os.Create(*cpuprofile)
    if err != nil {
        log.Fatal(err)
    }
    pprof.StartCPUProfile(f)
    defer pprof.StopCPUProfile()
}

I then started my code with the flag -cpuprofile=myprogram.prof and the file got created. Then I started the pprof tool with

go tool pprof myprogram myprogram.prof

Well, myprogram reads a big json file and maps it to a big map[string]string, so there is a lot going on in my program, but when I do like top10 in pprof, I get:

Entering interactive mode (type "help" for commands)
(pprof) top10
profile is empty

Answer 1

Most probably your code is executing too fast, even if you think it's doing a lot. Happened to me several times.

You can play with changing the sampling rate via runtime.SetCPUProfileRate. - set it to the value above default 100, unit is Hz. Please note the Go authors don't recommend values above 500 - see explanation.

Do it just before pprof.StartCPUProfile. You will also see the warning runtime: cannot set cpu profile rate until previous profile has finished - please see this answer for explanation.

HTH

Answer 2

Most probably you are not handling the System Interrupt signal. You should explicitly handle it in order for "pprof.StopCPUProfile()" to write the profile data successfully, otherwise, the program exits to fast when exited with "ctrl+c". Here is an example solution:

var f *os.File

func main() {
    flag.Parse()
    if *cpuProfile != "" {
        cpuProfileFile, err := os.Create(*cpuProfile)
        if err != nil {
            log.Fatal(err)
        }
       defer f.Close()
       pprof.StartCPUProfile(cpuProfileFile)
    }
        
    c := make(chan os.Signal, 2)                    
    signal.Notify(c, os.Interrupt, syscall.SIGTERM) // subscribe to system signals
    onKill := func(c chan os.Signal) {
        select {
        case <-c: 
            defer f.Close()
            defer pprof.StopCPUProfile()
            defer os.Exit(0)
        }
    }

    // try to handle os interrupt(signal terminated)
    go onKill(c)
}

Answer 3

For profiling go programs you can use pprof as a web server. You need to add a bit of code to your main file of your go program/application to start the pprof server which will continuously serve the resource usage details for your program on the server and you can easily get all the relevant details. If you follow the code below the you can see the details of your program on your browser at http://localhost:6060/debug/pprof/ (Need to refresh the page to see the updated data)

You may see the code snippet below or go to the following link for the complete code: github.com/arbaaz-khan/GoLangLearning/blob/master/ProfilingGoProgram/profile_go_prog.go

go func() {
    log.Printf("Starting Server! \t Go to http://localhost:6060/debug/pprof/\n")
    err := http.ListenAndServe("localhost:6060", nil)
    if err != nil {
        log.Printf("Failed to start the server! Error: %v", err)
        wg.Done()
    }
}()

Hope it helps!

Answer 4

If you use ctrl-c to stop the program, make sure you pass in profile.NoShutdownHook param in profile.Start().

Answer 5

did you handle ctrl-c signal? if you haven't, the program is stopped by OS. you must make sure the program is exit normally, only then the profile will be written to file. you can also check netprof module.

Answer 6

For me, the problem was my code was executing too fast. What I did is changing the sampling rate using runtime.SetCPUProfileRate. Note that in runtime.pprof.StartCPUProfile the sampling rate is 100 Hz and recommended to be 500 Hz at most.

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

    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
}

But setting it to 500 Hz wasn't fast enough in my case. After looking into the code of runtime.SetCPUProfileRate it seems that you can provide frequencies up to 1000000 Hz. After setting it to a large enough value it solved my issue.

// SetCPUProfileRate sets the CPU profiling rate to hz samples per second.
// If hz <= 0, SetCPUProfileRate turns off profiling.
// If the profiler is on, the rate cannot be changed without first turning it off.
//
// Most clients should use the runtime/pprof package or
// the testing package's -test.cpuprofile flag instead of calling
// SetCPUProfileRate directly.

func SetCPUProfileRate(hz int) {

    // Clamp hz to something reasonable.
    if hz < 0 {
        hz = 0
    }
    if hz > 1000000 {
        hz = 1000000
    }

    lock(&cpuprof.lock)
    if hz > 0 {
        if cpuprof.on || cpuprof.log != nil {
            print("runtime: cannot set cpu profile rate until previous profile has finished.\n")
            unlock(&cpuprof.lock)
            return
        }

        cpuprof.on = true
        cpuprof.log = newProfBuf(1, 1<<17, 1<<14)
        hdr := [1]uint64{uint64(hz)}
        cpuprof.log.write(nil, nanotime(), hdr[:], nil)
        setcpuprofilerate(int32(hz))
    } else if cpuprof.on {
        setcpuprofilerate(0)
        cpuprof.on = false
        cpuprof.addExtra()
        cpuprof.log.close()
    }
    unlock(&cpuprof.lock)
}