多次执行sql 后卡住_解Bug之路记一次中间件导致的慢SQL排查过程

解Bug之路-记一次中间件导致的慢SQL排查过程

前言

最近发现线上出现一个奇葩的问题,这问题让笔者定位了好长时间,期间排查问题的过程还是挺有意思的,就以此为素材写出了本篇文章。

Bug现场

我们的分库分表中间件在经过一年的沉淀之后,已经到了比较稳定的阶段。而且经过线上压测的检验,单台每秒能够执行1.7W条sql。但线上情况还是有出乎我们意料的情况。有一个业务线反映,每天有几条sql有长达十几秒的超时。而且sql是主键更新或主键查询,更奇怪的是出现超时的是不同的sql,似乎毫无规律可寻,如下图所示:6876b602e50def66128e58d00e13dc24.png
一个值得注意的点,就是此业务只有一部分流量走我们的中间件,另一部分还是直接走数据库的,而超时的sql只会在连中间件的时候出现,如下图所示:f4eb8ae7a454b1b7c2dbb031a0d8a310.png
很明显,是引入了中间件之后导致的问题。

排查是否sql确实慢

由于数据库中间件只关心sql,并没有记录对应应用的traceId,所以很难将对应的请求和sql对应起来。在这里,我们先粗略的统计了在应用端超时的sql的类型是否会有超时的情况。
分析了日志,发现那段时间所有的sql在往后端数据执行的时候都只有0.5ms,非常的快。如下图所示:2a1d20511460daecd55a432424a50877.png
看来是中间件和数据库之间的交互是正常的,那么继续排查线索。

寻找超时规律

由于比较难绑定对应请求和中间件执行sql之间的关系,于是笔者就想着列出所有的异常情况,看看其时间点是否有规律,以排查一些批处理导致中间件性能下降的现象。下面是某几条超时sql业务方给出的信息:

业务开始时间执行sql的应用ip业务执行耗时(s)
2018-12-24 09:45:24xx.xx.xx.24711.75
2018-12-24 12:06:10xx.xx.xx.24010.77
2018-12-24 12:07:19xx.xx.xx.13813.71
2018-12-24 22:43:07xx.xx.xx.24710.77
2018-12-24 22:43:04xx.xx.xx.24513.71

看上去貌似没什么规律,慢sql存在于不同的应用ip之上,排除某台应用出问题的可能。
超时时间从早上9点到晚上22点都有发现超时,排除了某个点集中性能下降的可能。

注意到一个微小的规律

笔者观察了一堆数据一段时间,终于发现了一点小规律,如下面两条所示:

业务开始时间执行sql的应用ip业务执行耗时(s)
2018-12-24 22:43:07xx.xx.xx.24710.77
2018-12-24 22:43:04xx.xx.xx.24513.71

这两笔sql超时对应的时间点挺接近的,一个是22:43:07,一个是22:43:04,中间只差了3s,然后与后面的业务执行耗时相加,发现更接近了,让我们重新整理下:

业务开始时间执行sql的应用ip业务执行耗时(s)业务完成时间(s)
2018-12-24 22:43:07xx.xx.xx.24710.7722:43:17.77
2018-12-24 22:43:04xx.xx.xx.24513.7122.43:17.71

发现这两笔业务虽然开始时间不同,但确是同时完成的,这可能是个巧合,也可能是bug出现导致的结果。于是继续看下是否有这些规律的慢sql,让业务又提供了最近的慢sql,发现这种现象虽然少,但是确实发生了不止一次。笔者突然感觉到,这绝对不是巧合。

由上述规律导致的思考

笔者联想到我们中间件有好多台,假设是中间件那边卡住的话,如果在那一瞬间,有两台sql同时落到同一台的话,中间件先卡住,然后在中间件恢复的那一瞬间,以0.5ms的速度执行完再返回就会导致这种现象。如下图所示:82496caee6c45543400c00f97d9b2d34.png
当然了还有另一种可能,就是sql先以0.5ms的速度执行完,然后中间件那边卡住了,和上面的区别只是中间件卡的位置不同而已,另一种可能如下图所示:519037918ef5b0b0fd00c3b80df3cc58.png

是否落到同一台中间件

线上一共4台中间件,在经历了一堆复杂线上日志捞取分析相对应之后,发现那两条sql确实落在了同一台中间件上。为了保证猜想无误,又找了两条符合此规律的sql,同样的也落在同一台中间件上面,而且这两台中间件并不是同一台,排除某台机器有问题。如下图所示:663854cf2960f8adb07283d2d2a31417.png

业务日志和中间件日志相对照

在上述发现的基础上,又经历了各种日志分析对应之后,终于找到了耗时sql日志和业务日志对应的关联。然后发现一个关键信息。中间件在接收到sql时候会打印一条日志,发现在应用发出sql到接收到sql还没来得及做后面的路由逻辑之前就差了10s左右,然后sql执行到返回确是非常快速的,如下图所示:8dbce9b6901946c43ed7b8bf3bb8e180.png

查看对应中间件那个时间点其它sql有无异常

笔者捞取了那个时间点中间件的日志,发现除了这两条sql之外,其它sql都很正常,整体耗时都在1ms左右,这又让笔者陷入了思考之中。

再从日志中找信息

在对当前中间件的日志做了各种思考各种分析之后,又发现一个诡异的点,发现在1s之内,处理慢sql对应的NIO线程的处理sql数量远远小于其它NIO线程。更进一步,发现在这1s的某个时间点之前,慢sql所在的NIO线程完全不打印任何日志,如下图所示:809652ce82b3fb2cf377bb265292da8f.png
同时也发现两条sql都落在对应的Reactor-Thread-2的线程里面,再往前回溯,发现近10s内的线程都没有打印任何信息,好像什么都没处理。如下图所示:5e5f8920e8acf9d4c22ee59e6567d1cd.png
感觉离真相越来越近了。这边就很明显了,reactor线程被卡住了!

寻找reactor线程为何被卡住

笔者继续顺藤摸瓜,比较了一下几个卡住的reactor线程最后打印的日志,发现这几条日志对应的sql都很快返回了,没什么异常。然后又比较了一下几个卡住的reactor线程恢复后打印出来的第一条sql,发现貌似它们通过路由解析起来都很慢,达到了1ms(正常是0.01ms),然后找出了其对应的sql,发现这几条sql都是150K左右的大小,按正常思路,这消失的10s应该就是处理这150K的sql了,如下图所示:00518f34465b340465bcddece69192a7.png

为何处理150K的sql会耗时10s

排查是否是网络问题

首先,这条sql在接入中间件之前就有,也就耗时0.5ms左右。而且中间件在往数据库发送sql的过程中也是差不多的时间。如果说网络有问题的话,那么这段时间应该会变长,此种情况暂不考虑。

排查是否是nio网络处理代码的问题

笔者鉴于可能是中间件nio处理代码的问题,构造了同样的sql在线下进行复现,发现执行很快毫无压力。笔者一度怀疑是线上环境的问题,traceroute了一下发现网络基本和线下搭建的环境一样,都是APP机器直连中间件机器,MTU都是1500,中间也没任何路由。思路一下又陷入了停滞。

柳暗花明

思考良久无果之后。笔者觉得排查一下是否是构造的场景有问题,突然发现,线上是用的prepareStatement,而笔者在命令行里面用的是statement,两者是有区别的,prepare是按照select ?,?,?带参数的形式而statement直接是select 1,2,3这样的形式。

而在我们的中间件中,由于后端的数据库对使用prepareStatement的sql具有较大的性能提升,我们也支持了prepareStatement。而且为了能够复用原来的sql解析代码,我们会在接收到对应的sql和参数之后将其还原成不带?的sql算出路由到的数据库节点后,再将原始的带?的sql和参数prepare到对应的数据库,如下图所示:2cd37f255bb05c0c2f59b553a267927f.png

重新构造prepareStatement场景

笔者重新构造了prepareStatement场景之后,发现在150K的sql下,确实耗时达到了10s,感觉终于见到曙光了。

最终原因字符串拼接

由于是线下,在各种地方打日志之后,终于发现耗时就是在这个将带?的sql渲染为不带问号的sql上面。下面是代码示意:

String sql="select ?,?,?,?,?,?...?,?,?...";
for(int i=0 ; i < paramCount;i++){
sql = sql.replaceFirst("\\?",param[i]);
}
return sql;

这个replaceFirst在字符串特别大,需要替换的字符频率出现的特别多的时候方面有巨大的性能消耗。之前就发现replaceFirst这个操作里面有正则的操作导致特殊符号不能正确渲染sql(另外参数里面带?也不能正确渲染),于是其改成了用split ?的方式进行sql的渲染。但是这个版本并没有在此应用对应的集群上使用。可能也正是这些额外的正则操作导致了这个replaceFirst性能在这种情况下特别差。

对应优化

将其改成新版本后,新代码如下所示:

String splits[] = sql.split("\\?");
String result="";
for(int i=0;i if(i result+=splits[i]+getParamString(paramNumber);
}else{
result+=splits[i];
}
}
return result;

这个解析时间从10s下降至2s,但感觉还是不够满意。
经同事提醒,试下StringBuilder。由于此应用使用的是jdk1.8,笔者一直觉得jdk1.8已经可以直接用原生的字符串拼接不需要用StringBuilder了。但还是试了一试,发现从2s下降至8ms!
改成StringBuilder的代码后如下所示:

String splits[] = sql.split("\\?");
StringBuilder builder = new StringBuilder();
for(int i=0;i if(i builder.append(splits[i]).append(getParamString(paramNumber));
}else{
builder.append(splits[i]);
}
}
return builder.toString();

笔者查了下资料,发现jdk 1.8虽然做了优化,但是每做一次拼接还是新建了一个StringBuilder,所以在大字符串频繁拼接的场景还是需要用一个StringBuilder,以避免额外的性能损耗。

性能之巅

事实上性能分析还是有一堆方法论的,下面这本书就能帮到你:

这本书有非常详细的性能排查清单,出现问题按照checklist进行排查,基本就能做到心中有数。

总结

IO线程不能做任何耗时的操作,这样会导致整个吞吐量急剧下降,对应分库分表这种基础组件在编写代码的时候必须要仔细评估,连java原生的replaceFirst也会在特定情况下出现巨大的性能问题,不能遗漏任何一个点,否则就是下一个坑。
每一次复杂Bug的分析过程都是一次挑战,解决问题最重要也是最困难的是定位问题。而定位问题需要的是在看到现象时候能够浮现出的各种思路,然后通过日志等信息去一条条否决自己的思路,直至达到唯一的那个问题点

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.mzph.cn/news/507257.shtml

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈email:809451989@qq.com,一经查实,立即删除!

相关文章

centos安装mysql5.6系统崩溃_CentOS7安装MySQL5.6冲突总结

[rootlocalhost ypeng]# service mysql statusRedirecting to /bin/systemctl status mysql.serviceUnit mysql.service could not be found.出现以上安装错误的原因是&#xff1a;系统已经可能是系统装了其他版本的mysql-libs包或者是mysql数据库文件导致不兼容。可以将MySQL彻…

c++思维导图_40+张最全Linux/C/C++思维导图,你确定不收藏?

ID&#xff1a;技术让梦想更伟大整理:李肖遥申明&#xff1a;所有图片都源自网络素材&#xff0c;侵删。这是我自己收集的&#xff0c;并花大量时间整理的可说最全的Linux/C/C思维导图。有些图可能不是高清&#xff0c;但是放大即可看清楚。linux思维导图认识LinuxLinux学习路径…

mysql logtimestamps_MySQL5.7.18参数log_timestamps导致日志信息时间差8小时

MySQL5.7.18参数log_timestamps导致日志信息时间差8小时环境:MySQL5.7.18CentOS6.8背景:排查问题查看mysql日志的时候发现mysql错误日志和慢查询日志中的时间戳信息比正常时间少了8小时.官方资料显示:log_timestamps 自5.7.2版本被引入&#xff0c;此参数控制了general log、er…

fortran安装_如何在 CentOS 8 上安装 GCC

本文最先发布在&#xff1a;如何在 CentOS 8 上安装 GCC​www.itcoder.techGNU 编译器集合是一系列用于语言开发的编译器和库的集合&#xff0c;包括: C, C, Objective-C, Fortran, Ada, Go, and D等编程语言。很多开源项目&#xff0c;包括 Linux kernel 和 GNU 工具&#xff…

mysql登录root 1130_通过Navicat for MySQL远程连接的时候报错mysql 1130的解决方法

解决方法&#xff1a;1。改表法。可能是你的帐号不允许从远程登陆&#xff0c;只能在localhost。这个时候只要在localhost的那台电脑&#xff0c;登入mysql后&#xff0c;更改"mysql" 数据库里的 "user" 表里的 "host"项&#xff0c;从"loc…

c# out原理 ref_移植贪吃蛇——从C#到C++

欢迎参与讨论&#xff0c;转载请注明出处。前言因为某些机缘巧合&#xff0c;引起了我对C的重视。一时兴起&#xff0c;决定将两年前用Unity写的Snake进行移植。经过两周的抽空&#xff0c;总算是完成了。项目采用现代C标准编写&#xff0c;采用CMake构建&#xff0c;图形库为S…

seata 如何开启tcc事物_分布式事务Seata-TCC源码分析

为了更好理解分布式事务&#xff0c;首先提出一个问题&#xff1a;假设数据库中有两个表ta&#xff0c;tb&#xff0c;我们要分别更改ta表中的ra记录和tb表中的rb记录&#xff0c;但要求ra和rb记录都修改成功&#xff0c;才认为此次操作时成功&#xff0c;或者需要失败回滚。针…

helm安装mysql_helm安装配置

简介helm是kubernetes的包管理工具&#xff0c;用于简化部署和管理 Kubernetes 应用。用来管理charts——预先配置好的安装包资源。Helm和charts的主要作用&#xff1a;应用程序封装版本管理依赖检查便于应用程序分发helm是一个C/S框架的软件&#xff0c;helm相当于一个客户端&…

promise的三种状态_一.Promise中核心逻辑的实现

首先看一下Promise代码&#xff1a;let promise new Promise((resolve,reject)>{resolve(成功);//reject(失败); }) promise.then(val>{console.log(val); },reason>{console.log(reason); })我们根据以上的一个简单的用例&#xff0c;得到Promise类的最主要的核心逻辑…

mysql如何定位到数据_如何快速定位当前数据库消耗CPU最高的sql语句?

概述如果是Oracle数据库我们可以很容易通过sql来定位到当前数据库中哪些消耗CPU高的语句&#xff0c;而mysql数据库可以怎么定位呢&#xff1f;这里用一个简单例子说明下...主要是了解如何定位的思路&#xff0c;具体看官网介绍..参考&#xff1a;https://www.percona.com/blog…

当当elastic-job docker快速部署_[小Z课堂]-docker 快速部署 elasticsearch 和 kibana,一键部署...

各位小伙伴&#xff0c;小Z课堂来袭&#xff0c;每天只需看三分钟&#xff0c;你就能用docker 快速部署各种环境。今天就用docker 来部署 elasticsearch 和 kibana。docker的入门请上度娘学习&#xff0c;这里直接进入实战。拉镜像镜像版本&#xff1a;base image&#xff1a;U…

xtrabackup备份mysql5.7_【 xtrabackup】CentOS7.x上基于 MySQL 5.7.x的XtraBackup 安装与备份还原...

MySQL的XtraBackup 备份与恢复https://shockerli.net/post/xtrabackup-backup-recovery-mysqlPercona XtraBackup 备份原理与实践http://www.unixfbi.com/349.htmlXtraBackup备份恢复模拟实践https://blog.51cto.com/13178102/2151512Percona XtraBackup 安装介绍篇https://www…

数字有维度, 质数可追寻

摘要 用数轴的点表示数, 实际是把数的几何意义单一 化, 把所有实数同等化. 在研究素数的问题上, 应该挖掘数的 更多几何意义, 就正自然数而言, 不同区间的数, 几何意义是 不相同的, 对应的点是不同空间的点, 具有多样化的. 寻找质 数, 就是设法把不同空间的 1 维数 (质数) 找出…

局域网聊天程序 java MySQL_课内资源 - 基于JAVA的局域网聊天软件的设计与实现(仿制QQ)...

一、系统分析1.1 问题描述客户端实现简易版的局域网聊天器实现富文本内容聊天智能聊天机器人群发消息传送文件等功能服务器端实现群发通知管理聊天线程1.2 系统功能分析客户端功能登陆注册发送表情消息发送文本消息截取图片图片处理震动效果发送文件群发消息设置聊天文本样式服…

北工大一拟录取女研究生在网络发不当言论,已被网友举报!

近日&#xff0c;北工大一拟录取女研究生在自己的社交平台发表不当的言论。随后&#xff0c;其言论引起网友的热议。>>>>对于网友的质疑&#xff0c;其通过微博发文称&#xff0c;要“开小号专门打拳”。当天夜里&#xff0c;有网友通过其微博的公开的考研信息&…

mysql微服务查询问题_【mysql】微服务架构下跨服务查询的聚合有什么好的方案?...

微服务架构中&#xff0c;每个服务都有自己的独立数据库。然而现在有个需求&#xff0c;需要生成一张实时的报表&#xff0c;该报表包含两个服务的数据。如服务A&#xff0c;服务B。B中仅包含A的主键id作为关联。而此报表的搜索条件包含A服务实体中的字段也包含B服务实体中的字…

mnist数据集svm python_python支持向量机分类MNIST数据集

支持向量机在高维或无限维空间中构造超平面或超平面集合&#xff0c;其可以用于分类、回归或其他任务。直观来说&#xff0c;分类边界距离最近的训练数据点越远越好&#xff0c;因为这样可以缩小分类器的泛化误差。调用sklearn.svm的svc函数&#xff0c;将MNIST数据集进行分类&…

mysql触发器可以使用正则表达式_SQL 正则表达式及mybatis中使用正则表达式

这篇文章主要介绍了SQL 正则表达式及mybatis中使用正则表达式的方法&#xff0c;非常不错&#xff0c;具有一定的参考借鉴价值,需要的朋友可以参考下mysql 提供的模式匹配的其他类型是使用扩展正则表达式。当你对这类模式进行匹配测试时&#xff0c;使用REGEXP和NOT REGEXP操作…

python代码200行左右_200行Python代码实现2048

import cursesfrom random import randrange,chiocefrom collections import defaultdictactions[Up,Left,Down,Right,Restart,Exit]letter_codes[ord(ch) for ch in WASDRQwasdrq]action_dictdict(zip(letter_codes,actions*2))def main(stdscr):def init():#重置游戏棋盘game…

python将excel导入mysql_Python将Excel数据自动导入MySQL,python,实现,excel,到,中

废话不多说&#xff0c;下面附上代码。# -*- coding: utf-8 -*-"""Created on Mon Apr 20 14:18:49 2020author: admin"""import osimport pandas as pd#import cx_Oracle as cxfrom sqlalchemy import create_engineimport pymysqlfile_name[]#…