(十八)MySQL排查篇:该如何定位并解决线上突发的Bug与疑难杂症?

7,919 阅读34分钟

引言

本文为掘金社区首发签约文章,14天内禁止转载,14天后未获授权禁止转载,侵权必究!

   前面《MySQL优化篇》《SQL优化篇》两章中,聊到了关于数据库性能优化的话题,而本文则再来聊一聊关于MySQL线上排查方面的话题。线上排查、性能优化等内容是面试过程中的“常客”,而对于线上遇到的“疑难杂症”,需要通过理性的思维去分析问题、排查问题、定位问题,最后再着手解决问题,同时,如果解决掉所遇到的问题或瓶颈后,也可以在能力范围之内尝试最优解以及适当考虑拓展性。

对于线上排查方面的文章,在之前的《JVM专栏》中,也出过一篇关于《JVM线上故障排查》的文章,性能优化也好,线上排查也罢,其实无论在哪个技术栈中,做这些工作的核心思想亦是共通的,所以MySQL线上排查的步骤,同样可参考JVM的线上排查步骤。

一、线上故障排查的思路与方向

   在程序开发与运行过程中,出现Bug问题的几率无可避免,数据库出现问题一般会发生在下述几方面:

  • ①撰写的SQL语句执行出错,俗称为业务代码Bug
  • ②开发环境执行一切正常,线上偶发SQL执行缓慢的情况。
  • ③线上部署MySQL的机器故障,如磁盘、内存、CPU100%MySQL自身故障等。

   当程序在开发/运行期间发生故障时又该如何处理呢?首先在碰到这类故障问题时,得具备良好的排查思路,再结合丰富的理论知识基础,通过经验+数据的支持依次分析后加以解决。

当然,上述这句话说了跟没说差不多哈,接下来聊一聊具体的排查和解决问题的思路。

1.1、线上排查及其解决问题的思路

   相对而言,解决故障问题也好,处理性能瓶颈也罢,通常思路大致都是相同的,步骤如下:

  • ①分析问题:根据理论知识+经验分析问题,判断问题可能出现的位置或可能引起问题的原因,将目标缩小到一定范围。
  • ②排查问题:基于上一步的结果,从引发问题的“可疑性”角度出发,从高到低依次进行排查,进一步排除一些选项,将目标范围进一步缩小。
  • ③定位问题:通过相关的监控数据的辅助,以更“细粒度”的手段,将引发问题的原因定位到精准位置。
  • ④解决问题:判断到问题出现的具体位置以及引发的原因后,采取相关措施对问题加以解决。
  • ⑤尝试最优解(非必须):将原有的问题解决后,在能力范围内,且环境允许的情况下,应该适当考虑问题的最优解(可以从性能、拓展性、并发等角度出发)。

   当然,上述过程是针对特殊问题以及经验老道的开发者而言的,作为“新时代的程序构建者”,那当然得学会合理使用工具来帮助我们快速解决问题:

  • ①摘取或复制问题的关键片段。
  • ②打开百度谷歌后粘贴搜索。
  • ③观察返回结果中,选择标题与描述与自己问题较匹配的资料进入。
  • ④多看几个后,根据其解决方案尝试解决问题。
  • ⑤成功解决后皆大欢喜,尝试无果后“找人/问群”。
  • ⑥“外力”无法解决问题时自己动手,根据之前的步骤依次排查解决。

前面给出了两套解决问题的步骤,面试/学习推荐前者,实际开发推荐后者,毕竟面试的时候人家问你怎么解决问题的,你总不能说靠百度,毕竟 “能够搜索出来的资料也是人写出来的,大家也能够成为这样的人!”

1.2、线上排查的方向

   数据库出现Bug的几率仅占一小部分,实际上一个业务系统中,各层面的节点都有可能存在一定的故障,但通常情况下来说,系统部署在线上出现问题,经过分析排查后,最终诱发问题的根本原因无非在于如下几点:

  • 应用程序本身导致的问题
    • 程序内部频繁触发GC,造成系统出现长时间停顿,导致客户端堆积大量请求。
    • JVM参数配置不合理,导致线上运行失控,如堆内存、各内存区域太小等。
    • Java程序代码存在缺陷,导致线上运行出现Bug,如死锁/内存泄漏、溢出等。
    • 程序内部资源使用不合理,导致出现问题,如线程/DB连接/网络连接/堆外内存等。
  • 上下游内部系统导致的问题
    • 上游服务出现并发情况,导致当前程序请求量急剧增加,从而引发问题拖垮系统。
    • 下游服务出现问题,导致当前程序堆积大量请求拖垮系统,如Redis宕机/DB阻塞等。
  • 程序所部署的机器本身导致的问题
    • 服务器机房网络出现问题,导致网络出现阻塞、当前程序假死等故障。
    • 服务器中因其他程序原因、硬件问题、环境因素(如断电)等原因导致系统不可用。
    • 服务器因遭到入侵导致Java程序受到影响,如木马病毒/矿机、劫持脚本等。
  • 第三方的RPC远程调用导致的问题
    • 作为被调用者提供给第三方调用,第三方流量突增,导致当前程序负载过重出现问题。
    • 作为调用者调用第三方,但因第三方出现问题,引发雪崩问题而造成当前程序崩溃。

   万变不离其宗,虽然上述中没有将所有可能会发生问题的位置写到,但总的来说,发生问题排查时,也就是这几个大的方向,先将发生问题的大体定位,然后再逐步推导出具体问题的位置,从而加以解决。

接着来聊一聊关于MySQL中一些Bug问题的排查手段,先从最基本的SQL报错聊起,接着再讲讲慢查询该如何排查和解决,最后再说说线上机器/程序故障时该如何排查。

二、SQL语句执行出错排查

   作为一个程序员,对MySQL数据库而言,接触最多的就是SQL语句的撰写,和写业务代码时一样,写代码时会碰到异常、错误,而写SQL时同样如此,比如:

ERROR 1064 (42000): You have an error in your SQL syntax; 
    check the manual that corresponds to your MySQL server version 
        for the right syntax to use near 'xxxxxxx' at line 1

在之前的《MySQL命令大全-错误码》中曾说到过,MySQL的错误信息会由三部分组成:

  • ErrorCode:错误码,上述错误信息中的1064
  • SQLStateSQL状态,也就是前面信息中的42000
  • ErrorInfo:错误详情,后面跟的一大长串描述则是具体的错误详情。

当在执行SQL时出现问题,一般都会抛出对应的错误信息,拿到了这些错误信息之后,其实解决的办法就比较简单了,首先可以参考具体的错误详情,如果英语好的小伙伴可以直接尝试阅读,如果英语不好的小伙伴可以借助一些翻译工具来转换成中文,比如上述的错误信息,从其给出的错误详情大致能够阅读出原因:

原文:You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'xxxxxxx' at line 1
翻译:您的SQL语法有错误;请查看与MySQL-Server版本对应的手册,以了解在第1“xxxxxxx”附近正确语法的使用方式。

从这段错误提示中可以明显得知:目前咱们执行SQL时遇到了一个语法错误,也就是SQL写错了,具体位置是第一行的'xxxxxxx'位置,所以如果要解决这个问题就很简单了,找到第一行'xxxxxxx'位置,观察后把SQL改对即可。

上述这种方式适用于绝大部分SQL报错的情况,如果遇到一个少见的错误,自己也无法从给出的错误信息中定位问题,这时最好的解决办法并不是自己研究,或者去问他人,而是直接百度/谷歌,作为一位合格的开发者,必须要能够熟练运用搜索引擎来解决问题,开发过程中遇到的80%问题都可以直接从网上找到答案,所以与其自己花精力去思考,或者去麻烦别人解决,不如直接在网上找现成的解决方案。

SQL执行报错,在网上要找这类问题的解决方案其实十分简单,毕竟MySQL内部对每种不同的错误都有对应的错误码,所以出现错误信息时,先直接去搜索对应的错误码即可,如下:
百度

基本上百度后就能出现对应的错误码详解,以及错误码出现后又该如何解决,这时我们需要做的仅仅只是点进去跟着操作即可,这种方法也是最省事省力的方案。

有人或许会疑惑,那万一我在百度上找不到解决方案怎么办?瞧这话说的,不是还是谷歌引擎嘛~

不过话说回来,靠人不如靠己,有时候确实网上的资源无法给咱们提供帮助时怎么办呢?这时咱们只能自行手动介入排查了,最经典也是最有效的排查方法,即是人.肉排查大法!对于这点稍后再细聊。

三、MySQL线上慢查询语句排查

   慢查询SQL排查其实是前面《SQL优化篇》最后遗留的一个问题,至于为何将其放到这篇来讲的原因其实也解释过,因为有些SQL可能在开发环境没有任何问题,但放到线上时就会出现偶发式执行耗时较长的情况,所以这类情况就只能真正在线上环境才能测出来,尤其是一些不支持灰度发布的中小企业,也只能放到线上测才能发现问题。

对于排查慢查询SQL而言,首先要做到的就是定位哪些SQL执行时较为耗时,但总不能把所有的SQL都做一遍监控吧?这样未免太影响性能了,其实对于这点咱们无需担心,在MySQL内部实际上早已提供了相关支持,也就是之前在《MySQL日志篇》聊到的慢查询日志,在项目上线之前手动开启一下慢查询日志即可。

但开启慢查询日志需要配置两个关键参数:

  • slow_query_log:取值为on、off,默认为off关闭,项目上线前需要手动开启。
  • long_query_time:指定记录慢查询日志的阈值,单位是秒,要指定更细粒度可以用小数表示。

重点是第二个参数,这个慢查询阈值并没有固定的标准,不同的业务系统取值也并不相同,为啥这样说呢?举个例子:现在有两个系统:

  • 一个是报表系统,主要负责对账、跑批、统计分析、报表导出....等工作。
  • 另一个系统则是一个门户网站,与用户直接交互,主要负责处理用户请求。

以上述这两个系统为例,将两个系统的慢查询日志阈值都设置为1s合适吗?这显然并不合适,因为报表系统中的大量操作基本上都会超出这个时间,毕竟涉及了大量的逻辑处理和运算的耗时工作。那如果将阈值调大呢?比如设置成5s合适吗?也不合适,因为这样可能会监控到报表系统的慢查询SQL,但却无法监控到门户网站的慢查询语句,毕竟在门户网站中超过800ms就算比较慢了。

因此从上述这个案例中可明显感受出来,对于慢查询日志的阈值分配,是一个比较讲究的技术活,设小了可能会收集到大量执行并不慢的SQL语句,设大了又可能造成真正的慢查询语句无法被记录下来。那么具体该如何设置合理的大小呢?具体的方法已经在之前的日志篇聊过了,大家感兴趣的话可自行去翻阅。

最后再提一嘴:如果想要每次MySQL重启时,慢查询的配置都生效,请记住不用使用set的方式在线修改,而是要将对应的参数配置到MySQL的配置文件中。

3.1、查看慢查询日志

   查看慢查询日志的方式,一般如果你的项目配备了完善的监控系统,通常情况下会自动去读取磁盘中的慢查询日志,然后可直接通过监控系统的大屏来观察。但如若未具备完善的监控系统,也可以通过cat这类命令去查看本地的日志文件,慢查询日志的磁盘文件默认位于MySQL的安装目录下,也可以通过slow_query_log_file=/xxx/xxx/xx.log的方式去手动指定。

下面举个例子来做实验,这里我可能会将慢查询阈值设置的很小,主要是为了观察到慢查询日志,因此诸位请不要纠结,实际的慢查询阈值还是需要根据业务来进行合理配置,如下:

-- 在MySQL客户端中直接使用 set 的方式修改

-- 先开启慢查询日志
set global slow_query_log = on;

-- 再查询默认的慢查询阈值(默认为10秒)
show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+

-- 手动修改慢查询阈值(设置为10ms)
set global long_query_time = 0.01;

-- 由于前面使用了global关键字设置了全局生效,因此需要重新连接
quit

-- 重连后再次查询慢查询阈值(已生效)
show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.010000 |
+-----------------+----------+

OK~,上面这组配置的含义是:当有查询语句的执行时长超过10msMySQL就会自动将其记录到慢查询日志中,下面来执行一条SQL试试感jio~

-- 一条普普通通的子查询语句
select 
    * 
from 
    zz_users 
where 
    user_id in (
        select user_id from zz_users where user_id < 5
    ) 
and 
    register_time < now();
+---------+-----------+----------+----------+---------------------+
| user_id | user_name | user_sex | password | register_time       |
+---------+-----------+----------+----------+---------------------+
|       1 | 熊猫      || 6666     | 2022-08-14 15:22:01 |
|       2 | 竹子      || 1234     | 2022-09-14 16:17:44 |
|       3 | 子竹      || 4321     | 2022-09-16 07:42:21 |
|       4 | 黑熊      || 8888     | 2022-09-17 23:48:29 |
+---------+-----------+----------+----------+---------------------+
4 rows in set (0.015 sec)

从上述的执行结果来看,其实这里执行的耗时为15ms,已经超出了咱们设定的10ms,那接着一起去看看磁盘中的慢查询日志吧!如果你不清楚你本地慢查询日志文件的位置,可以通过下述命令查询:

  • show variables like 'slow_query_log_file';

此时找到本地的慢查询日志,接着打开它来瞧瞧其中是否有数据呢?如下:
慢查询日志
因为我是在Windows系统,所以可以直接用记事本打开,如果你是Linux系统,记得使用cat命令即可。

从上面日志中记录的查询信息来看,可以得知几个信息:

  • 执行慢查询SQL的用户:root,登录IP为:localhost[127.0.0.1]
  • 慢查询执行的具体耗时为:0.014960s,锁等待时间为0s
  • 本次SQL执行后的结果集为4行数据,累计扫描6行数据。
  • 本次慢查询发生在db_zhuzi这个库中,发生时间为1667466932(2022-11-03 17:15:32)
  • 最后一行为具体的慢查询SQL语句。

3.2、排查SQL执行缓慢问题

   读取慢查询日志后,能够让咱们精准定位到发生慢查询SQL的用户、客户端机器、执行耗时、锁阻塞耗时、结果集行数、扫描行数、发生的库和时间、以及具体的慢查询SQL语句,得到了这些信息后,其实排查引起慢查询的原因就比较简单了。步骤如下:

  • 先根据本地慢查询日志文件中的记录,得到具体慢查询SQL执行的相关信息。
  • 查看Look_time的耗时,判断本次执行缓慢,是不是由于并发事务导致的长时间阻塞。
  • 如果不是,则通过《SQL优化篇》中说的explain索引分析工具,先判断索引的使用情况。

一般来说在开发环境中没有问题的SQL语句,放到线上环境出现执行缓慢的情况,多半原因是由于并发事务抢占锁,造成当前事务长时间无法获取锁资源,因此导致当前事务执行的SQL出现超时,这种情况下需要去定位操作相同行数据的大事务,一般长时间的阻塞是由于大事务持有锁导致的,找出对应的大事务并拆解或优化掉即可。

通过show status like 'innodb_row_lock_%';命令可以查询MySQL整体的锁状态,如下:
锁性能表现

  • Innodb_row_lock_current_waits:当前正在阻塞等待锁的事务数量。
  • Innodb_row_lock_timeMySQL启动到现在,所有事务总共阻塞等待的总时长。
  • Innodb_row_lock_time_avg:平均每次事务阻塞等待锁时,其平均阻塞时长。
  • Innodb_row_lock_time_maxMySQL启动至今,最长的一次阻塞时间。
  • Innodb_row_lock_waitsMySQL启动到现在,所有事务总共阻塞等待的总次数。

如果你在慢查询日志中,看到了大量由于锁阻塞导致执行超出慢查询阈值的SQL,那可以执行上述这条指令看看整个MySQL的锁状态,如果这些值都比较大时,就意味着你当前这个MySQL节点承载的并发压力过高,此时就急需进行《MySQL架构优化》


但如果慢查询不是因为锁阻塞导致的,那此时又该如何处理呢?不是锁阻塞导致的,那绝对是SQL执行时本身出现了问题,这时可以先用explain工具分析SQL的执行计划,查看索引的使用情况,找到那些执行计划中扫描行数过多、type=index、allSQL语句,尝试优化掉即可(但是要注意:如果是8.0以下版本的MySQL,在使用explain工具分析前,一定要记得设置SQL_NO_CACHE,否则会从查询缓存中读取数据)。

不过explain工具在分析复杂SQL时,生成的执行计划可能会比较多,如果你对该工具用的比较熟悉,那可以直接分析生成的执行计划,但这种方式略微会有些难以观测,最好的办法则是之前提到的人.肉排查大法!还记得上篇聊到的《撰写SQL的基本功》嘛?

对于一些较为复杂或庞大的业务需求,可以采取拆分法去逐步实现,最后组装所有的子语句,最终推导出符合业务需求的SQL语句。

所谓的人.肉排查法,也就是将一条复杂的查询语句,拆解成一条条的子语句,毕竟咱们除开要学会拆解需求外,还得掌握拆解复杂SQL的能力,拆解后可以对每条子语句使用explain工具分析,这样就能够精准定位到:复杂语句中导致耗时较长的具体子语句,最后将这条子语句优化后重新组装即可。

拆解排除法还有一个最大的好处是:有时组成复杂SQL的每条子语句都不存在问题,也就是每条子语句的执行效率都挺不错的,但是拼到一起之后就会出现执行缓慢的现象,这时拆解后就可以一步步的将每条子语句组装回去,每组装一条子语句都可以用explain工具分析一次,这样也能够精准定位到是由于那条子语句组合之后导致执行缓慢的,然后进行对应优化即可。

按照上述的方法论,基本上能够让你解除掉所有的慢查询问题,但在之前的SQL优化篇也说到过:如果是由于业务本身就会导致SQL检索数据量较大,那这种情况是无法进行优化的,此时就只能从业务层面着手解决。

最后再说一下为什么这种方法被称之为人.肉排查大法,这个名字是由战争时期的一个场景演变过来的,战争时期基本上都会有地雷战,也就是守的一方会布置地雷去阻碍攻方的进程,如果攻方停下来让地雷兵用仪器探测,然后拆除掉地雷,这个过程会十分耗时,如果这样做就会让守方达成拖延进程的目的。

这种情况下攻方为了进程不被耽误,通常会选择让人直接飞速的跑过去,也就是靠人直接踩雷的行为去引爆地雷,从而做到排雷的效果,以便于后方大部队的进程不会收到影响,而这个方法则被称为人.肉排雷法。

同样的思想换到编程中也相同,目前出现了问题,但是由于组成SQL的子语句过多,无法精准定位具体的问题出现原因,则会挨个拆解后分析,最终得出引出问题的SQL语句,这个思想在解决SQL执行报错时也额外好用,毕竟如果无法通过外力去排查问题时,这种方式就成了上上策,虽然看起来很傻,但却非常非常实用。也包括在Java中也可以去通过System.out.println("...");不断输出的方式排查问题,其思想与之相同。

四、MySQL线上机器故障排查

   MySQL数据库线上的机器故障主要分为两方面,一方面是由于MySQL自身引起的问题,比如连接异常、死锁问题等,另一方面则是部署MySQL的服务器硬件文件,如磁盘、CPU100%等现象,对于不同的故障问题排查手段也不同,下面将展开聊一聊常见的线上故障及解决方案。

4.1、客户端连接异常

客户端连接异常也是一种较为常见的故障,这里有可能是因为多方面原因导致的,如下:

  • ①数据库总体的现有连接数,超出了MySQL中的最大连接数,此时再出现新连接时会出异常。
  • ②客户端数据库连接池与MySQL版本不匹配,或超时时间过小,也可能导致出现连接中断。
  • MySQL、Java程序所部署的机器不位于同一个网段,两台机器之间网络存在通信故障。
  • ④部署MySQL的机器资源被耗尽,如CPU、硬盘过高,导致MySQL没有资源分配给新连接。

当数据库出现连接异常时,基本上就是因为上述四种原因导致的,对于第一二种情况比较简单,基本上问题出在数据库和客户端连接池的配置上面,首先排查一下两者的参数,然后适当调整参数即可。

这里主要说一下后面两种情况,这两种情况比较特殊,当数据库连接出现异常时,如果是由于这两种情况导致的,基本上很难让人摸到头脑。

  • MySQL、Java程序所部署的机器不位于同一个网段,两台机器之间网络存在通信故障。

这种情况,问题一般都出在交换机上面,由于Java程序和数据库两者不在同一个网段,所以相互之间通信需要利用交换机来完成,但默认情况下,交换机和防火墙一般会认为时间超过3~5分钟的连接是不正常的,因此就会中断相应的连接,而有些低版本的数据库连接池,如Druid只会在获取连接时检测连接是否有效,此时就会出现一个问题:

交换机把两个网段之间的长连接嘎了,但是Druid因为只在最开始检测了一次,后续不会继续检测连接是否有效,所以会认为获取连接后是一直有效的,最终就导致了数据库连接出现异常(后续高版本的Druid修复了该问题,可以配置间隔一段时间检测一次连接)。

一般如果是由于网络导致出现连接异常,通常排查方向如下:

  • 检测防火墙与安全组的端口是否开放,或与外网机器是否做了端口映射。
  • 检查部署MySQL的服务器白名单,以及登录的用户IP限制,可能是IP不在白名单范围内。
  • 如果整个系统各节点部署的网段不同,检查各网段之间交换机的连接超时时间是多少。
  • 检查不同网段之间的网络带宽大小,以及具体的带宽使用情况,有时因带宽占满也会出现问题。
  • 如果用了MyCat、MySQL-Proxy这类代理中间件,记得检查中间件的白名单、超时时间配置。

一般来说上述各方面都不存在问题,基本上连接异常应该不是由于网络导致的问题,要做更为细致的排查,可以在请求链路的各节点上,使用网络抓包工具,抓取对应的网络包,看看网络包是否能够抵达每个节点,如果每个节点的出入站都正常,此时就可以排除掉网络方面的原因。

  • ④部署MySQL的机器资源被耗尽,如CPU、硬盘过高,导致MySQL没有资源分配给新连接。

这种情况更为特殊,网络正常、连接数未满、连接未超时、数据库和客户端连接池配置正常....,在一切正常的情况下,有时候照样出现连接不上MySQL的情况咋整呢?在这种情况下基本上会陷入僵局,这时你可以去查一下部署MySQL服务的机器,其硬件的使用情况,如CPU、内存、磁盘等,如果其中一项达到了100%,这时就能够确定问题了!

因为数据库连接的本质,在MySQL内部是一条条的工作线程,要牢记的一点是:操作系统在创建一条线程时,都需要为其分配相关的资源,如果一个客户端尝试与数据库建立新的连接时,此刻正好有一个数据库连接在执行某个操作,导致CPU被打满,这时就会由于没有资源来创建新的线程,因此会向客户端直接返回连接异常的信息。

如果出现这样的问题,就需要先找到导致资源耗尽的连接/线程,然后找到它当时正在执行的SQL语句,最后需要优化相应的SQL语句后才能彻底根治问题。

OK~,到这里就将可能造成数据库连接异常的各方面原因,就做了简单的讲解,大家如果在线上遇到这些情况下时,可以遵循这些方法去做排除,最终也能够让你定位到出现的原因,并着手解决对应的问题。

4.2、MySQL死锁频发

对于死锁问题,其实在之前《MySQL事务与锁原理篇-死锁》中聊到过,MySQL内部其实会默认开启死锁检测算法,当运行期间出现死锁问题时,会主动介入并解除死锁,但要记住:虽然数据库能够主动介入解除死锁问题,但这种方法治标不治本!为啥治标不治本呢?因为死锁现象是由于业务不合理造成的,能出现一次死锁问题,自然后续也可能会多次出现,因此优化业务才是最好的选择,这样才能根治死锁问题。

从业务上解决死锁问题,首先咱们得先定准定位到产生死锁的SQL语句,对于这点需要在MySQL内部会有一个日志,来记录着它自身捕获到的死锁,可以通过如下命令查看:

  • SHOW ENGINE INNODB STATUS\G;:查看InnoDB存储引擎的运行状态日志。

当出现死锁时,MySQL会将死锁对应的信息记录到该日志中,但这个日志会记录着InnoDB运行期间的所有状态日志,因此输入之后,要先找到LATEST DETECTED DEADLOCK这块区域的日志:
死锁日志
上述这个死锁案例来自于《MySQL事务与锁原理篇-死锁现象》章节,当咱们手动模拟生产一个死锁后,在InnoDB的日志中就能够找到相应的死锁日志,这里为了方便观察则只列出了死锁的日志,其实InnoDB的运行时日志内容包含很多方面。

在上面的日志中,基本上已经写的很清楚了,在2022-11-04 23:04:34这个时间点上,检测到了一个死锁出现,该死锁主要由两个事务产生,SQL如下:

  • (1):UPDATE zz_account SET balance = balance + 888 WHERE user_name = "熊猫";
  • (2):UPDATE zz_account SET balance = balance + 666 WHERE user_name = "竹子";

在事务信息除开列出了导致死锁的SQL语句外,还给出了两个事务对应的线程ID、登录的用户和IP、事务的存活时间与系统线程ID、持有的锁信息与等待的锁信息.....。

除开两个发生死锁的事务信息外,倒数第二段落还给出了两个事务在哪个锁上产生了冲突,以上述日志为例,发生死锁冲突的地点位于db_zhuzi库中zz_account表的主键上,两个事务都在尝试获取对方持有的X排他锁,后面还给出了具体的页位置、内存地址....。

最后一条信息中,给出了MySQL介入解除死锁的方案,也就是回滚了事务(2)的操作,强制结束了事务(2)并释放了其持有的锁资源,从而能够让事务(1)继续运行。当然,如果你对于MySQL为何会选择回滚事务(2)比较感兴趣,可以参考之前的《MySQL事务与锁原理篇-死锁检测的wait-for graph算法》

经过查看上述日志后,其实MySQL已经为我们记录了产生死锁的事务、线程、SQL、时间、地点等各类信息,因此想要彻底解决死锁问题的方案也很简单了,根据日志中给出的信息,去找到执行相应SQL的业务和库表,优化SQL语句的执行顺序,或SQL的执行逻辑,从而避免死锁产生即可。

最后要注意:如果是一些偶发类的死锁问题,也就是很少出现的死锁现象,其实不解决也行,毕竟只有在一些特殊场景下才有可能触发,重点是要关注死锁日志中那些频繁出现的死锁问题,也就是多次死锁时,每次死锁出现的库、表、字段都相同,这种情况时需要额外重视并着手解决。

4.3、服务器CPU100%

对于CPU100%甚至更高的问题,其实排查起来也比较简单,办法基本上都相同,在之前聊《JVM线上排查》的时候,也聊到过如何排查这个问题,排查的思路其实很简单:

  • 先找到CPU过高的服务器。
  • 然后在其中定位到具体的进程。
  • 再定位到进程中具体的线程。
  • 再查看线程正在执行的代码逻辑。
  • 最后从代码层面着手优化掉即可。

上述这个工作具体该如何完成呢?下面一起来实操一下。

首先通过top指令查看系统后台的进程状态:

[root@localhost ~]# top
top - 14:09:20 up 2 days, 16 min,  3 users,  load average: 0.45, 0.15, 0.11
Tasks:  98 total,   1 running,  97 sleeping,   0 stopped,   0 zombie
%Cpu(s):100.0 us,  0.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   997956 total,   286560 free,   126120 used,   585276 buff/cache
KiB Swap:  2097148 total,  2096372 free,      776 used.   626532 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 76661 root      20   0 2249432  25708  11592 S 99.9  2.6   0:28.32 mysql
   636 root      20   0  298936   6188   4836 S  0.3  0.6   3:39.52 vmtoolsd
     1 root      20   0   46032   5956   3492 S  0.0  0.6   0:04.27 systemd
     2 root      20   0       0      0      0 S  0.0  0.0   0:00.07 kthreadd
     3 root      20   0       0      0      0 S  0.0  0.0   0:04.21 ksoftirqd/0
     5 root       0 -20       0      0      0 S  0.0  0.0   0:00.00 kworker/0:0H
     7 root      rt   0       0      0      0 S  0.0  0.0   0:00.00 migration/0
     8 root      20   0       0      0      0 S  0.0  0.0   0:00.00 rcu_bh
     9 root      20   0       0      0      0 S  0.0  0.0   0:11.97 rcu_sched
     .......

从如上结果中不难发现,PID76661MySQL进程对CPU的占用率达到99.9%,此时就可以确定,机器的CPU利用率飙升是由于该进程引起的。

此时可以再通过top -Hp [PID]命令查看该进程中CPU占用率最高的线程:

[root@localhost ~]# top -Hp 76661
.....省略系统资源相关的信息......
   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 77935 root      20   0 2249432  26496  11560 R 99.9  2.7   3:43.95 mysql
 77915 root      20   0 2249432  26496  11560 S  0.0  2.7   0:00.00 mysql
 77916 root      20   0 2249432  26496  11560 S  0.0  2.7   0:00.08 mysql
 77917 root      20   0 2249432  26496  11560 S  0.0  2.7   0:00.00 mysql
 77918 root      20   0 2249432  26496  11560 S  0.0  2.7   0:00.00 mysql
 77919 root      20   0 2249432  26496  11560 S  0.0  2.7   0:00.00 mysql
 .......

top -Hp 76661命令的执行结果中可以看出:其他线程均为休眠状态,并未持有CPU资源,而PID为77935的线程对CPU资源的占用率却高达99.9%

到此时,导致CPU利用率飙升的“罪魁祸首”已经浮现水面,但此时问题来了!在如果这里是Java程序,此时可以先将该线程的PID转换为16进制的值,然后进一步排查日志信息来确定具体线程执行的业务方法。但此时这里是MySQL程序,咱们得到了操作系统层面的线程ID后,如何根据这个IDMySQL中找到对应的线程呢?

4.3.1、查看OS线程ID与MySQL线程ID关系(MySQL5.7及以上)

MySQL5.7及以上的版本中,MySQL会自带一个名为performance_schema的库,在其中有一张名为threads的表,其中表中有一个thread_os_id字段,其中会保存每个连接/工作线程与操作系统线程之间的关系(在5.7以下的版本是隐式的,存在于MySQL内部无法查看)。

-- 先连接MySQL数据库
mysql -uroot -p
Enter password: ***

-- 进入 performance_schema 库
use performance_schema;

-- 查询 threads 表(竖排输出)
SELECT * FROM threads\G;

执行上述命令后,会输出所有已创建的线程,查询之后的最终结果如下:
MySQL~OS关系
从上述中可以明显看出MySQL线程和OS线程之间的关系,当通过前面的top指令拿到CPU利用率最高的线程ID后,在再这里找到与之对应的MySQL线程,同时也能够看到此线程正在执行的SQL语句,最后优化对应SQL语句的逻辑即可。

4.3.2、查看OS线程ID与MySQL线程ID关系(MySQL5.6及以下)

上面讲了MySQL5.7及以上版本的排查方式,但有些小伙伴可能会存在困扰:我的MySQL如果是MySQL5.7版本以下的呢?其实也不是不能排查,只是有些许麻烦!下面一起来过一过~

还记得之前排查死锁时用到的SHOW ENGINE INNODB STATUS\G;命令嘛?执行之后可以查看InnoDB引擎的运行时日志,在里面有一个TRANSACTIONS板块,统计着所有存活事务的信息,此时也可以从中得到相应的OS线程、MySQL线程的映射关系,如下:

MySQL-OS线程
但是这种方式仅能够获取到OS线程、MySQL线程之间的映射关系,无法获取到对应线程/连接正在执行的SQL语句,此时如果线程还在运行,则可以通过show processlist;查询,如下:
查询执行SQL
但这种方式只能看到正在执行的SQL语句,无法查询到最近执行过的语句,所以这种方式仅适用于:线上SQL还在继续跑的情况,如果SQL已经执行结果,其实CPU的占用率也会下降,这类偶发性的CPU占用过高也无需排查,我们要优化的是那些一直导致CPU过高的SQL语句。

同时再补充一句,SHOW ENGINE INNODB STATUS;命令只能显示1MB的数据,如果想要查看完整的InnoDB运行期日志,可以找到innodb_status.[pid]日志文件,MySQL会每隔15s就刷写一次InnoDB的运行日志进去,其中可以查看到完整的运行时日志。

4.3、CPU占用率过高排查总结

其实排查这类问题不难,主要是得先定位到对应的线程,然后再找出OS线程对应的MySQL线程,找到对应的MySQL线程后,再找到其正在执行的SQL语句,因为线程是执行这条语句才导致占用高额CPU资源的,因此最后只需要把SQL的逻辑调整合理后,就能够彻底解决CPU占用过高的问题。

4.4、MySQL磁盘100%

所谓的磁盘100%不是指磁盘空间被用光,而是指磁盘IO达到100%利用率,这种情况下一般会导致其他读写操作都被阻塞,因为操作系统中的IO总线会被占满,无法让给其他线程来读写数据,先来总结一下出现磁盘IO占用过高的原因:

  • ①突然大批量变更库中数据,需要执行大量写入操作,如主从数据同步时就会出现这个问题。
  • MySQL处理的整体并发过高,磁盘I/O频率跟不上,比如是机械硬盘材质,读写速率过慢。
  • ③内存中的BufferPool缓冲池过小,大量读写操作需要落入磁盘处理,导致磁盘利用率过高。
  • ④频繁创建和销毁临时表,导致内存无法存储临时表数据,因而转到磁盘存储,导致磁盘飙升。
  • ⑤执行某些SQL时从磁盘加载海量数据,如超12张表的联查,并每张表数据较大,最终导致IO打满。
  • ⑥日志刷盘频率过高,其实这条是①、②的附带情况,毕竟日志的刷盘频率,跟整体并发直接挂钩。

一般情况下,磁盘IO利用率居高不下,甚至超过100%,基本上是由于上述几个原因造成的,当需要排查磁盘IO占用率过高的问题时,可以先通过iotop工具找到磁盘IO开销最大的线程,然后利用pstack工具查看其堆栈信息,从堆栈信息来判断具体是啥原因导致的,如果是并发过高,则需要优化整体架构。如果是执行SQL加载数据过大,需要优化SQL语句......

磁盘利用率过高的问题其实也比较好解决,方案如下:

  • ①如果磁盘不是SSD材质,请先将磁盘升级成固态硬盘,MySQLSSD硬盘做了特殊优化。
  • ②在项目中记得引入Redis降低读压力,引入MQ对写操作做流量削峰。
  • ③调大内存中BufferPool缓冲池的大小,最好设置成机器内存的70~75%左右。
  • ④撰写SQL语句时尽量减少多张大表联查,不要频繁的使用和销毁临时表。

基本上把上述工作都做好后,线上也不会出现磁盘IO占用过高的问题,对于前面说到的:利用iotop、pstack工具排查的过程,就不再做实际演示了,其过程与前面排查CPU占用率过高的步骤类似,大家学习iotop、pstack两个工具的用法后,其实实操起来也十分简单。

五、MySQL线上排查篇总结

   本篇中对于MySQL开发过程中、线上环境中会出现的各类疑难杂症,以及具体该如何解决与排查的方法做了阐述,在本章中分了开发中的Bug、慢查询的排查、MySQL的故障这三个方向,然后再对每个方向做了具体描述,但有人或许会问我:为啥不写如何解决内存相关的问题呢

相对来说,MySQL中除开Memory引擎外,其他引擎都是基于磁盘的,虽然InnoDB将内存开发到了极致,但最终还是基于磁盘的,InnoDB对内存的占用最大不会超出BufferPool缓冲池的大小,因此MySQL自然也不存在所谓的OOM内存溢出、内存占用过高等问题。

同时大家是否还记得在《MySQL日志篇》中聊到的Error-log错误日志呢?其实当MySQL出现宕机、死锁、磁盘故障等各类问题时,都会将对应的错误信息记录到日志,因此当你排查问题没有头绪时,也可以参考错误日志中给出的信息,以此来定位问题的发生点,并着手解决。

《MySQL优化篇》《SQL调优篇》以及当前的《MySQL排查篇》都是基于个人知识和实际经验中的总结沉淀,如果各位小伙伴认为有误区的地方可以随时留言指正!同时,如果你感觉文章对你有所启发,请不要吝啬手中免费的点赞^~^,诸位不经意的点赞,对我而言却是写文时不小的鼓励,在此先万分感谢!