案例诊断：“交易耗时8S”缉凶记

背景

某日上午，小集购买a产品失败，页面弹出“系统异常，请稍后重试”的报错，便联系了技术团队的开发小成。

“小成，我刚才尝试买a产品一直显示系统异常，是不是有什么问题呢？”开发小成接到电话后，迅速着手排查，同时也收到了系统监控平台的告警。

小成立刻登录系统应用服务器，发现交易耗时在8s左右。经过一系列紧张的故障排查和恢复工作，虽然过程艰难，但最后还是成功地恢复了业务。

解决过程

【DAY1】

“交易的耗时为什么会这么久？是不是内存资源不足引起的？”

小成立即查看了应用服务所在的公有云服务器的资源状态，发现服务器的VM系统大量OOM报错，即使尝试重启Tomcat，也是失败。

“是不是有什么业务层的程序大量消耗资源导致？”

带着这个问题，小成继续一步步排查。半小时左右，小成发现合作机构的前置T应用上有大量的Close_wait连接，应用提示open too many files。大量Java的应用报错Java.io.IO.Exception: Broken Pipe.

为了尽快恢复业务，小成尝试重启了Tomcat应用，但错误依旧存在，尝试修改open files和max user processes参数，未见明显效果。小成又再试着在弹性服务器上分别Telnet本地端口和对方端口甚至重启了服务器。这些都无济于事，错误依然存在。

发现这些常用恢复方式不起作用，小成调整思路，看业务平台是不是有问题。果不其然发现应用平台上持续大量业务报错，报错信息集中在产品中心的捞取数据同步的定时任务。

“难道是这个定时任务的数据量增大导致的？”

小成确认了当日的定时同步数据的任务业务量级，发现每分钟1万左右，平均每秒（QPS）300~350之间（与日常调用量持平）。

“既然定时任务的量级未变，为什么会大量报错？”

业务恢复争分夺秒，小成申请停掉可疑的定时任务，发现不见效，尝试业务流量切换到备用集群观察。

流量切换后，问题恢复了。

“切换到备用集群竟然可以恢复，难道是老集群的问题？”

想着定时任务还停着，小成建议申请恢复定时任务，数据同步定时任务再次被拉起。

这时已经过去了近两个小时。虽然切换新集群业务恢复，定时任务也恢复运行，但根本原因还是没查明。小成开始复盘整个过程，思考各个疑点。

为什么数据同步定时任务会大量报错？虽然报错，为什么切换到新集群会恢复？

这时电话又响起了：“小成，备用集群也出事了！”

小成脑子快速闪过，“基本确定是定时任务的问题了”。

小成申请再次停止数据同步任务，经同意后，立即执行。执行后，业务开始逐渐正常。时间已经到了下午。

小成和团队人员紧急召开复盘会议，基于业务影响可能性的评估，决策对业务主链路进行隔离。当天下午紧急对业务链路进行隔离操作，并且在1个多小时内完成业务流量验证通过。

不知不觉一下午时间就这样过去了，小成理了理思路，决定把问题来龙去脉理清楚，于是发起了次日集中问题排查的会议邀约，参与人员涉及多方技术团队。

【DAY2】

通过对监控数据的梳理，小成发现当天机房的负载均衡服务器和弹性计算服务器有异常流量，且网络还有丢包情况。但是这流量的来源无法查明。另外T应用hang住的时候关系型数据库服务上的耗时急剧增加。

【DAY3～DAY4】

基于这一点，技术团队就此问题进一步深挖。通过复查所有相关SQL语句和查询数据量以及数据库数据量，试图找到病根，但是最终发现并没有异常。

那到底是什么变更导致数据库响应慢的？

技术人员再次调整思路，尝试在SIT环境 （线下测试环境）mock SQL 查询超时的情况，果然，重现了关系数据库服务查询耗时急剧增加的现象。并且T应用上出现大量Close_wait的连接，直到应用服务器上的资源耗尽，导致应用hang住。

【DAY5】

业务一切正常，但是SQL缓慢的原因还无法具体定位。

不过，业务涉及数据同步定时任务查询的SQL倒是还存在不少的优化空间，业务技术人员在当晚就通过索引优化的方式固定执行计划。

【DAY6】

第6天，小成邀请了数据库团队和公有云等技术专家团队参与到了问题排查中。

终于问题的根源逐渐水落石出，数据库和云服务器专家们就这个可疑的数据库服务响应慢的问题进行层层排查。

深入分析

（1）应用服务器单台网卡为什么有大量异常流量？

这是因为服务器主机的日志同步机制运行时，会每5分钟读取一次日志，从而引起异常流量。

（2）应用服务端为什么会大量Close Wait？

Close Wait产生的原因在于数据库服务端等待超时后，主动断开连接，如果应用服务端在数据库断开之后能够响应及时关闭，就不会积攒大量Close Wait，但是应用服务端在当天问题发生时并未马上关闭无用连接，所以大量的CloseWait状态过多，导致主机资源耗尽。

当天排查也发现合作机构前置应用在网关关闭连接后，业务查询还未结束时，前置应用的网关连接不会关闭。这一事实佐证了上面这一点。

（3）应用服务端为什么会大量报错“open too many files”？

应用服务器可以open的文件数有上限，通常不会到达这个阀值。如果出现那可能就是有文件句柄没有及时释放。由于前面有大量处于close_wait的tcp连接，每个连接对应一个套接字（socket），也对应一个文件句柄，这是导致报错的主要原因。

（4）数据库服务的耗时是否和数据库主机的CPU利用率有关？

分析：

数据库主机的各个逻辑CPU在问题发生期间的监控数据都是正常，该因素排除。

监控佐证：

图3-1所示是数据库实例采集到的CPU的平均利用率监控信息，从监控来看，并没有明显变化。

图3-1  CPU平均利用率

5）会不会是数据库主机磁盘IO有问题？

分析：

磁盘IO监控包括每秒读写IO次数，每秒读写IO吞吐量、每个读写IO的平均响应时间，磁盘当前队列长度。

数据库服务的DB文件分为数据文件和日志文件，日志文件存放于D盘，数据文件存放于E盘，Tempdb的文件在D盘。

模拟当天业务场景和大致时间点，从监控（如图3-2所示）可以看出，在09：25以前D盘的活动比较多，但总体都在正常范围。25分之后，E盘在45分左右有个高峰，但是峰值依然远低于磁盘的能力（最大IOPS14000）。磁盘IO平均响应时间供参考。当磁盘IO压力过大或者出现访问问题时，那个响应时间会有值。正常情况下，数据都非常小（小于1），总体来说数据库主机的IO负载也很低，此因素排除。

图3-2  C和D盘的每秒写吞吐量

（6）是不是和业务SQL性能有关 ？

分析：

关于SQL变慢，通过分析数据库日志发现，拉取同步数据的关键SQL缺乏正确的索引，进而导致其执行计划不是最优，理论分析这个执行计划也是不稳定的。随着业务同步数据的全量替换，以及表统计信息短时间内不能及时更新，SQLserver可能会根据查询参数比对统计信息而调整执行计划。

推测在09:35左右，这个SQL的执行计划发生变化导致性能出现更差的情形，而高并发的访问加剧了这个性能的问题。这一点表现在DB上就是CPU利用率升高，CPU利用率变高，反过来会影响SQL的性能（针对全体SQL）。

09:37前后相邻的两个诊断报告的等待事件表明Buffer Latch最大等待延迟也增加180ms（这表示Buffer Latch等待更严重）。调用端观察结果就是SQL执行时间变长的SQL比例越来越多。

关于SQL变慢，还需要关注的是，相对于问题发生前一天，数据库连接增长了300， CPU利用率也同比增长很多，从现有的数据很难断定是访问请求增加导致实例压力变化，还是实例压力变化导致访问增多（触发重试逻辑）。

这是一个恶性循环的过程，根源就是SQL执行缺乏正确的索引且并发很高！

监控佐证（如图3-3、3-4、3-5所示）。

SQL耗时分析报告，如表3-2所示。

表3-2  SQL耗时分析

重点问题SQL，SQL请求很高，且没有走上合适的索引（如图3-6所示）。

图3-6  问题SQL

问题当日09:02～09:37 期间总执次数:71163 次（实际从09:25开始），平均消耗时间0.72s。

问题当日09:31～09:56 期间总执次数:22914 次，平均消耗时间16.0s。

分析：

视图ViewEstimateIntrdayForE的定义（如图3-7所示）。

图3-7  视图定义

表FundData.dbo.SecuCodeRelationSMCode的索引（如图3-8所示）。

图3-8  SQL索引情况

小结

本文这个案例的发生，一层层剥开来看，最后还是SQL执行计划不佳引起。因为缺乏合适的索引，所以原SQL的执行计划很可能处于不稳定的状态，即SQLServer可能会根据压力状况、数据量、统计信息以及传参数值来判断当前的执行计划是否为最优，如果数据库基于内存中的信息判断有更好的选择（从数据库角度判断，这很可能是个更加错误的选择），就改变当前执行计划，从而导致性能上可能出现更大的延时，再加上高并发，就进一步放大了这一性能问题。

基于本次问题的整个过程处理和原因分析，可以总结出以下几点措施和优化点来避免类似问题重复发生：

（1）如何避免服务器异常流量？

优化服务器主机日志同步方式，可考虑迁移现有成熟的日志同步工具。

（2）大量close wait的异常怎么才能避免？

从业务上下游主链路梳理超时时间参数和SQL超时设置，对齐超时标准，统一调优。

（3）如何避免“open toomany files”？

检查文件读写操作、socket通讯是否正常。

（4）业务如何避免同类SQL执行计划问题发生？

针对TOP10 SQL集中review 执行计划和索引设置，避免触发SQLServer的可能的潜在问题。

数据库主机虽有CPU等系统监控，但是并无执行计划的监控，完善SQL执行计划的监控覆盖。

（5）线上问题迅速发现

完善依托公有云的业务应用监控，尤其是远程调用和数据库访问的监控数据完善，便于后续第一时间发现问题。

完善添加关系型数据库SQL执行计划监控项，添加数据库容量带宽和连接数的监控。

（6）问题快速定位

线上问题快速定位和排查能力提升，定位问题需要分阶段定位，首先定位外部系统原因，数据库原因，网络原因还是应用程序原因。本次在定位是数据库的原因耗时太长，丧失了数据库层面的第一现场。

问题处理环节，需以最快的时间协同不同团队之间的响应处理，避免错失问题排查的最佳时间窗口。

本文选自《逆流而上》

购买本书，请点击“查看原文”！