记一次接口耗时排查
背景
先来介绍下我们的接口，该接口每天的单个接口调用量 3 千万左右，峰值 1 分钟 2.5 W 笔请求，SpringBoot 框架，使用 druid、sharding-jdbc、tomcat8.5.40 , 数据库 Oracle11g (40T 存储)
最近在做生产监控的时候，发现最近一个接口的平均耗时突然上升了上去，到达了 30ms 左右（正常在 20ms），同时，也收到了业务部门的反馈，该接口出现超时的频率比之前多了挺多。此时，我意识到这个平均 10ms 的上升不是那么的简单
可能乍一看感觉 30ms 也没什么的，挺快的了，但是这是在每天 2000W 次调用下的平均值，平均值上升了这么多，最大值绝对是达到了秒级，后来通过查询幂等记录，也验证了我的这个猜想
文章图片
工作中调用耗时的问题，对我来说，已经是家常便饭了，接下来，让我们来一起分析一波吧
分析
一、不可能是别人的问题，肯定是我的问题
首先，本着对自己和对别人负责的态度，我们首先应该考虑的不是我们依赖的系统、中间件、数据库等外围系统问题，问题肯定是我们应用的问题（为啥这么想大家应该知道哈）
文章图片
1、服务器负载
我们上来第一步先去查看我们的系统负载
文章图片
这里很简单，一个 top，服务的负载、CPU 指标就都出来了, 从结果来看，我们的系统负载挺低的，一点都不忙
2、服务器 GC
接下来我们猜想一下是不是我的服务出现了 gc 呢，期间有 STW，导致的耗时的上升，话不多说，直接查jstat -gc 5000
文章图片
结论：没有 Fulll GC , Young GC 耗时在 7 ms 左右，也没有长时间的 STW.
3、线程堆栈
从 gc 和 gc log 来看，服务没发生过 full GC , 也没有长时间的 STW, 接下来看看线程堆栈吧，找找线程都在干嘛
从线程的堆栈来看，服务也没有阻塞，都在干活
4、开 DEBUG ，找到一个问题，解决了 ？
经过前三步之后，竟然找不到一点的蛛丝马迹 ... 哇 头皮发
接下来，就一步步的找吧，我在 RC 环境（准生产环境），专门申请了一台机器，打开了服务的 debug 日志，看看能不能发现点什么东西
果不其然，让我找到了一些服务的潜在 bug
因为调用量巨大，服务用到了 sharding-jdbc 做了分表操作，但是该接口在 update 的时候，竟然没用分区键去做 update ... 我特喵的 当时只想把写这块代码的人拉出来祭天
后来我们把这个 bug 紧急优化上线之后，发现服务的平均耗时并没有降低，但是每天出现耗时的调用数量是有所下降的（ 后来我们从 DBA 那里了解到，这一优化让我们的数据库的 redo log 一天减少了 200G ）
5、一阶段总结
可是为啥没解决呢，后来我们分析了一下，能走到这个分支的请求是非常的少的，一条不超过 1 K , 所以这个问题我们还得继续往下查啊 ...
二、排查本应用所依赖中间件
那我们接下来排查的方向是什么呢 ？？？根据我们分析日志看出来，所有的慢的地方都在与数据库的交互上，那是不是数据库的问题呢 ？ 哈哈，这里就得考我们去排查了 ..
我们排查所有耗时日志来看，7 台机器都会在同时时间出现耗时长的问题，所以肯定应该是服务所依赖的公共的组件的问题（PS: 后来排查到日志的时候，也意识到这里的想法的错误，也有可能是本身使用的框架有问题），那我们接下来就向着这个方向去考虑吧 .
文章图片
上图是我们的服务与数据库的交互全路径，这个梳理清楚后，我们需要排查的方向也就出来了
1、 服务虚拟化-vSwitch 问题
vSwitch 在网络的介绍都过于底层了，对于很多不是计算机基础的人来看，很不友好，这里就简单一点，他就是 虚拟和物理网络的纽带（当然，这里大家应该意识到虚拟机和宿主机的区别哈 ），具体简介请见 https://cloud.tencent.com/dev...
其实想要验证这个问题很简单，直接搞一台物理机，服务部署上去就完了。说干就干，跟运维的同事要一台物理机 , 各种网络访问权限都开通完毕之后，服务部署，上 ！
观察了两天之后，物理机还是存在和其他的虚拟机一样的问题，看来我们的 vSwitch 这里是没问题的
2、墙或交换机
接下来，轮到了网络上的墙和交换机的排查了，这个怎么排查呢 ？ 我们直接让运维兄弟们帮我们搬了一台机器到数据库区，也是辛苦了我们的运维大哥！等待所有的网络调通，服务所有的上线验证的 checklist 都做完之后，准备在数据库区部署服务，直连 DB .
ps: 在这里提醒一下兄弟们，DB 区和应用区本质上是不通的，各种访问都需要开通访问权限，大家一定要做好网络权限的检查，不然 ...
接下来就到了观察的阶段，观察了几天的日志之后，我们发现在数据库区的服务并没有像我们想象的那样给力，依旧是和应用区的服务一样，也出现了超时的告警 ...
那接下来就好说了，数据库、TCP 协议及服务器型号问题，我们继续往下走
3、数据库
这次，轮也该轮到数据库了吧 ...
在对数据库进行了一顿排查之后，我们定位了几个问题点.
3.1 log file sync
这里我们的优秀的 DBA 杨教授 发现了数据库的log file自适应参数是不正确的，因为LGWR使用了polling方式来取代post/wait，并且polling的间隔是10ms，这个间隔是在代码里写死的。随即对他进行了调整，调整之后，进入观察阶段，我们发现接口的平均耗时降低了下来 .
卧槽，莫非是他在搞劳资 ？ 马上开始排查服务器日志验证，诶？依旧有耗时超过 200ms 的，这是为啥子 ...
3.2 归档日志收集任务
经过观察日志，每天早上 7-9 点的耗时长的请求比较多，可是他们明明是在服务的低峰期啊？这是为啥子，经过对数据库的排查之后，我们发现 数据库有一个手动设置的归档日志收集在这个时间段，经过与 DBA 沟通后，我们发现这个操作完全可以在凌晨操作，于是我们将这个定时任务的启动时间从 7 点调整到了 3 点。 很明显，这个在业务低峰期跑，无疑对业务的影响是最小的 ...
3.3 数据库日志级别
经过上述调整之后，平均耗时已经下来了，但是依旧有较长的耗时存在，作为对技术的执着，必须解决这个问题，继续排查数据库，我们发现了一个 oracle 数据库的日志级别竟然是 ALL , 这个开启的原因我们就不追究了，但是，这个 ALL 有什么影响呢，我们对这个做了专门的测试，大家可以来参考我们做的一个测试的博客 ( https://blog.51cto.com/yangju... )
结论：oracle ALL 字段补充日志和主键补充日志一样为无条件式的，无论哪个字段被 update 命令修改，所有字段(除了 lob，long 类型)的旧值都将被记录，其效果相当于启用了主键补充日志的前提下既没有主键也没有非空唯一索引字段的情况，这样几乎所有的表数据都搬到了重做日志中，不但存在当前的，历史数据也没有丢下。对恢复操作来说比较好，但是对于 lgwr 和磁盘空间就不是太好，一般很少启用这样的日志。
3.4 redo log
做完上述调整之后，我们继续排查数据库是否还有其他的问题存在，我们的 redo log 一天 1.5T, 在我们解决了前面提到的应用的 bug 之后，数据库的 redo log 降低到了 1.3T，这里能看出服务依旧有大量的 redo 产生 , 这里我突然想到，服务有一个没用的代码，每笔请求都在 for update，经过对 redo log 的分析，验证了我的这一猜想，于是 , 我们联系了我们的产品、运营等相关人员，在经过几轮的讨论之后，我们决定下线该逻辑.
在经过了一阵时间之后，我们终于将该逻辑下线了 ...
再次排查 redo, 发现我们的每天的 redo log 也有降低，对于库的性能提升也是有帮助的 .
3.5 驱动版本
经过 oracle 官方的博客中的介绍，我们现在用到的 oracle 11g，使用的驱动是 0jdbc6，也是官方推荐的最适配版本，所以这里我们不进行深究
文章图片
3.6 数据库备份
我们的数据库每天都会有备份，每周六也会有一个数据库的全备，因为业务量比较大，所以这个数据库的备份时间特别长，排查到这里的时候，我们决定换一个备份的软件，希望他能有用吧 ...
在这里也说明一下，为什么没有分 oracle 的库？？？ 你没有猜错，因为成本高 ！而且，这个库的规划上，一共有三个 db .
最终测试出来的数据库备份建议：
1、限制备份的并发度还有限制速率，减少备份期间对 IO 的影响
2、将 REDO LOG 单独放在单独的 ASM 磁盘组上，备份不备份 ONLINE REDO
3、由之前的NFS备份，调整至专业备份软件以及SSD存储介质上
3.7 总结
在对数据库经过了如上的一顿操作之后，我们的耗时终于降低了下来，达到了上升之前的一个正常的水平 。在此，向本次优化提出建设性意见的 DBA 同事致以崇高的敬意.
文章图片
虽然平均耗时降低了下来，但是每天依旧有部分请求耗时超过正常范围，本着打破砂锅问到底的精神，我们继续往下去排查。
4、TCP 协议
我们继续来下我们的服务日志，诶？依旧有时间超过 200ms 的请求，当然了，比刚开始排查的时候，减少了很多，可是现在为什么还存在呢？这里有经验的同学一定知道 TCP 什么参数会引起这个现象。对，你猜的没错，就是 TCP_NODELAY。就是我之前的耗时排查那篇文章中提到过的神奇的 40ms .
为了验证上面的猜想，我们抓个包来看下
文章图片
从抓包的情况看，DB给客户端发ACK确实是延迟了40ms。
那服务端连接数据库，究竟有没有什么参数来调整呢？让我们继续找找 oracle 的官方指导吧
文章图片
文章图片
这里我们根据oracle的官方指导，设置一下tcp-no-delay 看看是否能生效
-Doracle.jdbc.TcpNoDelay=true
投产观察了一段时间后，貌似这个参数没有生效 ...
5、服务器 -> 项目框架
经过上述调整之后，突然听到了一个其他的服务也有耗时长的问题，我上去看了下他们的服务，和我们的这种现象类似？那会不会是运维采买的这批服务器有问题呢 ？
继续去找运维大哥，拿到这个服务器的监控 . 在我们耗时长的时候，服务器的 IO WAIT 会有一个上升！！！
文章图片
【记一次接口耗时排查】诶 ？ 有问题的另一个系统是不是也是这样的呢 ？
文章图片
果真，这个服务也是这样的情况 。 为什么在业务低峰期会有 IO WAIT 呢 ？我们从服务器的IO 和 虚拟机的VMstat 来分析下，看看能不能找到些什么
文章图片
从上图看 , 服务的iowait 是一直都有的，服务的IO产生要么写，要么读，在我这，只有写日志这一个场景了，后续我们测试了一下这个机器写的速度，明明能达到500M/s, 可是现在只有4M/s ，这里排出虚拟机的问题，带着问题我们继续往下找
文章图片
通过对vm的分析，这个虚拟机上阻塞的进程几乎一直都在存在，肯定是存在IO的等待，此时，我们只能定位到服务的日志打印框架上面。那我们用的是什么框架呢，来扒拉扒拉架构封装的 hao 东西，卧槽，不出所料，我们用的日志框架是 logback , 并且开启了异步日志，而 logback 的异步日志模型使用的队列正是ArrayBlockQueue，性能损耗的厉害。找到这，我就只能瞒着架构，偷偷的升级我们的日志框架（这里我用了更高性能的disruptor队列，我们的基础框架升级至log4j2有一些小小的问题；PS:这种行为大家不要模仿啊，日志打印规范在一个公司还是要有一个规范的，我这只是为了验证问题），进行压测
通过压测发现，我们TPS确实是有很大的提升，看来我们的改动是有效果的，于是我们决定在元旦后进行一次优化升级，看我们的线上环境跑起来怎么样 ...
6、服务器插件
在更新了我们的日志框架之后，我们发现了性能有了一定的提升，单独查询接口的 QPS 从 3000左右提升到了4300左右，但是依旧会有IO的WAIT,于是我们下掉了其中的一台机器，下面我们对这个服务器进行静默观察，发现在没有任务业务代码跑的情况下，服务器依旧会有iowait
文章图片
文章图片
这是为什么呢，我们抓一下，最终定位到了我们的服务器安装的一个安全插件。每次iowait 上升的时候，总有这个进程在read 。于是，我们发现问题后，把其中一台服务器的安全插件直接下掉了，进入静默观察阶段，24小时后，我们来看看结果
文章图片
很明显，这证实了我们上面抓到的这个插件，凌晨的凸起是日志的压缩备份，除了这个点之外，没有其他的 iowait 存在
可是从监控上看，插件只是读了很小的数据，为什么会有这么高的iowait呢，是插件的bug 还是磁盘的问题 ？这里就移交给我们的运维工程师和安全工程师去研究了，后续有结果再更新文档
总结
总体上，从监控图来看，我们的优化动作效果很明显，我们的最高的耗时已经达到了之前的平均的耗时，这次优化到这基本上也该画上一个句号了，毕竟还有很多bug需要去写
文章图片
PS: 耗时的凸起，为业务最低峰，数据库在做收集信息统计，这个目前对我们没有什么影响，所以这就不深究了
本次借着这个问题，算是把服务优化了一番，其中有几点总结一下
1、 服务本身问题，大家还是要关注自己的服务本身存在的问题，认真挖掘，仔细排查，有的时候不仅仅是业务本身的代码的问题，很有可能是用的基础框架的问题
2、 数据库的优化也是必不可少的，建议大家多关注数据库的各项指标及设置，这次我们排查和实践出来的数据库的可扩展性优化点还是很多的，例如：归档、备份、收集信息等
3、本项目本次优化点: 数据库 log file自适应参数、应用历史无用逻辑下线、应用 bug修复、外围应用不合理调用下线、应用日志框架升级、服务器插件等
4、希望这篇文章对你有所帮助，如有错误，希望不吝指出，谢谢 ～
推荐阅读
- JAVA（抽象类与接口的区别&重载与重写&内存泄漏）
- EffectiveObjective-C2.0|EffectiveObjective-C2.0 笔记 - 第二部分
- 野营记-第五章|野营记-第五章 讨伐梦魇兽
- 20170612时间和注意力开销记录
- 2018年11月19日|2018年11月19日 星期一 亲子日记第144篇
- 叙述作文
- 2019年12月24日
- 【故障公告】周五下午的一次突发故障
- 人生感悟记＃环境仪器宋庆国成长记＃072
- 基于微信小程序带后端ssm接口小区物业管理平台设计