无法从 CPU 分析中获取数据

Question

我正在尝试学习使用 Go 的分析功能。考虑到这一点，我创建了这个简单的应用程序：https://github.com/Matias-Barrios/countWords 它只是计算给定 txt 文件的单词出现次数。

问题是，.cpu.prof 文件创建后，我什么也看不到。打开文件后，我立即收到此错误：

(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)

我做错了什么？

注意：我的Go版本是go版本go1.13.1linux/amd64

Answer 1

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.

修复 CPU 文件的过早关闭：

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

例如，

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

输出：

$ 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
$

Answer 2

对我来说，问题是我的代码执行得太快了。我所做的是使用 runtime.SetCPUProfileRate. Note that in runtime.pprof.StartCPUProfile 更改采样率，采样率为 100 Hz，建议为 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
}

但在我的情况下将其设置为 500 Hz 还不够快。查看 runtime.SetCPUProfileRate 的代码后，您似乎可以提供高达 100000 Hz 的频率。将其设置为足够大的值后，它解决了我的问题。

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

无法从 CPU 分析中获取数据

Unable to get data from CPU profiling

profiling

go