这里使用火焰图复现 logger 100% CPU 问题。

先看现象， 用 wrk 压测 logger

1

wrk -t1 -c100 -d30 --script=post.lua 'http://127.0.0.1:4500/marco/log'

查看 CPU 占用情况

采集 30s 的 CPU profile 火焰图

图中红色标记部分 startSink 函数中 runtime.selectgo 消耗了大量 CPU， 而 runtime.selectgo 上面只有 runtime.sellock 和 runtime.selunlock 两个操作，即大量 CPU 耗费在 select 操作上，火焰图呈秃顶状态，即瓶颈所在。

查看 startSink 实现

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

    for {
        if exit == true {
            return
        }

        if moveforward {
            fakeRead = readChan
        } else {
            fakeRead = nil
        }

        select {
        case read := <-fakeRead:
            count++
            buf.Write(read)
        case <-done:
            DiskQueue.Close()
            exit = true
        default:
            //pass
        }

        if count == GlobalConf.CntBatch || exit == true {
            hostPoolResponse := pool.Get()
            addr := hostPoolResponse.Host()
            err := handler.Publish(fmt.Sprintf("%s%s"， addr， SinkConf.Uri)， buf.Bytes())
            hostPoolResponse.Mark(err)

            if err != nil {
                Log.Error("%s"， err.Error())
                moveforward = false
                time.Sleep(1 * time.Second)
                continue
            } else {
                moveforward = true
            }

            buf.Reset()
            count = 0
        }
    }

本希望通过 moveforward 来控制 fakeRead 是否取值，而如果 fakeRead 为 nil 时， 整个 select 会一直阻塞，所以加上了 default 操作，让 select 变成非阻塞，但因为一直没有读取内容，count 没有增加而不会触发 sleep 操作。最终导致非阻塞的 select 一直空转循环，类似一个空 while 循环，占用了大量 CPU。

优化

改用其他方法实现这部分逻辑，这里不再贴出来了，重在分享发现问题的过程，改进后的火焰图在前面已给出。

总结

Golang 应用通常只要能编译通过，很少有运行时问题；而当应用遇到高CPU 、高内存占用或者作为 http 服务端响应时间长，QPS 上不去等，且不能 code review 解决时，可以尝试使用pprof 和 Flame-Graph 来分析定位问题，有奇效。当然 Golang 程序的调试及调优还有很多方法，比如直接结合go test 和 benchmark通过测用例分析热点代码、使用 go pprof分析汇编代码等。

转载:http://io.upyun.com/2018/01/21/debug-golang-application-with-pprof-and-flame-graph/