Unable to get data from CPU profiling

Question

Im trying to learn to use Go's profiling capabilities. With that in mind I crated this simple app : https://github.com/Matias-Barrios/countWords which simply count the number of word occurrences for a given txt file.

The problem is, I can not see anything once the .cpu.prof file has been created. As soon as I open the file I get this error :

(0) matias #> go tool pprof .cpu.prof 
File: main
Type: cpu
Time: Oct 9, 2019 at 12:38am (-03)
Duration: 201.31ms, Total samples = 0 
No samples were found with the default sample value type.
Try "sample_index" command to analyze different sample values.
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 0, 0% of 0 total
      flat  flat%   sum%        cum   cum%
(pprof) 

What am I doing wrong here?

Note : My Go version is go version go1.13.1 linux/amd64

Answer 1

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.

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 100000 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)
}

Answer 2

The Go Programming Language Specification

Defer statements

A "defer" statement invokes a function whose execution is deferred to the moment the surrounding function returns, either because the surrounding function executed a return statement, reached the end of its function body, or because the corresponding goroutine is panicking.

---

Fix the premature Close of the CPU file:

func CPUprofiling() {
    fd, err := os.Create(".cpu.prof")
    if err != nil {
        log.Fatalln(err.Error())
    }
    defer fd.Close()
    pprof.StartCPUProfile(fd)
    defer pprof.StopCPUProfile()
}

For example,

package main

import (
    "bufio"
    "flag"
    "fmt"
    "log"
    "os"
    "runtime/pprof"
    "strings"
)

var filename string

func main() {
    cpu, err := os.Create(".cpu.prof")
    if err != nil {
        log.Fatalln(err.Error())
    }
    defer cpu.Close()
    pprof.StartCPUProfile(cpu)
    defer pprof.StopCPUProfile()

    flag.StringVar(&filename, "f", "", "Path to the input file")
    flag.Parse()
    if filename == "" {
        flag.Usage()
        log.Fatalln()
    }
    for w, c := range getResults(filename) {
        fmt.Printf("%-20s\t%d\n", w, c)
    }

    mem, err := os.Create(".mem.prof")
    if err != nil {
        log.Fatalln(err.Error())
    }
    defer mem.Close()
    pprof.WriteHeapProfile(mem)
}

func getResults(path string) map[string]int {
    results := make(map[string]int)
    file, err := os.Open(filename)
    defer file.Close()
    if err != nil {
        log.Fatalln(err.Error())
    }
    scanner := bufio.NewScanner(file)
    scanner.Split(bufio.ScanWords)
    for scanner.Scan() {
        results[removeNonWordChars(scanner.Text())]++
    }
    delete(results, "")
    return results
}

func removeNonWordChars(input string) string {
    var result strings.Builder
    result.Grow(len(input))
    for _, r := range strings.ToLower(input) {
        if r >= 'a' && r <= 'z' {
            _, err := result.WriteRune(r)
            if err != nil {
                log.Fatalln(err.Error())
            }
        }
    }
    return result.String()
}

Output:

$ go tool pprof .cpu.prof
File: main
Type: cpu
Time: Oct 9, 2019 at 5:39am (EDT)
Duration: 600.79ms, Total samples = 390ms (64.91%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 320ms, 82.05% of 390ms total
Showing top 10 nodes out of 43
      flat  flat%   sum%        cum   cum%
     110ms 28.21% 28.21%      110ms 28.21%  syscall.Syscall
      60ms 15.38% 43.59%       90ms 23.08%  runtime.mapassign_faststr
      40ms 10.26% 53.85%       40ms 10.26%  unicode/utf8.DecodeRune
      30ms  7.69% 61.54%       30ms  7.69%  strings.(*Builder).WriteRune
      20ms  5.13% 66.67%       20ms  5.13%  runtime.slicebytetostring
      20ms  5.13% 71.79%       20ms  5.13%  strings.ToLower
      10ms  2.56% 74.36%       60ms 15.38%  bufio.ScanWords
      10ms  2.56% 76.92%       10ms  2.56%  bufio.isSpace
      10ms  2.56% 79.49%       10ms  2.56%  fmt.(*buffer).writeString
      10ms  2.56% 82.05%       10ms  2.56%  memeqbody
(pprof) quit
$