小结：
1、内存消耗分析 list peek 定位到函数
https://mp.weixin.qq.com/s/_LovnIqJYAuDpTm2QmUgrA
使用pprof和go-torch排查golang的性能问题
原创 felix021 felix021 2019-09-22
最近线上服务压力很大，api的p99有点扛不住。
广告业务对延时的要求普遍比较严格，有些adx设置的超时时间低至100ms，因此亟需找出性能热点。
根据对目前系统情况的估计（和metrics埋点数据），大致估计问题出在广告的正排环节。
使用 pprof 也证明了这一块确实是热点：
$ go tool pprof http://$IP:$PORT/debug/pprof/profile...(pprof) top 10Showing nodes accounting for 25.50s, 32.63% of 78.14s totalDropped 1533 nodes (cum <= 0.39s)Showing top 10 nodes out of 284flat flat% sum% cum cum%4.56s 5.84% 5.84% 4.87s 6.23% syscall.Syscall4.03s 5.16% 10.99% 4.03s 5.16% runtime.aeshashbody3.50s 4.48% 15.47% 6.01s 7.69% git.xxx.org/xxx/target.NewFilter2.78s 3.56% 19.03% 3.73s 4.77% runtime.mapaccess2_fast642.63s 3.37% 22.40% 4.52s 5.78% runtime.mapiternext2.08s 2.66% 25.06% 2.16s 2.76% runtime.heapBitsForObject1.65s 2.11% 27.17% 1.93s 2.47% runtime.mapaccess1_fast641.57s 2.01% 29.18% 2.96s 3.79% runtime.mapaccess21.43s 1.83% 31.01% 2.06s 2.64% runtime.runqgrab1.27s 1.63% 32.63% 1.27s 1.63% runtime.epollwait(pprof) pngGenerating report in profile001.png (使用生成的线框图查看耗时）
其中第三行 NewFilter 就是正排过滤函数。因为一些历史原因，系统里不是所有定向条件都使用了倒排，正排实现起来毕竟简单、容易理解，而一旦开了这个口子，就会有越来越多正排加进来，推测是这个原因导致了性能的逐渐衰退。
经过讨论，D同学花了一周多的时间，逐个梳理重写。在Libra（字节跳动内部的ABTest平台，参考谷歌分层实验框架方案）上开实验，平均耗时 -9%，从统计数据上来说，实验组比对照组有了显著的改进，但从最终结果上，整体的p95、p99超时都出现了进一步恶化。
这说明真正的问题不在于正排的计算，优化的思路出现了偏差。
考虑到晚高峰期间的cpu占用率也只是刚超过50%，也就是说有可能性能问题在于锁，但pprof的 block 和 mutex 都是空的，没有线索。
猜测问题有可能在日志，代码里确实用得不少。日志用的是 github.com/ngaut/logging 库，每一次调用都会用到两个全局mutex。但通过调整log level 为error级别，大幅减少了日志量，并没有看到性能的改善。
经过搜索，发现 uber 基于 pprof 开发了一个神器 go-torch，可以生成火焰图。安装好 go-torch 及依赖 FlameGraph 以后执行：
$ go-torch -u http://$IP:$PORT -f cpu.svgINFO[14:52:23] Run pprof command: go tool pprof -raw -seconds 30 http://$IP:$PORT/debug/pprof/profileINFO[14:52:54] Writing svg to cpu.svg
用 Chrome 打开 cpu.svg，人肉排查：
可以看到，在NewFilter旁边竟然还有一个耗时接近的 runtime.growslice ，结合实际代码（略作简化），可以推测是 slice 的初始化长度不足。
matchAds := make([]*ad, 0, 4096)adsBitMap.GetList(func(seq int) {if NewFilter(ctx, ad) {matchAds = append(matchAds, adlist[seq])}})// 顺便提一下，bitmap是一个uint64数组，GetList(f) 是将每一个等于1的bit索引传给 f// GetList方法里面用了cpu的BSF指令来提高性能。
实际上最终定向后得到的广告往往在数万甚至数十万的级别，而 go 的 slice 扩容在超过1024个元素以后是1.25倍，可想而知会出现大量的内存分配和拷贝，导致性能随着广告数量的增加逐渐恶化。最近的广告数量也确实有了大幅的上升 —— 逻辑上形成了闭环。
经过优化，使用更大的初始化长度，并且使用 sync.Pool 来进一步减少内存分配，最终上线后p95和p99都下降了超过50%，效果显著。
参考文章：
golang 使用pprof和go-torch做性能分析
https://www.cnblogs.com/li-peng/p/9391543.html
Go语言性能优化工具pprof文本输出的含义_梁喜健_新浪博客 http://blog.sina.com.cn/s/blog_48c95a190102xtse.html
Go语言性能优化工具pprof文本输出的含义
(2018-10-13 12:02:19)
对于广大gopher来说，pprof是做性能优化时经常会用到的一个工具，但很多刚刚入坑的开发者难免会对pprof文本输出中的某些字段感到困惑，这里不妨做一个简单的说明。以下是一段典型的pprof函数耗时的文本输出，其中前几行比较容易理解，其说明了显示出来的函数耗时总计占用了5.73s，而全部耗时为6.21秒，所以显示出来的函数耗时占总体的92.27%，其中有cum耗时小于0.03秒的67个函数耗时被丢弃而未予显示。
(pprof) top78
Showing nodes accounting for 5.73s, 92.27% of 6.21s total
Dropped 67 nodes (cum <= 0.03s)
Showing top 78 nodes out of 79
flat flat% sum% cum cum%
4.14s 66.67% 66.67% 4.14s 66.67% runtime.kevent /usr/local/go/src/runtime/sys_darwin_amd64.s
0.52s 8.37% 75.04% 0.52s 8.37% runtime.mach_semaphore_signal /usr/local/go/src/runtime/sys_darwin_amd64.s
0.34s 5.48% 80.52% 0.34s 5.48% runtime.mach_semaphore_timedwait /usr/local/go/src/runtime/sys_darwin_amd64.s
0.17s 2.74% 83.25% 0.17s 2.74% runtime.mach_semaphore_wait /usr/local/go/src/runtime/sys_darwin_amd64.s
0.13s 2.09% 85.35% 0.13s 2.09% runtime.scanstack /usr/local/go/src/runtime/mgcmark.go
0.07s 1.13% 86.47% 0.07s 1.13% runtime.memmove /usr/local/go/src/runtime/memmove_amd64.s
0.06s 0.97% 87.44% 0.06s 0.97% runtime.usleep /usr/local/go/src/runtime/sys_darwin_amd64.s
接下来的一大坨文本涉及到了这样几列字段：flat和flat%、sum%、cum和cum%，其中flat代表的是该函数自身代码的执行时长，而cum代表的是该函数自身代码+所有调用的函数的执行时长。这样解释可能不太直观，我们以下面的例子来说明，函数b由三部分组成：调用函数c、自己直接处理一些事情、调用函数d，其中调用函数c耗时1秒，自己直接处理事情耗时3秒，调用函数d耗时2秒，那么函数b的flat耗时就是3秒，cum耗时就是6秒。
func b() {
c() // takes 1s
do something directly // takes 3s
d() // takes 2s
}
至于flat%和cum%指的就是flat耗时和cum耗时占总耗时（也就是6.21秒）的百分比，而最后一个sum%指的就是每一行的flat%与上面所有行的flat%总和，代表从上到下的累计值，比如第二行的75.04%就等于第一行flat%的66.67%+本行flat%的8.37%，下面的以此类推。
https://mp.weixin.qq.com/s/4Vn1Rq82wOFiLdEmjXU0fw
go pprof与线上事故：一次成功的定位与失败的复现
原创 唐银鹏 从菜鸟到大佬 2020-05-01
Flat：函数自身运行耗时
Flat%：函数自身耗时比例
Sum%：指的就是每一行的flat%与上面所有行的flat%总和
Cum：当前函数加上它之上的调用运行总耗时
Cum%：当前函数加上它之上的调用运行总耗时比例
举例说明：函数b由三部分组成：调用函数c、自己直接处理一些事情、调用函数d，其中调用函数c耗时1秒，自己直接处理事情耗时3秒，调用函数d耗时2秒，那么函数b的flat耗时就是3秒，cum耗时就是6秒。
// 该示例在文末参考列表的博客中func b() {c() // takes 1sdo something directly // takes 3sd() // takes 2s}
[test@demo ~]$ go tool pprof http://localhost:8003/debug/pprof/profile
Fetching profile over HTTP from http://localhost:8003/debug/pprof/profile
Saved profile in /home/test/pprof/pprof.admin.samples.cpu.010.pb.gz
File: admin
Type: cpu
Time: Dec 24, 2020 at 9:48am (CST)
Duration: 30s, Total samples = 660ms ( 2.20%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top32
Showing nodes accounting for 600ms, 90.91% of 660ms total
Showing top 32 nodes out of 228
flat flat% sum% cum cum%
130ms 19.70% 19.70% 160ms 24.24% syscall.Syscall
100ms 15.15% 34.85% 100ms 15.15% runtime.futex
30ms 4.55% 39.39% 30ms 4.55% runtime.epollwait
30ms 4.55% 43.94% 30ms 4.55% syscall.Syscall6
20ms 3.03% 46.97% 20ms 3.03% runtime.mapassign_faststr
20ms 3.03% 50.00% 20ms 3.03% runtime.mapiterinit
20ms 3.03% 53.03% 20ms 3.03% runtime.usleep
10ms 1.52% 54.55% 120ms 18.18% AdminSite/middleware/auth/v1.(*auth0Client).CheckAdminAuth // 注意此处，该函数内部发起了grpc请求，请求服务端认证token，故flat 10ms 而 cum 120ms 。 10ms 1.52% 56.06% 10ms 1.52% aeshashbody
10ms 1.52% 57.58% 20ms 3.03% github.com/go-kratos/kratos/pkg/net/http/blademaster.parseMetadataTo
10ms 1.52% 59.09% 10ms 1.52% golang.org/x/net/http2.(*Framer).WriteHeaders
10ms 1.52% 60.61% 10ms 1.52% google.golang.org/grpc.(*pickerWrapper).pick
10ms 1.52% 62.12% 10ms 1.52% google.golang.org/grpc/internal/transport.(*http2Client).handleData
10ms 1.52% 63.64% 10ms 1.52% google.golang.org/grpc/internal/transport.(*outStreamList).dequeue
10ms 1.52% 65.15% 10ms 1.52% google.golang.org/protobuf/internal/impl.(*stringConverter).PBValueOf
10ms 1.52% 66.67% 10ms 1.52% internal/poll.runtime_pollSetDeadline
10ms 1.52% 68.18% 10ms 1.52% memeqbody
10ms 1.52% 69.70% 10ms 1.52% net.sockaddrToTCP
10ms 1.52% 71.21% 10ms 1.52% net/http.Header.sortedKeyValues
10ms 1.52% 72.73% 10ms 1.52% net/url.escape
10ms 1.52% 74.24% 10ms 1.52% runtime.(*spanSet).push
10ms 1.52% 75.76% 10ms 1.52% runtime.acquireSudog
10ms 1.52% 77.27% 10ms 1.52% runtime.checkTimers
10ms 1.52% 78.79% 10ms 1.52% runtime.efaceeq
10ms 1.52% 80.30% 10ms 1.52% runtime.gcWriteBarrier
10ms 1.52% 81.82% 10ms 1.52% runtime.gentraceback
10ms 1.52% 83.33% 10ms 1.52% runtime.getitab
10ms 1.52% 84.85% 30ms 4.55% runtime.mallocgc
10ms 1.52% 86.36% 10ms 1.52% runtime.mapaccess1
10ms 1.52% 87.88% 20ms 3.03% runtime.mapaccess1_faststr
10ms 1.52% 89.39% 10ms 1.52% runtime.mapassign
10ms 1.52% 90.91% 10ms 1.52% runtime.nextFreeFast (inline)
(pprof) top32 -cum // 按照cum逆序 Showing nodes accounting for 240ms, 36.36% of 660ms total
Showing top 32 nodes out of 228
flat flat% sum% cum cum%
0 0% 0% 320ms 48.48% net/http.(*conn).serve
0 0% 0% 240ms 36.36% github.com/go-kratos/kratos/pkg/net/http/blademaster.(*Engine).ServeHTTP
0 0% 0% 240ms 36.36% github.com/go-kratos/kratos/pkg/net/http/blademaster.(*Engine).handleContext
0 0% 0% 240ms 36.36% net/http.serverHandler.ServeHTTP
0 0% 0% 200ms 30.30% github.com/go-kratos/kratos/pkg/net/http/blademaster.(*Context).Next
0 0% 0% 200ms 30.30% github.com/go-kratos/kratos/pkg/net/http/blademaster.HandlerFunc.ServeHTTP
0 0% 0% 200ms 30.30% github.com/go-kratos/kratos/pkg/net/http/blademaster.Recovery.func1
0 0% 0% 200ms 30.30% github.com/go-kratos/kratos/pkg/net/http/blademaster.Trace.func1
0 0% 0% 190ms 28.79% github.com/go-kratos/kratos/pkg/net/http/blademaster.Logger.func1
130ms 19.70% 19.70% 160ms 24.24% syscall.Syscall
0 0% 19.70% 150ms 22.73% internal/poll.ignoringEINTR
0 0% 19.70% 120ms 18.18% AdminSite/internal/server/http.MidAuthHandler
10ms 1.52% 21.21% 120ms 18.18% AdminSite/middleware/auth/v1.(*auth0Client).CheckAdminAuth
0 0% 21.21% 110ms 16.67% github.com/go-kratos/kratos/pkg/net/rpc/warden.(*Client).recovery.func1
0 0% 21.21% 110ms 16.67% github.com/go-kratos/kratos/pkg/net/rpc/warden.chainUnaryClient.func2
0 0% 21.21% 110ms 16.67% github.com/go-kratos/kratos/pkg/net/rpc/warden.chainUnaryClient.func2.1
0 0% 21.21% 110ms 16.67% github.com/go-kratos/kratos/pkg/net/rpc/warden.clientLogging.func1
0 0% 21.21% 110ms 16.67% google.golang.org/grpc.(*ClientConn).Invoke
100ms 15.15% 36.36% 100ms 15.15% runtime.futex
0 0% 36.36% 90ms 13.64% google.golang.org/grpc/internal/transport.(*loopyWriter).run
0 0% 36.36% 90ms 13.64% google.golang.org/grpc/internal/transport.newHTTP2Client.func3
0 0% 36.36% 90ms 13.64% runtime.findrunnable
0 0% 36.36% 90ms 13.64% runtime.mcall
0 0% 36.36% 90ms 13.64% runtime.schedule
0 0% 36.36% 80ms 12.12% internal/poll.(*FD).Read
0 0% 36.36% 80ms 12.12% internal/poll.(*FD).Read.func1
0 0% 36.36% 80ms 12.12% net.(*conn).Read
0 0% 36.36% 80ms 12.12% net.(*netFD).Read
0 0% 36.36% 80ms 12.12% runtime.park_m
0 0% 36.36% 80ms 12.12% syscall.Read (inline)
0 0% 36.36% 80ms 12.12% syscall.read
0 0% 36.36% 70ms 10.61% github.com/go-kratos/kratos/pkg/net/rpc/warden.(*Client).handle.func1
(pprof) top32 -flat // 按照flat逆序 Ignore expression matched no samples
Active filters:
ignore=flat
Showing nodes accounting for 600ms, 90.91% of 660ms total
Showing top 32 nodes out of 228
flat flat% sum% cum cum%
130ms 19.70% 19.70% 160ms 24.24% syscall.Syscall
100ms 15.15% 34.85% 100ms 15.15% runtime.futex
30ms 4.55% 39.39% 30ms 4.55% runtime.epollwait
30ms 4.55% 43.94% 30ms 4.55% syscall.Syscall6
20ms 3.03% 46.97% 20ms 3.03% runtime.mapassign_faststr
20ms 3.03% 50.00% 20ms 3.03% runtime.mapiterinit
20ms 3.03% 53.03% 20ms 3.03% runtime.usleep
10ms 1.52% 54.55% 120ms 18.18% AdminSite/middleware/auth/v1.(*auth0Client).CheckAdminAuth
10ms 1.52% 56.06% 10ms 1.52% aeshashbody
10ms 1.52% 57.58% 20ms 3.03% github.com/go-kratos/kratos/pkg/net/http/blademaster.parseMetadataTo
10ms 1.52% 59.09% 10ms 1.52% golang.org/x/net/http2.(*Framer).WriteHeaders
10ms 1.52% 60.61% 10ms 1.52% google.golang.org/grpc.(*pickerWrapper).pick
10ms 1.52% 62.12% 10ms 1.52% google.golang.org/grpc/internal/transport.(*http2Client).handleData
10ms 1.52% 63.64% 10ms 1.52% google.golang.org/grpc/internal/transport.(*outStreamList).dequeue
10ms 1.52% 65.15% 10ms 1.52% google.golang.org/protobuf/internal/impl.(*stringConverter).PBValueOf
10ms 1.52% 66.67% 10ms 1.52% internal/poll.runtime_pollSetDeadline
10ms 1.52% 68.18% 10ms 1.52% memeqbody
10ms 1.52% 69.70% 10ms 1.52% net.sockaddrToTCP
10ms 1.52% 71.21% 10ms 1.52% net/http.Header.sortedKeyValues
10ms 1.52% 72.73% 10ms 1.52% net/url.escape
10ms 1.52% 74.24% 10ms 1.52% runtime.(*spanSet).push
10ms 1.52% 75.76% 10ms 1.52% runtime.acquireSudog
10ms 1.52% 77.27% 10ms 1.52% runtime.checkTimers
10ms 1.52% 78.79% 10ms 1.52% runtime.efaceeq
10ms 1.52% 80.30% 10ms 1.52% runtime.gcWriteBarrier
10ms 1.52% 81.82% 10ms 1.52% runtime.gentraceback
10ms 1.52% 83.33% 10ms 1.52% runtime.getitab
10ms 1.52% 84.85% 30ms 4.55% runtime.mallocgc
10ms 1.52% 86.36% 10ms 1.52% runtime.mapaccess1
10ms 1.52% 87.88% 20ms 3.03% runtime.mapaccess1_faststr
10ms 1.52% 89.39% 10ms 1.52% runtime.mapassign
10ms 1.52% 90.91% 10ms 1.52% runtime.nextFreeFast (inline)
(pprof)
go tool pprof http://127.0.0.1:123/debug/pprof/heap
使用list命令直接可以查看到具体是哪一行分配了多少内存
list Output annotated source for functions matching regexp
pdf Outputs a graph in PDF format
peek Output callers/callees of functions matching regexp
(pprof) list new
Total: 1.02MB
ROUTINE ======================== google.golang.org/grpc/internal/transport.newFramer in /home/shawn/go/pkg/mod/google.golang.org/grpc@v1.29.1/internal/transport/http_util.go
0 528.17kB (flat, cum) 50.74% of Total
. . 658: if writeBufferSize < 0 {
. . 659: writeBufferSize = 0
. . 660: }
. . 661: var r io.Reader = conn
. . 662: if readBufferSize > 0 {
. 528.17kB 663: r = bufio.NewReaderSize(r, readBufferSize)
. . 664: }
. . 665: w := newBufWriter(conn, writeBufferSize)
. . 666: f := &framer{
. . 667: writer: w,
. . 668: fr: http2.NewFramer(w, r),
ROUTINE ======================== google.golang.org/grpc/internal/transport.newHTTP2Client in /home/shawn/go/pkg/mod/google.golang.org/grpc@v1.29.1/internal/transport/http2_client.go
0 528.17kB (flat, cum) 50.74% of Total
. . 244: localAddr: conn.LocalAddr(),
. . 245: authInfo: authInfo,
. . 246: readerDone: make(chan struct{}),
. . 247: writerDone: make(chan struct{}),
. . 248: goAway: make(chan struct{}),
. 528.17kB 249: framer: newFramer(conn, writeBufSize, readBufSize, maxHeaderListSize),
. . 250: fc: &trInFlow{limit: uint32(icwz)},
. . 251: scheme: scheme,
. . 252: activeStreams: make(map[uint32]*Stream),
. . 253: isSecure: isSecure,
. . 254: perRPCCreds: perRPCCreds,
(pprof) (pprof) peek new
Showing nodes accounting for 1040.92kB, 100% of 1040.92kB total
----------------------------------------------------------+-------------
flat flat% sum% cum cum% calls calls% + context
----------------------------------------------------------+-------------
528.17kB 100% | google.golang.org/grpc/internal/transport.newHTTP2Client
0 0% 0% 528.17kB 50.74% | google.golang.org/grpc/internal/transport.newFramer
528.17kB 100% | bufio.NewReaderSize (inline)
----------------------------------------------------------+-------------
528.17kB 100% | google.golang.org/grpc/internal/transport.NewClientTransport
0 0% 0% 528.17kB 50.74% | google.golang.org/grpc/internal/transport.newHTTP2Client
528.17kB 100% | google.golang.org/grpc/internal/transport.newFramer
----------------------------------------------------------+-------------
(pprof)
list Output annotated source for functions matching regexp
pdf Outputs a graph in PDF format
peek Output callers/callees of functions matching regexp
