背景

先来介绍下咱们的接口，该接口每天的单个接口调用量 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 <PID> 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、心愿这篇文章对你有所帮忙，如有谬误，心愿不吝指出，谢谢 ～