解决Bug之路——中间件引发的SQL排错过程回忆前言：最近在网上遇到一个奇怪的问题。为了解决这个问题，作者进行了很长时间的努力。这个问题的排查过程非常有趣。正好我很久没有更新博客了，所以就根据它写了这篇文章。
Bug场景经过一年的风雨，分库分表中间件已经到了一个相对稳定的阶段。另外，经过在线压测，单机每秒可运行1.7W的SQL。然而，网上的事情仍然发生超出我们的预期。某业务线报告每天都有多个SQL 语句超时超过10 秒。更奇怪的是，不存在SQL 在主键更新或主键查询时超时的模式，如下图所示。
值得注意的是，这个业务只有一部分流量经过中间件，其余的直接到数据库，只有中间件连接时才会出现超时SQL（如下图：所示）。
显然这个问题是由于中间件的引入引起的。
检查你的SQL 是否真的很慢。由于数据库中间件只考虑SQL，并没有记录对应应用程序的TraceId，因此很难将相应的请求与SQL进行匹配。这里我们先粗略统计一下应用端超时的SQL类型是否超时。通过分析日志，我们发现该期间的所有SQL语句在后端数据上的执行时间仅为0.5毫秒，速度非常快。如下图
中间件和数据库之间的交互似乎没问题。继续检查线索。
由于找到超时模式很难将相应的请求与中间件执行SQL 之间的关系绑定起来，因此作者可以列出所有异常并识别它们，以便对中间件进行故障排除。我们希望查看时间点是否存在任何模式。批处理导致性能下降。下面是一些Timeout SQL业务方提供的信息：
营业开始时间
执行SQL的应用程序IP
业务执行时间（秒）
2023年12月24日09:45:24
xx.xx.xx.247
11.75
2023年12月24日12:06:10
xx.xx.xx.240
10.77
2023年12月24日12:07:19
xx.xx.xx.138
13.71
2023年12月24日22:43:07
xx.xx.xx.247
10.77
2023年12月24日22:43:04
xx.xx.xx.245
13.71
不同应用程序IP 上似乎不存在缓慢SQL 的模式，排除了任何特定的应用程序问题。超时发生在上午9:00到晚上22:00，消除了特定时间点性能集中下降的可能性。
查看了一段时间的大量数据后，我发现了一个小规律，如下面两篇文章：所示。
营业开始时间
执行SQL的应用程序IP
业务执行时间（秒）
2023年12月24日22:43:07
xx.xx.xx.247
10.77
2023年12月24日22:43:04
xx.xx.xx.245
13.71
这两个SQL超时对应的时间是一个22:43:07和一个22:43:04。差距只有3秒。如果加上后续的业务执行时间，你会发现更加接近。我们来排序：
营业开始时间
执行SQL的应用程序IP
业务执行时间（秒）
任务完成时间（秒）
2023年12月24日22:43:07
xx.xx.xx.247
10.77
22:43:17.77
2023年12月24日22:43:04
xx.xx.xx.245
13.71
22.43:17.71
事实证明，这两项业务起步时间不同，但同时完成。这可能是巧合，也可能是错误的结果。我们定期检查是否存在慢SQL，并要求公司向我们提供最新的慢SQL，我们发现这种现象很少见，但多次出现。笔者突然觉得这并非巧合。
上述规则引发的想法是，假设一个中间件被卡住了，如果此时两个SQL 同时落在同一个SQL 上，那么首先是中间件被卡住，然后那个中间件会提醒我。当中间件以0.5ms的速度执行并在返回的那一刻就返回时，就会出现这种现象。如下图
当然，还有另一种可能，即SQL最初以0.5ms的速度运行，然后中间件停止了。与上面唯一的区别是中间件卡的位置。如下图所示
同一个中间件线上总共有4个中间件吗？经过一系列复杂的在线日志提取和分析，我们发现两条SQL属于同一个中间件。为了证实我们的猜测，我们又发现了两条符合这个规则的SQL语句。它们位于同一个中间件上，但这两个中间件并不相同。这排除了特定中间件的任何问题。机器。如下图
业务日志和中间件日志对比根据以上结果，我们进行了各种日志分析并采取了措施，结果发现SQL日志和业务日志之间存在关联性，这个关联性需要很长时间。接下来，找到重要信息。中间件收到SQL后输出日志。可以看到，应用程序发送SQL和接收到SQL执行后续路由逻辑之间有大约10秒的时间差。然后SQL就会很快执行并返回，如下图所示的Show :
我检查了当时中间件对应的其他SQL语句是否有异常，而当时检索中间件日志时发现，除了这两条SQL语句之外，其他SQL语句都是正常的。全程也很正常。耗时大概1ms左右，陷入了沉思。
接下来，在日志中查找信息。经过我们对当前中间件日志的思考和分析，我们发现慢SQL对应的NIO线程在一秒内处理的SQL数量要少得多。比其他NIO 线程。更进一步，我们注意到慢SQL 所在的NIO 线程在第二个特定点之前没有发出任何日志，如下图所示。
同时我们还发现有两条SQL语句落入了对应的Reactor-Thread-2线程中。再往回看，我们发现该线程在过去10秒内没有输出任何信息。它被处理了。如下图
我感觉我们离真相越来越近了。这里很明显，反应堆线程被卡住了。
为了寻找反应器线程卡住的原因，作者继续跟踪线索，并比较了几个卡住的反应器线程最后输出的日志。这些日志对应的SQL立即返回，说明没有异常。然后我比较了一些卡住的reactor线程恢复后的第一个SQL输出，发现路由解析非常慢，达到了1毫秒（通常是0.01毫秒）好吧，然后我找到了相应的SQL。所有这些SQL 的大小约为150K。正常的想法是，损失的10 秒应该是处理这150K 个SQL，如下图所示：
为什么处理150K的SQL需要10秒？请检查是否是网络问题。首先，这个SQL在连接到中间件之前就存在，大约需要0.5毫秒。中间件将SQL 发送到数据库也需要大约相同的时间。如果有网络问题，这段时间暂时不考虑。
为了检查问题是否出在nio网络处理代码上，我认为可能是中间件的nio处理代码有问题，于是我构建了相同的SQL并离线重现，发现执行速度很快，压力很大。自由的。我曾经怀疑是我线上环境的问题，但是当我运行traceroute时发现网络与离线基本相同，MTU为1500。沿途没有任何路线。我的思绪突然又停了下来。
想了很久，没有结果。我想检查一下构建的场景是否有问题，但是网上，使用的是prepareStatement，但不同的是select格式中使用的是Prepare。带有参数的语句直接采用select 1,2,3 的形式。
我们的中间件还支持prepareStatement，因为它显着提高了后端数据库的SQL性能。然后，为了能够复用原来的SQL解析代码，在接收到对应的SQL和参数后，恢复没有它的SQL，计算要路由到的数据库节点，并转换原来的SQL和Prepare参数。对应的数据库：如下图
重建prepareStatement场景当作者重建prepareStatement场景，发现150K SQL确实花了10秒时，他终于感觉看到了一些曙光。
最后一个原因是字符串连接是离线完成的。登录到各个位置后，我注意到将SQL 渲染为没有问号的SQL 需要很长时间。下面是代码图：
String sql=\’select ,\’;for(int i=0 ; i paramCount;i++){ sql=sql.replaceFirst(\’\\\\ \’,param[i]);如果字符串很大并且需要替换的字符频繁出现，这个replaceFirst会消耗很大的性能。之前我们发现replaceFirst操作有一个常规操作会导致特殊符号无法正确渲染SQL（还有包含“的参数），所以我们使用了split的方式来渲染SQL。但是这个版本并没有在集群上使用支持此应用程序，在这种情况下，这些额外的定期操作可能特别不利于replacementFirst 性能。
更改为新版本并进行相应优化后，新代码将如下所示：
String Splits[]=sql.split(\’\\\\ \’);String result=\’\’;for(int i=0;i解析时间从10秒减少到2秒，但还是不太理想。这个应用使用jdk1.8，所以我一直以为jdk1.8可以让我直接使用原生字符串拼接，而不需要使用StringBuilder，但我还是尝试了一下，我发现速度从2ms下降到了8ms，代码如下：
String Splits[]=sql.split(\’\\\\ \’);StringBuilder builder=new StringBuilder();for(int i=0;i笔者查了资料，发现jdk 1.8虽然做了优化，但是拼接了一个新的StringBuilder仍然是每次创建StringBuilder时都会创建，因此在频繁串联大字符串的场景下，仍然需要StringBuilder以避免性能进一步下降。
综上所述，IO线程无法执行耗时的操作，因此在编写代码时，必须仔细评估相应的分库、分表等基础组件。在某些情况下使用时，如果出现重大性能问题，您就不能忽视这一点。如果没有的话，那就是下一个坑了。任何复杂的错误分析过程都是一个挑战。最重要也是最难解决的就是找出问题所在。识别问题所需要做的就是观察现象，提出不同的想法，并利用日志和其他信息一一反驳你的想法，直到找到唯一的问题。
更多实用文章请关注作者公众号《解Bug之路》。
本文和图片来自网络，不代表火豚游戏立场，如若侵权请联系我们删除：https://www.huotun.com/game/567714.html