MySQL 数据库响应延迟问题分析一例（例2）

Posted 2021-12-05 渔夫数据库笔记

1.版本

数据版本：

阿里云 PolarDB（目前使用的版本是基于 mysql 8.0.13 研发）

2.问题描述

业务侧报告说，每天早上他们有个表insert操作都会有响应时间异常的现象(响应时间能达到3s)。

3.问题分析

3.1 业务侧/binlog 日志分析

业务侧日志如下截图：

 #上图中2021-11-02 09:18:36:725 是业务侧收到数据库响应的时间

# 上图是业务侧对应的insert sql 在binlog中解析出来的记录。我们看到该sql确实执行了3s，所以可以确认是sql执行慢了，导致业务侧收到响应出现延迟，下面来看看一个简单的insert(插入一条记录)，为什么耗时3s才执行完成

3.2 阿里云协助分析

因为是用的是阿里云的产品，很多信息都看不到，请求阿里云协助分析问题。应阿里云侧要求需要打开sql洞察功能(注，这个功能开启要收费。这里小吐槽一下，这个功能是很好，但是作为客户，我们花钱开通以后只是看到了部分数据，只有他们自己的后台工程师才有权限看到更多更全面的数据)

先说阿里云跟踪几天后，给出的结论，他们在后台观察到，在出问题的时间点，总是伴随着一些执行批量数据插入的sql(单条sql 插入五万多条记录)。这些大批量的insert导致那些后续那些单条insert在获取 binlog 相关 mutex锁时出现等待，从而导致那些简单sql执行时间异常。阿里云侧给出的说明截图如下：

 

 3.3 根据阿里云的结论对binlog进行统计分析

grep -i "exec_time=" mysql-bin.026572.txt|grep "211102  9:18:33"

#统计业务侧出现响应延迟的对应sql执行时间点下，binlog中sql操作的执行时间，我们看到在2021-11-02 09:18:33.xxx 时间点之后所有所有09:18:33 这个时间点binlog中sql的执行时间都是3s。继续统计09:18:34 和 09:18:35 两个时间binlog中sql执行时间发现 09:18:34 所有的sql执行时间都是2s，09:18:35 binlog中所有sql执行时间都是1s，09:18:36 恢复正常。所以影响时间在3s左右。