背景首先介绍一下我们的接口，每天单接口调用约3000万次，峰值每分钟2.5W笔请求，SpringBoot框架，使用druid，sharding-jdbc，tomcat8.5.40，最近数据库Oracle11g（40T存储）在做生产监控时，发现最新接口的平均耗时突然增加到30ms左右（正常情况下是20ms）。同时，也收到了业务部门的反馈。这个接口超时的频率比以前高了很多。至此，我才意识到平均增加10ms并不是那么简单。乍看之下，30ms似乎不算什么，挺快的，但这是每天2000W调用下的平均值，而且平均值增加了这么多。最大值肯定在二级。后来通过查询幂等记录，也验证了我的猜想，工作中调用耗时的问题对我来说已经是家常便饭了。接下来，我们一起来分析一下。波霸分析1.不可能是别人的问题，一定是我的问题首先，本着对自己对他人负责的态度，首先要考虑的不是系统，中间件，数据库等周边我们依赖的系统。问题肯定是我们应用的问题（你应该知道你为什么这么想）1.服务器负载第一步是检查我们的系统负载。这里很简单。一顶，服务负载和CPU指标都出来了，从结果来看，我们的系统负载相当低，一点也不忙。2.ServerGC接下来猜猜我的服务有没有GC。这期间有STW，导致耗时增加。多说一句，直接查jstat-gc5000结论：没有FulllGC，YoungGC大概7ms，也没有长STW。3.线程栈从gc和gclog来看，服务没有发生过fullGC，也没有长期的STW，接下来我们看一下线程栈，看看线程在干什么。从线程栈看，服务没有阻塞，都在工作。4.开启DEBUG，发现问题。解决了？走完前三步，竟然找不到任何蛛丝马迹……哇，好头皮啊。接下来，我们一步步寻找。我申请了一台RC环境（准生产环境）的机器，开通了服务。调试日志，看看我是否能找到一些东西。果然，我在服务中发现了一些潜在的错误。由于调用量巨大，服务使用了sharding-jdbc进行分表操作，但是更新后接口没用。partitionkey做update。。。只想把写这段代码的人拉出来祭拜大神。我们紧急优化这个bug上线后，发现服务的平均耗时并没有减少，反而是每天的消耗量减少了（后来从DBA那里了解到，这个优化让我们数据库的redolog一天减少了200G.)5.第一阶段的总结，但是为什么没有解决，后面我们分析了，能到这个分支的请求很少，一个请求不超过1K，所以我们要继续调查这个问题……二是检查这个应用程序依赖的中间件。我们接下来的调查方向是什么？？？根据我们对日志的分析，所有慢的地方都在与数据库的交互上。那是数据库的问题吗？哈哈，这里要查..我们查了所有的耗时日志，7台机器会同时出现耗时问题，那肯定是服务依赖的公共组件有问题（PS:后来在查看日志的时候也意识到这里的思路是错误的，或者可能是我使用的框架有问题），那就往这个方向考虑吧。上图展示了我们的服务与数据库的交互。路径，这个梳理完之后，我们需要考察的方向就出来了1.Servicevirtualization-vSwitch问题。网络中vSwitch的引入太低级了。对于很多不会电脑的人来说是很不友好的。这里是简单的说，他就是连接虚拟和物理网络的纽带（当然大家要清楚这里虚拟机和主机的区别）。详细介绍请看https://cloud.tencent.com/dev...其实我想验证这个问题很简单。搭建物理机，部署服务即可。搞定，向运维同事要一台物理机，各种网络访问权限激活后，服务部署，走！经过两天的观察，物理机还是和其他虚拟机一样的问题。看来我们的vSwitch到这里是没有问题的。2.墙壁或开关接下来，轮到检查墙壁和网络开关。这个怎么查？我们直接让运维小哥帮我们搬了一台机器到数据库区，这也是我们运维小哥辛苦的一件事情！等待所有网络调整，服务在线验证checklist全部完成后，准??备在数据库区部署服务，直接连接DB。各种访问都需要开通访问权限，大家一定要做好网络权限的检查，否则……接下来就是观察阶段了。观察了几天日志，发现数据库方面的服务没有我们的好。和想象中的一样强大，还是和应用区的服务一样，还有超时报警。。。然后说说数据库，TCP协议和服务器模型问题，继续往下看3.的database这次，轮到数据库了。。。查了数据库，发现了几个问题。3.1logfilesync在这里我们优秀的DBAYang教授发现了数据库的logfileadaptive参数是不正确的，因为LGWR使用的是polling而不是post/wait，pollinginterval是10ms，硬编码在代码中。立即调整他。调整后，我们进入观察阶段，发现界面的平均耗时有所降低。卧槽，是不是搞劳资的？马上开始查看服务器日志验证，嗯？还有200多ms的耗时，这是为什么呢...3.2Archive日志收集任务观察日志发现，每天早上7-9点的请求耗时较多，但明显处于低位服务高峰期？为什么是这样？查看数据库后，我们发现数据库中有这段时间收集的手动设置的归档日志。和DBA沟通后发现这个操作可以在凌晨操作，所以我们把这个定时任务的开始时间从7点调整为3点。显然，在业务的非高峰期运行，对业务的影响无疑是最小的……3.3经过以上数据库日志级别的调整，平均耗时已经降下来了，但是还有很长的路要走耗时的时间。持久化技术一定要解决这个问题，继续查数据库，发现一个oracle数据库的日志级别是ALL，这个开启的原因我们就不追究了，但是这个ALL有什么影响呢？专项测试可以参考我们做的一个测试博客（https://blog.51cto.com/yangju...）结论：oracleALL字段补充日志和主键补充日志一样是无条件的，无论哪个字段被update命令修改，所有字段（lob和long类型除外）的旧值都会被记录下来。效果相当于在启用主键补充日志的前提下既没有主键也没有非空唯一索引字段的情况。这样几乎所有的表数据都被移到了redologs中，不仅是当前的，还有历史数据。适用于恢复操作，但不适用于lgwr和磁盘空间，此类日志很少启用。3.4Redolog经过以上调整后，我们继续查看数据库是否还有其他问题。我们的重做日志是每天1.5T。我们解决了上面提到的应用bug后，数据库的redolog减少到1.3T，这里可以看到服务还是有很多redogeneration的。到这里突然想到service有一段无用代码，每次request都是update。分析redolog后，验证了我的猜测，于是，我们联系了我们的产品、运维等相关人员，几轮讨论后，我们决定将逻辑下线。过了一段时间，我们终于把逻辑下线了……再次查看redo，发现我们每天的redolog也减少了，这对库的性能提升也有帮助。Oracle官方博客已经介绍了3.5驱动版本。我们现在使用的oracle11g使用的驱动是0jdbc6，这也是官方推荐的最合适的版本，这里就不赘述了。3.6数据库备份我们的数据库每天都会进行备份，每周六都会进行数据库的全量备份。因为业务量比较大，所以这个数据库的备份时间很长。Check到了这里，我们决定换个备份软件，希望能有用。。。这里也说明一下，为什么没有分oracle库？？？你猜对了，因为成本高！而且，在这个库的规划中，一共有三个db。最终测试的数据库备份建议：1.限制备份的并发，限制速率，减少备份时对IO的影响。2.将REDOLOG单独放在ASM磁盘组上，备份不备份ONLINEREDO3，从之前的NFS备份，调整为专业的备份软件和SSD存储介质3.7总结经过对数据库的上述操作，我们的时间消耗有终于减少了，在上涨前达到正常水平。在此，向对本次优化提出建设性意见的DBA同仁致以崇高的敬意。虽然平均耗时有所降低，但每天仍有部分请求耗时超过正常范围。本着打破砂锅问底线的精神，我们继续深入调查。4.对于TCP协议，我们继续下载我们的服务日志，嗯？仍然有超过200ms的请求。当然，比起刚开始调查的时候少了很多，但为什么现在还存在呢？这里有经验的同学肯定知道什么TCP参数会导致这种现象。是的，你猜对了，就是TCP_NODELAY。就是我之前的耗时调查文章中提到的神奇的40ms。为了验证上面的猜想，我们来抓个包，从抓包的情况看，DB向客户端发送ACK确实延迟了40ms。服务器连接数据库时有什么参数需要调整吗？我们继续寻找oracle的官方指导。这里我们按照oracle官方的指导设置tcp-no-delay，看看能不能生效。...5。Server->Projectframework经过以上调整，突然听说其他服务也有耗时长的问题。我上去看看他们的服务。是不是和我们的很像？难不成是运维采购的那批服务器有问题？继续找运维小哥，拿到这个服务器的监控。当我们用的时间长了，服务器的IOWAIT就会上升！！！嗯？其他有问题的系统也是这样吗？果然，这项服务也是如此。为什么在低营业时间会出现IOWAIT？我们来分析一下服务器的IO和虚拟机的VMstat，看看能不能发现点什么。从上图可以看出，服务的iowait一直都在，服务的IO不是写就是读。就我而言，只写日志的场景就结束了。后来我们测试了这台机器的写入速度。明明可以达到500M/s，现在只有4M/s了。这里是虚拟机的问题。带着问题，我们继续在vm中查找，根据分析，这个虚拟机上的阻塞进程几乎一直存在，肯定有IO等待。这个时候我们只能定位服务的日志打印框架。那么我们使用的是什么框架呢？我们来看看架构封装的hao东西。不出所料，我们使用的日志框架是logback，并且启用了异步日志，而logback的异步日志模型使用的队列正是ArrayBlockQueue，性能损耗比较严重。发现这一点，只能瞒着架构偷偷升级我们的日志框架（这里我使用了更高性能的disruptor队列，我们??的基础框架升级到log4j2还有一些小问题；PS：这种行为大家不要模仿一下，某公司日志打印还是有标准的，我只是来验证一下），通过压测，发现我们的TPS确实有了很大的提升。看来我们的修改是有效的奏效了，所以我们决定在元旦之后进行一次优化升级，看看我们的线上环境运行的怎么样...6.服务端插件更新我们的日志框架后，我们发现性能在一定程度上有所提高。单次查询接口的QPS从3000左右提升到4300左右，但是还是会出现IOWAIT，所以我们掉了一台机器。接下来我们静静观察这台服务器，发现并没有任务业务代码在运行。接下来，服务器仍然会有iowait。为什么是这样？让我们抓住它，最后找到一个安装在我们服务器上的安全插件。每次iowait上升，总是有这个进程读。于是，我们发现问题后，直接下载了其中一台服务器的安全插件，进入静默观察阶段。24小时后，我们查看了结果。很明显，这证实了我们上面捕获的插件。凸起是日志的压缩备份。除了这一点，没有其他的iowait。但是从监控的角度来看，插件只是读取了少量的数据。为什么会有这么高的iowait？是插件的bug还是磁盘的bug？问题？这个交给我们运维工程师和安全工程师研究，有结果后会更新文档。这里有一个大家很容易陷入的科普误区：%iowait不能反映磁盘瓶颈（推荐一篇介绍iowait的文章->http://linuxperf.com/?p=33）总结总的来说，从监控图中，我们的优化动作效果很明显，我们的最高耗时已经达到了之前的平均耗时，本次优化基本到这里画上句号了。毕竟还有很多bug需要写。PS：耗时凸起是业务的最低峰，数据库正在收集信息统计。这个目前对我们没有影响，所以这个我这次就不细说了。这次我用这个问题来优化服务。这里总结几点：1、服务本身的问题。有时候不仅仅是业务本身代码的问题，很有可能是使用的基础框架的问题。2.数据库的优化也是必不可少的。建议大家多关注数据库的各项指标和设置。本次我们将检查和实践中数据库的可扩展性还有很多优化点，例如：归档、备份、信息收集等。3、本项目的优化点：数据库日志文件自适应参数、应用历史下线无用逻辑、应用bug修复、周边应用被无理调用下线、应用日志框架升级、服务端插件等4、希望本文对您有所帮助。如有错误，希望大家指出，谢谢~
