性能文章>一次系统延迟优化案例>

一次系统延迟优化案例原创

318566

一次系统延迟优化案例

服务监控系列文章
服务监控系列视频

问题背景

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

image.png

探索过程

排查sql慢查询

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

排查系统各项指标

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

image.png

系统是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分析得到的火焰图。

image.png

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

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

用go trace分析系统延迟

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

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

image.png

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

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

image.png

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

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

image.png

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

优化

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

成果

image.png

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

结论

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

点赞收藏
蓝胖子的编程梦
请先登录,查看6条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

一次 Rancher go 应用内存占用过高问题排查

一次 Rancher go 应用内存占用过高问题排查

实现定时任务的六种策略

实现定时任务的六种策略

6
6