一次系统延迟性优化案例

服务监控系列文章

服务监控系列视频

问题背景

线上隔三差五晚上 10 点左右总会有 sql 报警出现，且是同样的 sql，我们的 sql 报警是在应用程序内部通过对 sql 操作增加钩子函数，对 sql 前后执行的位置记录下时间戳，然后 sql 执行完毕后，对时间戳进行相减得到 sql 执行时长，大于 1s 则报警。晚上 10 点正好是我们的业务高峰。部分接口也会在此期间出现超过 2s 的响应。

探索过程

排查 sql 慢查询

由于是执行 sql 的地方出现报警，所以 我还是首先通过后台的慢查询日志，发现在 mysql 服务器测并没有这条慢 sql 打印出来，且重新执行该 sql，执行时间仍然在毫秒内完成，排除掉 sql 本身带来的性能问题。

排查系统各项指标

接着查看云服务器的 cpu，网络带宽 Mbps，磁盘 iops，Bps 各项指标，均未到达瓶颈，仅在高峰期有波峰。

系统是 4 核系统，唯一达到瓶颈的也就是系统负载达到了 5。说明有进程或线程在等待执行。为什么系统各个硬件指标都不是很高，程序反而慢了呢，cpu 为什么没有干更多活来执行更多的指令呢。

考虑程序在执行一个 cpu 使用率不高的动作,但是这个动作却不是在执行用户代码

一般通过 go 自带的分析性能的工具 go tool pprof 查看 cpu 的使用率，关于 cpu 的使用和统计原理可以查看 golang pprof 监控系列(5) —— cpu 使用 统计原理这篇文章，pprof 工具 是查看 on-cpu，也就是 cpu 真正执行的时间，但是我们这里 cpu 使用率并不高，应该分析的是，程序中等待 cpu 的时长 我们将等待 cpu 的时长分析叫做 off-cpu,go 提供了这样的工具(github.com/felixge/fgprof)fgprof 的性能文件 同时结合了 off-cpu 和 on-cpu 的情况。由于目前出现的情况是 cpu 使用率不高，也就是 on-cpu 不高，但是程序有延迟，也就是 off-cpu 偏高的情况，这种情况用 fgprof 去分析 off-cpu 的时长就很合适。以下是 fgprof 分析得到的火焰图。

火焰图中，从上到下代表方法的调度顺序，同一层次中，如果方法占用的长度越长，代表这个方法占据这部分指标的份额就越大。

可以在执行时查询数据库，cpu 在 withLock 和等待数据库返回数据库时耗费了很多等待时间。有大量的 golang 客户端库的方法出现在这里，但是这里只能看出这部分代码等待 cpu 的时间占所有等待时间的大部分，无法确定程序真正等待的时长。

用 go trace 分析系统延迟

基于上面分析，为更进一步确定是数据库查询带来的延迟，并且更加明确的知道客户端执行查询方法带来的具体时长，决定采用更加精确化的工具，通用这个工具也是 golang 自带的性能分析工具，通过 go trace 分析程序运行时的行为。 go trace 通过在程序内部埋点的方式，记录了 runtime 中各种行为的耗时情况，是个分析延迟情况很好的一个工具，关于它的使用和统计原理介绍可以查看https://github.com/HobbyBear/performance-analyze这篇文章。

以下是通过 go trace 得到的分析文件。

我通过 go trace 工具 一共进行了 3s 的采样，图中 Goroutine 这一栏代表协程 id， 其中有的协程 网络 io 等待时间 Network wait 就占了 2 秒多，程序会在网络 io 系统调用开始时记录下此时时间时间戳，并将协程从 p 队列拿下来，然后异步等到 epoll 回调通知，等到文件描述符可读后，将协程重新加入到 p 队列，重新执行调度。这里的 Network wait 就是从 p 队列拿下来到加入到 p 队列的时间间隔。

但是注意 协程的网络等待时间长，不能完全说明是导致系统延迟的原因，因为一个协程是有可能处理多个网络请求的，所以有可能一个协程在 多次 http 请求间，读等待时间较长导致。所以继续看下其他指标。

协程加入到 p 队列后仅仅是一个就绪状态，只有真正被 cpu 调度到时，协程才算开始执行了。 我们将加入到调度队列到真正执行这段时间间隔称作 Scheduler wait。

协程从就绪到 运行状态 有的协程 耗时达到了 879ms，可见协程调度的压力也是过大的。接着再看一个另一个和延迟有关的指标 Sync block。

Sync block 记录的是程序由于锁 mutex，通道，select case 语句，wait group 导致程序阻塞带来的延迟，可以看到 延迟开销也是不小的，有的协程在 3s 采样期间内 达到 778ms。对应于之前 fprof 的火焰图，网络和阻塞开销就是执行数据库操作时的网络请求以及 withlock 操作，由于阻塞更加剧了协程调度的开销。每次阻塞都会引发协程的重新调度。当然 go trace 左上角可以点击 graph 同样能观察得出上述结论。

优化

基于上诉分析 可以得出结论 由于程序的阻塞虽然不是慢查询导致，但是依然是由于数据库操作带来的，所以简单直接的优化就是减少数据库操作，或者更直接点说，在高并发接口下，尽可能减少请求网络接口等阻塞操作。将这部分查询数据提前存到本地内存里，通过内存直接查询。 这样便可以从协程调度延迟，锁阻塞延迟，网络等待延迟这些维度去减少整个系统的延迟时间，充分的利用 cpu。不至于出现 cpu 利用率不高，但是系统还是有延迟的情况。

成果

可以看到对比之前情况，除开 22 点峰值，已经没有超过 2s 的响应了，但是 22 点峰值时还是会有，原因是我们线上的机器同时部署了多台服务，由于其他服务的影响导致，所以后续可能还会继续做优化，将其他服务的处理接口能力提升上去，或者更好的做好隔离。

结论

go trace 是个很好的分析系统延迟的工具。对高并发接口的设计最好减少网络以及其他阻塞操作，流量上去后，这些阻塞很可能带来系统延迟。