这是我参与「第三届青训营 -后端场」笔记创作活动的的第4篇笔记
本文章分为上下篇,上篇地址:juejin.cn/post/710267…
2. 性能调优实战
2.1 简介
性能调优原则:
- 要依靠数据不是猜测
- 要定位最大瓶颈而不是细枝末节
- 不要过早优化
- 不要过度优化
2.2 性能分析工具 pprof
性能调优前提是对应用程序性能表现有实际的数据指标,所以需要知道应用在什么地方耗费了多少 CPU、Memory
pprof 是用于可视化和分析性能分析数据的工具
下面从功能简介、排查实战、采样过程和原理三个方面介绍 pprof
2.2.1 pprof 功能简介
2.2.2 pprof 排查实战
2.2.2.1 搭建 pprof 实战项目
下载项目代码:github.com/wolfogre/go…
项目提前埋入了一些炸弹代码,产生可观测的性能问题。
会占用 1CPU 核心和超过 1GB 的内存
package main
import (
"log"
"net/http"
_ "net/http/pprof" // 自动注册 pprof 的 handler 到 http server
"os"
"runtime"
"time"
"github.com/wolfogre/go-pprof-practice/animal"
)
func main() {
log.SetFlags(log.Lshortfile | log.LstdFlags)
log.SetOutput(os.Stdout)
runtime.GOMAXPROCS(1) // 限制CPU使用数
runtime.SetMutexProfileFraction(1) // 开启锁调用跟踪
runtime.SetBlockProfileRate(1) // 开启阻塞调用跟踪
go func() {
if err := http.ListenAndServe(":6060", nil); err != nil {
log.Fatal(err)
}
os.Exit(0)
}()
for {
for _, v := range animal.AllAnimals {
v.Live()
}
time.Sleep(time.Second)
}
}
代码中引入了nethttpprof这个包,它会将pprof的入口注册到/debug/pprof这个路径下,我们可通过浏览器打开这个路径,来查看-些基本的性能统计。
运行「炸弹」,并等待它运行稳定。
在浏览器中打开http://localhost:6060/debug/pprof,可以看到这样的页面, 这就是我们刚刚引入的net/http/pprof注入的入口了。
页面上展示了可用的程序运行采样数据,下面也有简单说明,分别是:
- allocs:内存分配情况 blocks:阻塞操作情况
- cmdline:程序启动命令及
- goroutine:当前所有goroutine的堆栈信息
- heap:堆上内存使用情况(同alloc)
- mutex:锁竞争操作情况
- profile: CPU占用情况
- threadcreate:当前所有创建的系统线程的堆栈信息
- trace:程序运行跟踪信息
在这里看到的数据可读性很差,如上图。
所以我们会借助pprof工具帮我们「阅读」这些指标。
其中,cmdline显示运行进程的命令,threadcreate比较复杂且不透明,trace需要另外的工具解析,因此这几项暂不涉及。
2.2.2.1 CPU
先从CPU问题排查开始。首先查看程序进程的资源占用,CPU占用了58%,显然这里是有问题的。
pprof的采样结果是将一段时间内的信息汇总输出到文件中,所以首先需要拿到这个profile文件。你可以直接使用暴露的接口链接下载文件后使用,也可以直接用pprof工具连接这个接口下载需要的数据。
这里使用go tool pprof +采样链接来启动采样。链接中就是刚刚「炸弹」程序暴露出来的接口,链接结尾的profile代表采样的对象是CPU使用。如果你在浏览器里直接打开这个链接,会启动一个60秒的采样,并在结束后下载文件。这里我们加上seconds=10的参数,让它采样十秒。
go tool pprof "http://localhost:6060/debug/pprof/profile?=seconds=10"
稍等片刻,我们需要的采样数据已经记录和下载完成,并展示出pprof终端。
命令top:查看占用资源最多的函数
输入top,查看CPU占用最高的函数
这五列从左到右分别是:
| 列名 | 说明 |
|---|---|
| flat | 当前函数本身的执行耗时 |
| flat% | flat占CPU总时间的比例 |
| sum% | 上面每一行的flat%总和 |
| cum | 当前函数本身加上其调用函数的总耗时 |
| cum% | cum占CPU总时间的比例 |
表格前面描述了采样的总体信息。默认会展示资源占用最高的10个函数。如果只需要查看最高的N个函数,可以输入topN, 例如查看最高的3个调用,输入top3
可以看到表格的第一行里,Tiger.Eat函数本身占用3.56秒的CPU时间,占总时间的95.44%,显然问题就是这里引起的。
在这张表中可以看到,有时 flat == cum,有时 flat == 0。这分别是什么情况呢?
- flat == cum,函数中没有调用其他函数
- flat == 0,函数中只有其他函数的调用
命令list:根据指定的正则表达式查找代码行
接下来输入 list Eat 查找这个函数,看看具体是哪里出了问题。
List命令会根据后面给定的正则表达式查找代码,并按行展示出每一行的占用。
可以看到,第24行有一个100亿次的空循环,占用了3.56秒的CPU时间,问题就在这了,定位成功。
命令web:调用关系可视化
除了这两种视图之外,我们还可以输入web命令,生成一张调用关系图, 默认会使用浏览器打开。
图中除了每个节点的资源占用以外,还会将他们的调用关系穿起来。
图中最明显的就是方框最红最大,线条最粗的*Tiger.Eat函数,是不是比top命令的视图更直观些呢?
到这里,CPU的炸弹已经定位完成。
为了方便后续的展示,我们先将这个「炸弹」拆除,注意这一部分我们的主要目的是展示如何定位问题,所以不会花太多时间在看代码上。我们将问题代码直接注释掉,重新打开「炸弹」程序。
2.2.2.2 Heap 堆内存
注释CPU问题代码,重新运行后,打开活动监视器,可以发现进程的CPU已经降下来了 然而内存使用还是很高。
接着我们来排查内存问题。
在上面排查CPU的过程中,我们使用的是pprof终端,这里我们介绍另一种展示方式。通过-http=:8080参数,可以开启pprof自带的Web UI,性能指标会以网页的形式呈现。
输入下面的命令启动pprof工具,注意这时的链接结尾是heap。
go tool pprof -http=:8080 "http://localhost:6060/debug/pprof/heap"
等待采样完成后,浏览器会被自动打开,展示出 web 视图 中的 graph 视图,同时展示的资源使用从「CPU时间」变为了「内存占用」
可以明显看到,这里出问题的是*Mouse.Steal()函数,它占用了1GB内存。
在页面顶端的View菜单中,我们可以切换不同的视图。
比如top视图
以及source视图
在 source 视图中可以看到刚刚在 graph 视图中的四个调用和具体的源码视图。
如果内容太多,也可以在顶部的搜索框中输入 Steal 来使用正则表达式过滤需要的代码。
根据源码我们会发现,在 *Mouse.Steal() 这个函数会向固定的Buffer中不断追加1MB内存,直到Buffer达到1GB大小为止,和我们在 Graph 视图中发现的情况一致。 我们将这里的问题代码注释掉,至此,「炸弹」已被拔除了两个。
重新运行「炸弹」程序,发现内存占用已经降到了23.6MB, 刚才的解决方案起效果了。
在采样中,也没有出现异常节点了(实际上没有任何节点了) 。
不过,内存的问题真的被全部排除了吗?
大家在使用工具的过程中,有没有注意过右上角有个unknown_inuse_space
打开sample菜单,会发现堆内存实际上提供了四种指标:
- alloc_objects:程序累计申请的对象数
- inuse_objects:程序当前持有的对象数
- alloc_space:程序累计申请的内存大小
- inuse_space:程序当前占用的内存大小
在堆内存采样中,默认展示的是inuse_ space视图, 只展示当前持有的内存,但如果有的内存已经释放,这时inuse采样就不会展示了。
我们切换到alloc_ space指标,分析alloc的内存问题。
在 alloc_space 中马上就能定位到了*Dog.Run()中还藏着一个「炸弹」,它会每次申请16MB大小的内存,并且已经累计申请了超过3.5GB内存。在Top视图中还能看到这个函数被内联了。
定位到的这个函数在反复申请16MB的内存,但因为是无意义的申请,分配结束之后会马上被GC,所以在inuse采样中并不会体现出来。
我们将这一行问题代码注释掉。至此,内存部分的「炸弹」已经被全部拆除。
2.2.2.3 goroutine协程
Golang是一门自带垃圾回收的语言,一般情况下内存泄露是没那么容易发生的。
但是有一种例外: goroutine是很容易泄露的,进而会导致内存泄露。所以接下来,我们来看看goroutine的使用情况。
打开http://localhost:6060/debug/pprof/,发现「炸弹」程序已经有105条goroutine在运行了,这个量级并不是很大,但对于一个简单 的小程序来说还是很不正常的。
打开http://localhost:6060/debug/pprof/goroutine,看看结果。
可以看到,pprof生成了一张非常长的调用关系图,尽管最下方的问题用红色标了出来,不过这么多节点还是比较难以阅读和分析的。
这里我们介绍另一种更加直观的展示方式——火焰图。
火焰图是非常常用的性能分析工具,在程序逻辑复杂的情况下很有用。
打开View菜单,切换到Flame Graph视图。
可以看到,刚才的节点被堆叠了起来。
在火焰图中,自顶向下展示了各个调用,表示各个函数调用之间的层级关系。每一行中,条形越长代表消耗的资源占比越多。显然,那些「又平又长」的节点是占用资源多的节点。
可以看到,*Wolf.Drink()这个调用创建了超过90%的goroutine,问题可能在这里。
到 Source 视图搜索 Drink,发现函数每次会发起10条无意义的goroutine,每条等待30秒后才退出,导致了goroutine的泄露。
这里为了模拟泄漏场景,只等待了30秒就退出了。
试想一下,如果发起的 goroutine 没有退出,同时不断有新的goroutine被启动,对应的内存占用持续增长,CPU调度压力也不断增大,最终进程会被系统kill掉,是严重的 goroutine 泄露问题。
把对应的代码注释掉后,可以看到goroutine数量已经到正常水平了
接下来我们分析下锁的问题。
2.2.2.4 mutex 锁
打开http://localhost:6060/debug/pprof/mutex,发现存在一个锁操作。
在 graph 视图中定位到函数在 *Wolf.Howl()
然后在Source视图中定位到具体哪一行发生了锁竞争。
在这个函数中,goroutine足足等待了1秒才解锁,在这里阻塞住了,显然不是什么业务需求。把这行代码注释掉。
2.2.2.5 block 阻塞
我们开始排查最后一个阻塞问题。
在程序中,除了锁的竞争会导致阻塞之外,还有很多逻辑(例如读取一个channel)也会导致阻塞,在页面中可以看到阻塞操作还有两个。
打开http://localhost:6060/debug/pprof/block
在 graph 视图定位到函数在*Cat.Pee()
切换到 source 视图,可以看到在*Cat.Pee()函数中读取了 一个time.After()生成的channel,导致这个goroutine实际上阻塞了1秒钟,而不是等待了1秒钟。
不过通过上面的分析,我们只定位到一个block的问题。另一个为什么没有展示呢?
可以关注一下pprof Top视图中表格之外的部分。
可以发现,有4个节点因为cumulative小于1.41秒被drop掉了,这就是另一个阻塞操作的节点。但他因为总用时小于总时长的千分之5,所以被省略掉了。这样的过滤策略能够更加有效地突出问题所在,而省略问题相对较小的信息。
如果不作任何过滤全部展示的话,对于一个复杂的程序可能内容就会非常庞大了,不利于我们的问题定位。
那么如何查看另一个阻塞操作的信息呢?
点开 block 指标的页面。
可以看到,第二个阻塞操作发生在了http handler中,这个阻塞操作是符合预期的。
2.2.2.6 小结
至此,我们已经发现了代码中存在的所有「炸弹」。
以上我们介绍了
- 五种使用pprof采集的常用性能指标:CPU、堆内存、Goroutine、 锁竞争和阻塞
- 两种展示方式:交互式终端和网页
- 四种视图:Top、 Graph、 源码和火焰图。
pprof除了http的获取方式之外,也可以直接在运行时调用runtime/pprof包将指标数据输出到本地文件。视图中还有一个更底层的「反汇编」视图。有兴趣的同学可以尝试一下它们的用法。
俗话说,知其然还要知其所以然,接下来我们来看看它们内部的实现。
2.2.3 pprof 采样过程和实现原理
2.2.3.1 CPU
- 采样对象: 函数调用和它们占用的时间
- 采样率:100次/秒,固定值
- 采样时间:从手动启动到手动结束
graph LR
A(开始采样) --> B(设置信号处理函数) --> C(开启定时器)
graph LR
A(停止采样) --> B(取消信号处理函数) --> C(关闭定时器)
CPU采样会记录所有的调用栈和它们的占用时间。
在采样时,进程会每秒暂停一百次,每次会记录当前的调用栈信息。汇总之后,根据调用栈在采样中出现的次数来推断函数的运行时间。
你需要手动地启动和停止采样。
每秒100次的暂停频率不能更改。这个定时暂停机制在unix或类unix系统上是依赖信号机制实现的。
每次「暂停」都会接收到一个信号,通过系统计时器来保证这个信号是固定频率发送的。
接下来看看具体的流程。
一共有三个相关角色:
-
操作系统
- 每 10ms 向进程发送一次 SIGPROF 信号
-
进程
- 每次接收到 SIGPROF 会记录调用堆栈
-
写缓冲
- 每 100ms 读取已经记录的调用栈并写入输出流
当采样停止时,进程向OS取消定时器,不再接收信号,写缓冲读取不到新的堆栈时,结束输出。
2.2.3.2 Heap 堆内存
- 采样程序通过内存分配器在堆上分配和释放的内存,记录分配/释放的大小和数量
- 采样率:每分配 512KB 记录一次,可在运行开头修改,设为1则为每次分配均记录
- 采样时间:从程序运行开始到采样时
- 采样指标:alloc_space, alloc_objects, inuse_space, inuse_objects
- 计算方式:inuse = alloc - free
提到内存指标的时候说的都是「堆内存」而不是「内存」,这是 因为pprof的内存采样是有局限性的。
内存采样在实现上依赖内存分配器的记录,所以它只能记录在堆上分配,且会参与GC的内存,一些其他的内存分配,例如调用结束就会回收的栈内存、一些更底层使用cgo调用分配的内存,是不会被内存采样记录的。
与CPU和goroutine都不同的是,内存的采样是一个持续的过程, 它会记录从程序运行起的所有分配或释放的内存大小和对象数量,并在采样时遍历这些结果进行汇总。
还记得刚才的例子中,堆内存采样的四种指标吗? alloc 的两项指标是 从程序运行开始的累计指标;而 inuse 的两项指标是通过累计分配减去累计释放得到的程序当前持有的指标。
你也可以通过比较两次 alloc 的差值来得到某一段时间程序分配的内存 [大小和数量]
2.2.3.3 goroutine 协程 & ThreadCreate 线程创建
-
Goroutine
- 记录所有用户发起且在运行中的 goroutine(即入口非 runtime 开头的) runtime.main 的调用栈信息
-
ThreadCreate
- 记录程序创建的所有系统线程的信息
Goroutine:
graph LR
A(Stop The World) --> B(遍历 allg 切片) --> C(输出创建 g 的堆栈) --> D(Start The World)
ThreadCreate:
graph LR
A(Stop The World) --> B(遍历 allm 链表) --> C(输出创建 m 的堆栈) --> D(Start The World)
goroutine 和系统线程的采样在概念和实现上都比较相似,所以在这里进行对比。
他们在实现上非常的相似,采样都是立刻触发的全量记录,你可以通过比较两个时间点的差值来得到某一时间段的指标。
2.2.3.4 Block 阻塞 & Mutex 锁
-
阻塞操作
- 采样阻塞操作的次数和耗时
- 采样率:阻塞耗时超过阈值的才会被记录,设为1则为每次阻塞均记录
graph TD
A(阻塞操作) --> |上报调用栈和消耗时间| B(Profiler) --> |采样| C(遍历阻塞记录) --> D(统计阻塞次数和耗时)
B --> E(时间未到阈值则丢弃)
-
锁竞争
- 采样争抢锁的次数和耗时
- 采样率:只记录固定比例的锁操作,设为1则为每次加锁均记录
graph TD
A(锁竞争操作) --> |上报调用栈和消耗时间| B(Profiler) --> |采样| C(遍历锁记录) --> D(统计锁竞争次数和耗时)
B --> E(比例未命中则丢弃)
阻塞和锁竞争在流程和原理上也非常相似,记录的都是对应操作发生的调用栈、次数和耗时。
不过这两个指标的采样率含义并不相同。阻塞操作的采样率是一个「阈值」,消耗超过阈值时间的阻塞操作才会被记录,1为每次操作都会记录。记得炸弹程序的main代码吗?里面设置了rate=1 锁竞争的采样率是一个「比例」,运行时会通过随机数来只记录固定比例的锁操作,1为每次操作都会记录。
它们在实现上也是基本相同的。都是一个「主动上报」的过程。 在阻塞操作或锁操作发生时,会计算出消耗的时间,连同调用栈一起主动上报给采样器,采样器会根据采样率可能会丢弃一些记录。
在采样时,采样器会遍历已经记录的信息,统计出具体操作的次数、调用栈和总耗时。
和堆内存一样, 你可以对比两个时间点的差值计算出段时间内的操作指标。
2.2.3.5 小结
- 掌握常用 pprof 工具功能
- 灵活运用 pprof 工具分析解决性能问题
- 了解 pprof 的采过程和工作原理
在实战过程中,虽然我们只是模拟了一个使用 pprof 分析性能问题的小场景,但是大部分排查思路和想法是通用的,熟悉 pprof 工具后,分析真正的服务问题也会得心应手,对解决性能问题和性能调优很有帮助。
2.3 性能调优案例
在实际工作中,当服务规模比较小的时候,可能不会触发很多性能问题,同时性能优化带来的效果也不明显,很难体会到性能调优带来的收益;而当业务量逐渐增大,比如一个服务使用了几千台机器的时候,性能优化一个百分点,就能节省数百台机器,成本降低是非常可观的。
接下来我们来了解下工程中进行性能调优的实际案例
程序从不同的应用层次上看,可以分为业务服务、基础库和Go语言本身三类,对应优化的适用范围也是越来越广
-
业务服务
- 一般指直接提供功能的程序,比如专门处理用户评论操作的程序
-
基础库
- 一般指提供通用功能的程序,主要是针对业务服务提供功能,比如监控组件,负责收集业务服务的运行指标
-
Go语言本身进行的优化项
2.3.1 业务服务优化
2.3.1.1 基本概念
- 服务:能单独部署,承载一定功能的程序
- 依赖:Service A 的功能实现依赖 Service B 的
- 调用链路:能支持一个接口请求的相关服务集合以及相互之间的依赖关系
- 基础库:公共的工具包、中间件
上图是系统部署的简单示意图,客户端请求经过网关转发,由不同的业务服务处理,业务服务可能依赖其他的服务,也可能会依赖存储、消息队列等组件
接下来我们以业务服务优化为例,说明性能调优的流程,图中的 Service B 被 Service A依赖,同时也依赖了存储和Service D
2.3.1.2 流程
-
建立服务性能评估手段
-
分析性能数据,定位性能瓶颈
- 主要用 pprof 采样性能数据,分析服务的表现
-
重点优化项改造
- 进行服务改造,重构代码,使用更高效的组件等
-
优化效果验证
- 通过压测对比和正确性验证之后,服务可以上线进行实际收益评估 整体的流程可以循环并行执行,每个优化点可能不同,可以分别评估验证
这个流程也是性能调优相对通用的一个流程,可以适用于其他场景。
2.3.1.3 建立服务性能评估手段
-
服务性能评估方式
- 单独 benchmark 无法满足复杂逻辑分析
- 不同负载情况下性能表现差异
-
请求流量构造
- 不同请求参数覆盖逻辑不同
- 线上真实流量情况
-
压测范围
- 单机器压测
- 集群压测
-
性能数据采集
- 单机性能数据
- 集群性能数据
性能评估手段建立后,产出是服务的性能指标分析报告
下面是实际的压测报告截图,会统计压测期间服务的各项监控指标,包括qps,延迟等内容,同时在压测过程中,也可以采集服务的pprof数据,使用之前的方式分析性能问题
2.3.1.4 分析性能数据,定位性能瓶颈
有了服务优化前的性能报告和一些性能采样数据,我们就可以进行性能瓶颈分析了
-
使用库不规范
业务问题常见的性能问题可能是使用基础组件不规范
比如这里通过火焰图看出 json 的接卸部分占用了较多的 CPU 资源,那么我们就能定位到具体的逻辑代码,是在每次使用配置是都会进行 json 解析,拿到配置项,实际组件内部提供了缓存机制,只有数据变更的时候才需要解析 json
还有类似日志使用不规范,一部分是调试日志发布到线上,一部分是线上服务在不同的调用链路上数据有差别,测试场景日志量还好,但是到了真实线上全量场景,会导致日志量增加,影响性能
-
高并发场景优化不足
另外常见的性能问题就是高并发场景的优化不足,左边是服务高峰期的火焰图,右边是低峰期的火焰图,可以发现metrics,即监控组件的CPU资源占用变化较大,主要原因是监控数据上报是同步请求,在请求量上涨,监控打点数据量增加时,达到性能瓶颈,造成阻塞,影响业务逻辑的处理,后续是改成异步上报的机制提升了性能
2.3.1.5 重点优化项改造
定位到性能瓶颈后,我们也有了对应的修复手段,但是修改完后能直接发布上线吗?
-
正确性是基础
性能优化的前提是保证正确性,所以在变动较大的性能优化上线之前,还需要进行正确性验证,因为线上的场景和流程太多,所以要借助自动化手段来保证优化后程序的正确性
-
响应数据 diff
-
线上请求数据录制回放
同样是线上请求的录制,不过这里不仅包含请求参数录制,还会录制线上的返回内容,重放时对比线上的返回内容和优化后服务的返回内容进行正确性验证
-
新旧逻辑接口数据 diff
-
2.3.1.6 优化效果验证
改造完成后可以进行优化效果验证了
-
重复压测验证
-
上线评估优化效果
- 关注服务监控
- 逐步放量
- 收集性能数据
下图中可以看到现在的数据比优化前好很多,能够支持更多的qps。
压测并不能保证和线上表现完全一致,有时还要通过线上的表现再进行分析改进,是一个长期的过程。
2.3.1.7 进一步优化,服务整体链路解析
以上的内容是针对单个服务的优化过程,从更高的视角看,性能是不是还有优化空间?
在熟悉服务的整体部署情况后,可以针对具体的接口链路进行分析调优
- 规范上游服务调用接口,明确场景需求
- 分析链路,通过业务流程优化提升服务性能
比如Service A调用Service B是否存在重复调用的情况,调用Service B服务时,是否更小的结果数据集就能满足需求,接口是否一定要实时数据,能否在Service A层进行缓存,减轻调用压力
这种优化只使用与特定业务场景,适用范围窄,不过能更合理的利用资源
2.3.2 基础库优化
2.3.2.1 AB实验SDK的优化
比如在实际的业务服务中,为了评估某些功能上线后的效果,经常需要进行AB实验,看看不同策略对核心指标的影响,所以公司内部多数服务都会使用AB实验的SDK,如果能优化AB组件库的性能,所有用到的服务都会有性能提升。
-
分析基础课核心逻辑和性能瓶颈
- 设计完善改造方案
- 数据按需获取
- 数据序列化协议优化
-
内部压测验证
-
推广业务服务落地验证
类似业务服务的优化流程,先统计下各个服务中AB组件的资源占用情况,看看AB组件的哪些逻辑更耗费资源,提取公共问题进行重点优化。
图中看到有部分性能耗费在序列化上,因为AB相关的数据量较大,所以在制定优化方案时会考虑优化数据序列化协议,同时进行按需加载,只处理服务需要的数据。
完成改造和内部压测验证后,会逐步选择线上服务进行试点放量,发现潜在的正确性和使用上的问题,不断迭代后推广到更多服务
2.3.3 Go 语言优化
接下来是适用范围最广的优化,就是针对Go本身进行的优化,会优化编译器和运行时的内存分配策略,构建更高效的go发行版本
- 优化内存分配策略
- 优化代码编译流程,生成更高效的程序
- 内部压测验证
- 推广业务服务落地验证
优点:
- 接入简单,只需要调整编译配置
- 通用性强
下图中服务只是换用新的发行版本进行编译,CPU占用降低8%
2.4 总结
-
性能调优原则
- 要依靠数据而不是猜测
-
性能分析工具 pprof
- 熟练使用 pprof 工具排查性能问题并了解其基本原理
-
性能调优
- 保证正确性
- 定位主要瓶颈