一次系统延迟优化案例

问题背景

线上隔三差五晚上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 是个很好的分析系统延迟的工具。 对高并发接口的设计最好减少网络以及其他阻塞操作，流量上去后，这些阻塞很可能带来系统延迟。