Go 代码调优利器 - 火焰图

转自：http://lihaoquan.me/2017/1/1/Profiling-and-Optimizing-Go-using-go-torch.html

Go 代码调优利器 - 火焰图

前言
作为DevOps，我们在日常搞的项目,从开发到测试然后上线，我们基本都局限在功能的单元测试，对一些性能上的细节很多人包括我自己，往往都选择视而不见， 后果往往让工具应用产生不可预测的灾难（it’s true）。有些人说底层的东西，或者代码层面的性能调优太深入了，性能提升可以用硬件来补，但我觉得这只是自欺欺人的想法，提升硬件配置这种土豪方法不能一直长存的，更何况 现在我们的工具哪个不是分布式的，哪个不是集群上跑的，为了冗余也好，为了易于横向扩展也罢，不可能保证所有的服务器都具备高性能的，我们不能让某些低配的服务器运行我们有性能缺陷的代码产生短板，成为瓶颈。
我记得2016年参与了一些通用服务agent的开发，由于要运行于公司全网几乎所有服务器中，生产上的环境复杂程度超乎我们想象。
一个问题到达很深入的时候，就已经是共同的问题
更何况Go语言已经为开发者内置配套了很多性能调优监控的好工具和方法，这大大提升了我们profile分析的效率，除了编码技巧，不断在实战项目中磨炼自己 对性能问题分析的能力，对日后我们在项目的把控力和一些功能布局都是很有帮助。
Golang的性能调优手段
Go语言内置的CPU和Heap profiler
Go强大之处是它已经在语言层面集成了profile采样工具,并且允许我们在程序的运行时使用它们，
使用Go的profiler我们能获取以下的样本信息：
CPU profiles
Heap profiles
block profile、traces等

Go语言常见的profiling使用场景
基准测试文件：例如使用命令go test . -bench . -cpuprofile prof.cpu 生成采样文件后，再通过命令 go tool pprof [binary] prof.cpu 来进行分析。

import _ net/http/pprof：如果我们的应用是一个web服务，我们可以在http服务启动的代码文件(eg: main.go)添加 import _ net/http/pprof，这样我们的服务 便能自动开启profile功能，有助于我们直接分析采样结果。

通过在代码里面调用 runtime.StartCPUProfile或者runtime.WriteHeapProfile

更多调试的使用，建议可以阅读The Go Blog的 Profiling Go Programs
go-torch
在没有使用go-torch之前，我们要分析一分profile文件的时候，遇到结构简单的还好，但遇到一些调用关系复杂的，我相信大部分程序员都觉得无从下手，如下图：

hard-to-read-profile
这样的结构，带给我们的是晦涩难懂的感觉，我们需要寻求更直观，更简单的分析工具。
go-torch是Uber
公司开源的一款针对Go语言程序的火焰图生成工具，能收集 stack traces,并把它们整理成火焰图，直观地程序给开发人员。
go-torch是基于使用BrendanGregg创建的火焰图工具生成直观的图像，很方便地分析Go的各个方法所占用的CPU的时间， 火焰图是一个新的方法来可视化CPU的使用情况，本文中我会展示如何使用它辅助我们排查问题。
go-torch项目首页
下图是火焰图的一个事例展示：
df
这样的展示方式相比之前的树状的，有了更直观的表现，
好，我们了解应该差不多了，可以开始安装并使用go-torch了
安装
1.首先，我们要配置FlameGraph
的脚本
FlameGraph 是profile数据的可视化层工具，已被广泛用于Python和Node

git clone https://github.com/brendangregg/FlameGraph.git

2.检出完成后，把flamegraph.pl
拷到我们机器环境变量$PATH的路径中去，例如：
cp flamegraph.pl /usr/local/bin

3.在终端输入 flamegraph.pl -h
是否安装FlameGraph成功
$ flamegraph.pl -hOption h is ambiguous (hash, height, help)USAGE: /usr/local/bin/flamegraph.pl [options] infile > outfile.svg --title # change title text --width # width of image (default 1200) --height # height of each frame (default 16) --minwidth # omit smaller functions (default 0.1 pixels) --fonttype # font type (default "Verdana") --fontsize # font size (default 12) --countname # count type label (default "samples") --nametype # name type label (default "Function:") --colors # set color palette. choices are: hot (default), mem, io, # wakeup, chain, java, js, perl, red, green, blue, aqua, # yellow, purple, orange --hash # colors are keyed by function name hash --cp # use consistent palette (palette.map) --reverse # generate stack-reversed flame graph --inverted # icicle graph --negate # switch differential hues (blue<->red) --help # this message eg, /usr/local/bin/flamegraph.pl --title="Flame Graph: malloc()" trace.txt > graph.svg

4.安装go-torch
有了flamegraph的支持，我们接下来要使用go-torch展示profile的输出，而安装go-torch很简单，我们使用下面的命令即可完成安装
go get -v github.com/uber/go-torch

5.使用go-torch命令
$ go-torch -hUsage: go-torch [options] [binary] <profile source>pprof Options: -u, --url= Base URL of your Go program (default: http://localhost:8080) -s, --suffix= URL path of pprof profile (default: /debug/pprof/profile) -b, --binaryinput= File path of previously saved binary profile. (binary profile is anything accepted by https://golang.org/cmd/pprof) --binaryname= File path of the binary that the binaryinput is for, used for pprof inputs -t, --seconds= Number of seconds to profile for (default: 30) --pprofArgs= Extra arguments for pprofOutput Options: -f, --file= Output file name (must be .svg) (default: torch.svg) -p, --print Print the generated svg to stdout instead of writing to file -r, --raw Print the raw call graph output to stdout instead of creating a flame graph; use with Brendan Gregg's flame graph perl script (see https://github.com/brendangregg/FlameGraph) --title= Graph title to display in the output file (default: Flame Graph) --width= Generated graph width (default: 1200) --hash Colors are keyed by function name hash --colors= set color palette. choices are: hot (default), mem, io, wakeup, chain, java, js, perl, red, green, blue, aqua, yellow, purple, orange --cp Use consistent palette (palette.map) --reverse Generate stack-reversed flame graph --inverted icicle graphHelp Options: -h, --help Show this help message

按照上面的几个步骤，我们基本可以具备生成我们的火焰图的前提条件了，但生成火焰图并不是这篇文章所要表达的目的，记住，我们的目的是： 找出问题，分析问题，解决问题！
下面我们就结合案例，介绍如何使用火焰图辅助性能调优吧
调优实例
demo代码
demo是一个web的服务端程序，对外提供了两个用于我们演示的HTTP接口
我们先阅读 main.go
func main() { flag.Parse() //高级接口 http.HandleFunc("/advance", handler.WithAdvanced(handler.Simple)) //简单接口 http.HandleFunc("/simple", handler.Simple) http.HandleFunc("/", index) fmt.Println("Starting Server on", hostPort) if err := http.ListenAndServe(hostPort, nil); err != nil { log.Fatalf("HTTP Server Failed: %v", err) }}

启动服务后, 浏览器访问 http://localhost:9090/simple 和 http://localhost:9090/advance
正常都会输出
Hello VIP!

虽然输出的内容是一样的，但 /advance 接口附加了一些统计功能，我们可以在终端上启动web服务时，多增加printStats参数：
$ go run main.go -printStats

当我们刷新接口地址的时候，终端都会把访问信息打印出来，如下：
IncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 418.07µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 71.084µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 93.233µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 88.246µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 99.305µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 82.383µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 86.55µsIncCounter: handler.received.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 1RecordTimer: handler.latency.lihaoquantekiMacBook-Pro.advance.Mac-OS.Chrome = 109.914µs

OK, 例子很简单而且表面上看起来web服务都很正常，但背后真的是风平浪静吗？毕竟我们的并发量还没真正上去，cpu和内存都还没经受考验呢！
我们继续保持web服务处于工作状态，然后输入以下命令：
kapok -d=35 -c=1000 http://localhost:9090/advance

kapok 是我自己开发用于压测的工具，除此之外，可使用go-wrk 或者 vegeta等http压测工具代替

在上面的压测过程中，我们再新建一个终端窗口输入以下命令，生成我们的profile文件：
$ go tool pprof --seconds 25 http://localhost:9090/debug/pprof/profile

命令中，我们设置了25秒的采样时间，当看到(pprof)的时候，我们输入 web
, 表示从浏览器打开
Fetching profile from http://localhost:9090/debug/pprof/profile?seconds=25Please wait... (25s)Saved profile in /Users/lihaoquan/pprof/pprof.localhost:9090.samples.cpu.014.pb.gzEntering interactive mode (type "help" for commands)(pprof) web

这样我们可以得到一个完整的程序调用性能采样profile的输出,如下图：

web-pprof
就像评分报告一样，模块间的调用耗时都能从图中得到展现，但是, 这种图有个缺点，就是层次很深的话，这周发散性的层级关系有点不友好，我们可能需要换一种展示方式来告诉我们应用是否有问题
好，我们回调终端上，依旧调用压力测试工具：
kapok -d=35 -c=1000 http://localhost:9090/advance

不过，我们决定使用go-torch来生成采样报告:
go-torch -u http://localhost:9090 -t 30

大概等三十秒后，go-torch完成采用后，会输出以下信息：
Writing svg to torch.svg

torch.svg
是go-torch采样结束后自动生成的profile文件，我们也照旧用浏览器进行打开：

f1

嗯，这样体验好多了，接下来我们可以基于这个火焰图诊断一下我们的web服务是否是“健康”的！
火焰图的y轴表示cpu调用方法的先后，x轴表示在每个采样调用时间内，方法所占的时间百分比，越宽代表占据cpu时间越多

我们发现
os.Hostname

这个地方很明显有可疑，因为按正常理解一个回去hostname的方法，不应该占据这么多的资源啊，我们先去代码里看下：
func getStatsTags(r *http.Request) map[string]string { userBrowser, userOS := parseUserAgent(r.UserAgent()) stats := map[string]string{ "browser": userBrowser, "os": userOS, "endpoint": filepath.Base(r.URL.Path), } host, err := os.Hostname() if err == nil { if idx := strings.IndexByte(host, '.'); idx > 0 { host = host[:idx] } stats["host"] = host } return stats}

getStatsTags
这个方法会在每次访问 /advance接口的时候都会被调用，而代码里也很明显的使用了 os.Hostname()
。 一般情况下我们的机器的hostname不应该是频繁变化的，所以 我们应该把这个获取hostname的代码单独拿出来，作为一个全局性的处理，这样每次接口调用就不用再新调用它一次了：
改进后的代码：
var _hostName = getHost()func getHost() string { host, err := os.Hostname() if err != nil { return "" } if idx := strings.IndexByte(host, '.'); idx > 0 { host = host[:idx] } return host}func getStatsTags(r *http.Request) map[string]string { userBrowser, userOS := parseUserAgent(r.UserAgent()) stats := map[string]string{ "browser": userBrowser, "os": userOS, "endpoint": filepath.Base(r.URL.Path), } if _hostName != "" { stats["host"] = _hostName } return stats}

为了检验我们的诊断是否正确，我们重启我们的web服务再来调试一下,继续同时运行以下命令
$ kapok -d=35 -c=1000 http://localhost:9090/advance

依旧在压测的同时，我们并行采样：
$ go-torch -u http://localhost:9090 -t 30

生成新的profile后，浏览器打开

f2

可以看到，之前的os.Hostname在火焰图上没有了，我们解决了一个bug~
想必这里我们一定认为安枕无忧了，但是俗语说祸不单行，bug一般不会轻易显露出来的，我们最好还是 深入挖掘它。
我们发现下图的一个地方（绿色框中的地方）：

f3
从统计数据看到，绿色框标识的地方，采用数只有140，而这个函数应该也是每次调用/advance的时候都会被调用一次的，也就是说这里出现问题了。
我们在火焰图上再点进去，发现了可疑的地方了：
f4

绿色标识的地方所示，addTagsToName这个方法调用，为什么会出现两次呢？
知道可能出现问题的地方，但百思不得其解！要怎么样才能具体定位问题所在呢？
我们这个时候应该针对addTagsToName，尝试对症下药。
我们矛头指向addTagsToName，做一次基准测试
测试文件如下：
reporter_test.go
package statsimport "testing"func BenchmarkAddTagsToName(b *testing.B) { tags := map[string]string{ "host": "myhost", "endpoint": "hello", "os": "OS X", "browser": "Chrome", } for i := 0; i < b.N; i++ { addTagsToName("recv.calls", tags) }}func TestAddTagsToName(t *testing.T) { tests := []struct { name string tags map[string]string expected string }{ { name: "recvd", tags: nil, expected: "recvd.no-endpoint.no-os.no-browser", }, { name: "recvd", tags: map[string]string{ "endpoint": "hello", "os": "OS X", "browser": "Chrome", }, expected: "recvd.hello.OS-X.Chrome", }, { name: "r.call", tags: map[string]string{ "host": "my-host-name", "endpoint": "hello", "os": "OS{}/\tX", "browser": "Chro\:me", }, expected: "r.call.my-host-name.hello.OS----X.Chro--me", }, } for _, tt := range tests { got := addTagsToName(tt.name, tt.tags) if got != tt.expected { t.Errorf("addTagsToName(%v, %v) got %v, expected %v", tt.name, tt.tags, got, tt.expected) } }}

我们执行一下benchmark测试
先是cpu的性能分析
$ go test -bench . -benchmem -cpuprofile prof.cpuBenchmarkAddTagsToName-4 500000 3172 ns/op 480 B/op 16 allocs/opPASSok github.com/domac/playflame/stats 1.633s

使用go tool分析一下：
$ go tool pprof stats.test prof.cpuEntering interactive mode (type "help" for commands)(pprof) top10930ms of 1420ms total (65.49%)Showing top 10 nodes out of 85 (cum >= 60ms) flat flat% sum% cum cum% 130ms 9.15% 9.15% 420ms 29.58% regexp.(machine).tryBacktrack 120ms 8.45% 17.61% 120ms 8.45% regexp/syntax.(Inst).MatchRunePos 120ms 8.45% 26.06% 300ms 21.13% runtime.mallocgc 100ms 7.04% 33.10% 100ms 7.04% regexp.(bitState).push 90ms 6.34% 39.44% 300ms 21.13% runtime.growslice 90ms 6.34% 45.77% 90ms 6.34% runtime.memmove 80ms 5.63% 51.41% 530ms 37.32% regexp.(machine).backtrack 80ms 5.63% 57.04% 80ms 5.63% runtime.heapBitsSetType 60ms 4.23% 61.27% 850ms 59.86% regexp.(*Regexp).replaceAll 60ms 4.23% 65.49% 60ms 4.23% sync/atomic.CompareAndSwapUint32(pprof)

从排行榜看到，大概regexp很大关系，但这不好看出真正问题，需要再用别的招数
我们在(pprof)后，输入list addTagsToName
， 分析基准测试文件中具体的方法
(pprof) list addTagsToNameTotal: 1.42sROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 20ms 1.37s (flat, cum) 96.48% of Total . . 31: } . . 32:} . . 33: . . 34:func addTagsToName(name string, tags map[string]string) string { . . 35: var keyOrder []string . 10ms 36: if _, ok := tags["host"]; ok { . 20ms 37: keyOrder = append(keyOrder, "host") . . 38: } . 30ms 39: keyOrder = append(keyOrder, "endpoint", "os", "browser") . . 40: . . 41: parts := []string{name} . . 42: for _, k := range keyOrder { 20ms 40ms 43: v, ok := tags[k] . . 44: if !ok || v == "" { . . 45: parts = append(parts, "no-"+k) . . 46: continue . . 47: } . 1.12s 48: parts = append(parts, clean(v)) . . 49: } . . 50: . 150ms 51: return strings.Join(parts, ".") . . 52:} . . 53: . . 54:var specialChars = regexp.MustCompile([{}/\\:\s.]) . . 55: . . 56:func clean(value string) string {(pprof)

OK, 我们找到一个耗时比较多的功能调用了
1.12s 48: parts = append(parts, clean(v))

这个地方就是耗时最多的地方了，也就是接下来我们应该去调优的代码区域了。我们先别急，因为这个代码段内嵌了一次clean方法的调用。
继续在(pprof) 后输入 list clean
,看是不是在clean出问题
(pprof) list cleanTotal: 1.42sROUTINE ======================== github.com/domac/playflame/stats.clean in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 0 950ms (flat, cum) 66.90% of Total . . 52:} . . 53: . . 54:var specialChars = regexp.MustCompile([{}/\\:\s.]) . . 55: . . 56:func clean(value string) string { . 950ms 57: return specialChars.ReplaceAllString(value, "-") . . 58:}

没出意外的话，应该是 clean 方法使用不正确导致的，而且不正确的地方应该是下面的代码段：
specialChars.ReplaceAllString(value, "-")

这段代码引起了性能问题！我们着手调优吧。
代码修复前
var specialChars = regexp.MustCompile([{}/\\:\s.])func clean(value string) string { return specialChars.ReplaceAllString(value, "-")}

这段代码是把指定的特殊字符替换成‘-’，正则模块虽然灵活正则表达式比纯粹的文本匹配效率低，只是做简单文本替换的话，干脆自己写一个替换方法算了
改进后
func clean(value string) string { newStr := make([]byte, len(value)) for i := 0; i < len(value); i++ { switch c := value[i]; c { case '{', '}', '/', '\', ':', ' ', '\t', '.': newStr[i] = '-' default: newStr[i] = c } } return string(newStr)}

我们再观察基准测试报告的cpu调用分析：
$ go test -bench . -benchmem -cpuprofile prof.cpuBenchmarkAddTagsToName-4 1000000 1063 ns/op 448 B/op 15 allocs/opPASSok github.com/domac/playflame/stats 1.087s

对比上一次的测试，性能有了很大的提升：
(pprof) list cleanTotal: 1.02sROUTINE ======================== github.com/domac/playflame/stats.clean in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 10ms 110ms (flat, cum) 10.78% of Total . . 48: } . . 49: . . 50: return strings.Join(parts, ".") . . 51:} . . 52: 10ms 10ms 53:func clean(value string) string { . 60ms 54: newStr := make([]byte, len(value)) . . 55: for i := 0; i < len(value); i++ { . . 56: switch c := value[i]; c { . . 57: case '{', '}', '/', '\', ':', ' ', '\t', '.': . . 58: newStr[i] = '-' . . 59: default: . . 60: newStr[i] = c . . 61: } . . 62: } . 40ms 63: return string(newStr) . . 64:}(pprof)

但我们还不能放松，我们看到其中一项指标: 15 allocs/op

我们功能调用的速度上去了，但对象内存分配好像也没得到改善啊，这怎么办？
我们继续深入下去, 既然源码分析不行，试试汇编代码：
(pprof)disasm......... . . a4cfb: MOVQ $0x0, 0(SP) . . a4d03: MOVQ 0x70(SP), AX . . a4d08: MOVQ AX, 0x8(SP) . . a4d0d: MOVQ 0x40(SP), AX . . a4d12: MOVQ AX, 0x10(SP) . . a4d17: MOVQ 0x48(SP), AX . . a4d1c: MOVQ AX, 0x18(SP) . 60ms a4d21: CALL runtime.slicebytetostring(SB) . . a4d26: MOVQ 0x20(SP), AX . . a4d2b: MOVQ 0x28(SP), CX . . a4d30: MOVQ AX, 0xb8(SP) . . a4d38: MOVQ CX, 0xc0(SP) . . a4d40: MOVQ 0x80(SP), BP . . a4d48: ADDQ $0x88, SP . . a4d4f: RET.........

我们在这里定位到 runtime.slicebytetostring(SB) 这里可能是引起内存分配问题的所在
runtime.slicebytetostring函数正是被函数bytes.(*Buffer).String函数调用的。它实现的功能是把元素类型为byte的切片转换为字符串
我们再详细看下代码究竟哪里涉及到字符串的转换行为
(pprof) list addTagsToNameTotal: 1.02sROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 40ms 770ms (flat, cum) 75.49% of Total . . 30: } . . 31:} . . 32: . . 33:func addTagsToName(name string, tags map[string]string) string { . . 34: var keyOrder []string . 10ms 35: if _, ok := tags["host"]; ok { . 10ms 36: keyOrder = append(keyOrder, "host") . . 37: } . 30ms 38: keyOrder = append(keyOrder, "endpoint", "os", "browser") . . 39: . . 40: parts := []string{name} 10ms 10ms 41: for _, k := range keyOrder { 10ms 40ms 42: v, ok := tags[k] . . 43: if !ok || v == "" { . . 44: parts = append(parts, "no-"+k) . . 45: continue . . 46: } 10ms 520ms 47: parts = append(parts, clean(v)) . . 48: } . . 49: 10ms 150ms 50: return strings.Join(parts, ".") . . 51:} . . 52: . . 53:func clean(value string) string { . . 54: newStr := make([]byte, len(value)) . . 55: for i := 0; i < len(value); i++ {(pprof)

留意上面的代码，为了拼接字符串，我们原方案是采用slice存放字符串元素，最后通过string.join()来拼接， 我们多次调用了append方法，而在go里面slice其实如果容量不够的话，就会触发分配，所以 针对这个思路，我们需要对代码的slice预分配容量，减少动态分配：
func addTagsToName(name string, tags map[string]string) string { keyOrder := make([]string, 0, 4) if _, ok := tags["host"]; ok { keyOrder = append(keyOrder, "host") } keyOrder = append(keyOrder, "endpoint", "os", "browser") parts := make([]string, 1, 5) parts[0] = name for _, k := range keyOrder { v, ok := tags[k] if !ok || v == "" { parts = append(parts, "no-"+k) continue } parts = append(parts, clean(v)) } return strings.Join(parts, ".")}

我们执行又一次的基准测试
$ go test -bench . -benchmem -cpuprofile prof.cpuBenchmarkAddTagsToName-4 3000000 527 ns/op 144 B/op 10 allocs/opPASSok github.com/domac/playflame/stats 2.142s

可以看到对象分配的性能上去了，但不明显，而且，耗时好像比上一次还多了。唉~~ 问题还没彻底解决。
再分析profile:
$ go tool pprof stats.test prof.cpuEntering interactive mode (type "help" for commands)(pprof) list addTagsToNameTotal: 1.86sROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 140ms 1.76s (flat, cum) 94.62% of Total . . 34:} . . 35: . . 36:func addTagsToName(name string, tags map[string]string) string { . . 37: // The format we want is: host.endpoint.os.browser . . 38: // if there's no host tag, then we don't use it. . 30ms 39: keyOrder := make([]string, 0, 4) 10ms 30ms 40: if _, ok := tags["host"]; ok { . . 41: keyOrder = append(keyOrder, "host") . . 42: } 10ms 10ms 43: keyOrder = append(keyOrder, "endpoint", "os", "browser") . . 44: . . 45: parts := make([]string, 1, 5) . . 46: parts[0] = name . . 47: for _, k := range keyOrder { 40ms 240ms 48: v, ok := tags[k] . . 49: if !ok || v == "" { . . 50: parts = append(parts, "no-"+k) . . 51: continue . . 52: } 50ms 820ms 53: parts = append(parts, clean(v)) . . 54: } . . 55: 30ms 630ms 56: return strings.Join(parts, ".") . . 57:} . . 58: . . 59:// clean takes a string that may contain special characters, and replaces these . . 60:// characters with a '-'. . . 61:func clean(value string) string {(pprof)

可以看到 return strings.Join(parts, “.”) 这里的时间比之前的还长！！这就是问题之一
parts = append(parts, clean(v)) 这里也是耗时比较多的，也是问题之一
我们一个一个来：
既然知道拼接字符串，除了把字符串装在数组里，再使用join的确很方便把字符串元素拼接，但调用次数很大的时候，可能会导致对象分配低效的问题。 这里我们决定采用缓存buffer来优化字符串拼接：
func addTagsToName(name string, tags map[string]string) string { keyOrder := make([]string, 0, 4) if _, ok := tags["host"]; ok { keyOrder = append(keyOrder, "host") } keyOrder = append(keyOrder, "endpoint", "os", "browser") buf := &bytes.Buffer{} buf.WriteString(name) for _, k := range keyOrder { buf.WriteByte('.') v, ok := tags[k] if !ok || v == "" { buf.WriteString("no-") buf.WriteString(k) continue } writeClean(buf, v) } return buf.String()}func writeClean(buf *bytes.Buffer, value string) { for i := 0; i < len(value); i++ { switch c := value[i]; c { case '{', '}', '/', '\', ':', ' ', '\t', '.': buf.WriteByte('-') default: buf.WriteByte(c) } }}

我们引入buff缓冲的支持，看下优化的效果
$ go test -bench . -benchmem -cpuprofile prof.cpuBenchmarkAddTagsToName-4 3000000 488 ns/op 160 B/op 2 allocs/opPASSok github.com/domac/playflame/stats 1.981s

不错。性能指标继续上去了，而且执行耗时下降了，CPU的问题算是解决了
我们多一个心眼，上面我们关注都是CPU调用性能，很有必要看看内存情况：
$ go test -bench . -benchmem -memprofile prof.memBenchmarkAddTagsToName-4 3000000 479 ns/op 160 B/op 2 allocs/opPASSok github.com/domac/playflame/stats 1.939s

生成prof.mem后，分析查看top10内存消耗排行榜：
$ go tool pprof --alloc_objects stats.test prof.memEntering interactive mode (type "help" for commands)(pprof) top107594956 of 7594956 total ( 100%) flat flat% sum% cum cum% 7594956 100% 100% 7594956 100% github.com/domac/playflame/stats.addTagsToName 0 0% 100% 7594956 100% github.com/domac/playflame/stats.BenchmarkAddTagsToName 0 0% 100% 7594956 100% runtime.goexit 0 0% 100% 7594956 100% testing.(B).launch 0 0% 100% 7594956 100% testing.(B).runN(pprof)

又是addTagsToName引起内存分配问题，只好列出那里消耗多：
(pprof) list addTagsToNameTotal: 7594956ROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 7594956 7594956 (flat, cum) 100% of Total . . 40: if _, ok := tags["host"]; ok { . . 41: keyOrder = append(keyOrder, "host") . . 42: } . . 43: keyOrder = append(keyOrder, "endpoint", "os", "browser") . . 44: 3848310 3848310 45: buf := &bytes.Buffer{} . . 46: buf.WriteString(name) . . 47: for _, k := range keyOrder { . . 48: buf.WriteByte('.') . . 49: . . 50: v, ok := tags[k] . . 51: if !ok || v == "" { . . 52: buf.WriteString("no-") . . 53: buf.WriteString(k) . . 54: continue . . 55: } . . 56: . . 57: writeClean(buf, v) . . 58: } . . 59: 3746646 3746646 60: return buf.String() . . 61:} . . 62: . . 63:// writeClean cleans value (e.g. replaces special characters with '-') and . . 64:// writes out the cleaned value to buf. . . 65:func writeClean(buf *bytes.Buffer, value string) {(pprof)

问题定为在buf := &bytes.Buffer{}
，我们之前用它优化了我们的字符串拼接，cpu是优化了，但每次调用都新建一个buf的话，内存其实没改善，还有什么其它的解决手段呢？
我们尝试使用对象池，把buffer对象池话
var bufPool = sync.Pool{ New: func() interface{} { return &bytes.Buffer{} },}func addTagsToName(name string, tags map[string]string) string { keyOrder := make([]string, 0, 4) if _, ok := tags["host"]; ok { keyOrder = append(keyOrder, "host") } keyOrder = append(keyOrder, "endpoint", "os", "browser") buf := bufPool.Get().(*bytes.Buffer) defer bufPool.Put(buf) buf.Reset() buf.WriteString(name) for _, k := range keyOrder { buf.WriteByte('.') v, ok := tags[k] if !ok || v == "" { buf.WriteString("no-") buf.WriteString(k) continue } writeClean(buf, v) } return buf.String()}

调试一下：
$ go test -bench . -benchmem -memprofile prof.memBenchmarkAddTagsToName-4 3000000 564 ns/op 48 B/op 1 allocs/opPASSok github.com/domac/playflame/stats 2.272s

调用也在正常了
(pprof) list addTagsToNameTotal: 4008802ROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/lihaoquan/GoProjects/Playground/src/github.com/domac/playflame/stats/reporter.go 4008802 4008802 (flat, cum) 100% of Total . . 67: } . . 68: . . 69: writeClean(buf, v) . . 70: } . . 71: 4008802 4008802 72: return buf.String() . . 73:} . . 74: . . 75:// writeClean cleans value (e.g. replaces special characters with '-') and . . 76:// writes out the cleaned value to buf. . . 77:func writeClean(buf *bytes.Buffer, value string) {(pprof)

我们再生产新的火焰图：

f5

从火焰图看到，我们的性能采用报告也在合理正常的范围！
总结
经过上面的一系列分析，我们日常开发应用程序后，一定要做好测试：千里之堤毁于蚁穴

代码中一个看起来很普通的地方，可能就是我们性能的瓶颈了。
日常开发原则
避免过早优化
尽量用快速迭代的方式进行开发，毕竟Go让我们在基准测试还是生产上对代码进行profile分析变得容易。加上go-torch极大帮助 我们快速定位有问题的代码。过早优化相对片面，建议先有功能，再不断完善。

避免在热点区域进行大量对象分配

对热点区域编写基准测试用例，可以使用 -benchmem 和 memory profile来观察是否我们频繁进行内存分配，因为分配的潜台词是会发生 GC，GC会很大程度上会有服务延迟的风险。
切忌对汇编代码谈虎色变

一般情况下，对象分配或者调用耗时的细节会体现在汇编出来的代码上，我们也不需要对汇编太惧怕，掌握基本的指令和操作符知识，我们很大程度 能把一些隐藏的问题揪出来。