.mysql insert慢排查

原创张鹏 2022-09-26

474

1192.mysql insert慢排查

作者：张昊DBA，主要负责MySQL故障处理、DMP产品支持，擅长MySQL，喜欢打球_唱歌。
前段时间客户反馈有 insert 慢，查看 slow.log ，发现确实慢，不光它慢，别的也慢；(客户只关注客户的重点，运维要全面的进行分析)。
之前也遇到过类似问题，从领导那里求取真经，下面给大家简单分享下真经内容：
先整体观察某一天或这某个时间段内慢sql的记录情况，重点观察慢sql记录时间点、sql类型；
如果是insert之类的sql慢，怀疑的维度大概是：磁盘io、锁、半同步复制；
如果有批量慢sql的情况，重点关注select，用以排查半同步复制。
开始实战

宏观统计 slow.log ，经过统计发现慢 sql 呈现出批量慢的情况
记录到 slow.log 的 sql 类型比较多，有 select 、insert 、delete 、update 、commit 和 show 开头的管理类 sql 。
[root@big hao]# less slow.log |grep “# Tim”|awk -F “.” ‘{print $1}’|termsql -0 “select COL2 time,COUNT(COL2) sql_count from tbl group by COL2”
time|sql_count
2022-08-30T00:05:56|63
2022-08-30T00:27:37|65
2022-08-30T00:34:58|31
2022-08-30T00:49:22|65
2022-08-30T00:56:41|61
2022-08-30T01:11:04|64
2022-08-30T01:32:50|63
2022-08-30T01:40:06|60
2022-08-30T01:54:32|59
2022-08-30T02:01:47|58
2022-08-30T02:16:16|62
2022-08-30T02:23:28|58
2022-08-30T02:37:58|58
2022-08-30T02:45:10|54
2022-08-30T02:59:40|44
2022-08-30T03:06:52|55
2022-08-30T03:21:24|55
2022-08-30T03:28:35|59
2022-08-30T03:43:08|27
2022-08-30T03:50:17|27
2022-08-30T04:04:53|58
2022-08-30T04:11:59|48
2022-08-30T04:26:34|60
[root@big hao]# less slow.log |grep “# Time” -A 6 |egrep -i “insert|delete|update|select|commit|show” |awk ‘{print $1}’|sed -e ‘s/;/ /g’ |termsql -0 “select COL0 sql_stat,count(COL0) sql_count from tbl group by COL0”
sql_stat|sql_count
COMMIT|59
DELETE|11
INSERT|321
SELECT|18
UPDATE|6
commit|2627
select|16
show|17
update|628
结合 mysql 的 error.log 中的 flush 信息进行排查
从 error.log 中看到有大量的 flush 信息输出，时间点跟 slow.log 高度重合；error.log 中的 flush 信息是表示这个时间点 mysql 在进行刷盘的时候效率比较低，进一步可以排查磁盘 io 情况。
[root@big hao]# less mysql-error.log |grep “2022-08-30T” |grep flush
2022-08-30T00:05:56.685140+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 5301ms to flush 121 and evict 0 pages
2022-08-30T00:27:37.800463+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4028ms to flush 120 and evict 0 pages
2022-08-30T00:49:22.874045+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4992ms to flush 24 and evict 0 pages
2022-08-30T01:11:04.900200+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4947ms to flush 16 and evict 0 pages
2022-08-30T01:32:50.117427+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6136ms to flush 112 and evict 0 pages
2022-08-30T01:54:32.106385+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4912ms to flush 18 and evict 0 pages
2022-08-30T02:16:16.060394+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4870ms to flush 16 and evict 0 pages
2022-08-30T02:37:58.933258+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4796ms to flush 16 and evict 0 pages
2022-08-30T02:59:40.755206+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4741ms to flush 24 and evict 0 pages
2022-08-30T03:43:08.053816+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4230ms to flush 105 and evict 0 pages
2022-08-30T04:04:53.504756+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4381ms to flush 16 and evict 0 pages
2022-08-30T06:15:16.414777+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4380ms to flush 18 and evict 0 pages
2022-08-30T06:37:01.679180+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7198ms to flush 24 and evict 0 pages
配置磁盘监控脚本，分析监控数据
分析部分时间点发现磁盘 io 确实存在异常情况，跟 mysql-error.log 中 flush 的时间点完全重合。
//磁盘io监控脚本
#!/bin/bash
while sleep 1;
do
echo “########date '+%F %H:%M:%S'” >> /app/monitor/diskmoni(date "+%Y%m%d").log sar -d -p 1 10 >> /app/monitor/diskmoni(date “+%Y%m%d”).log
done
其他时间点的慢sql分析
在 slow.log 中还有一些时间点也出现了大量的慢 sql ，这个时间点主库的磁盘 io 是正常的，例如 slow.log 中的“2022-08-30T11:04:27”，分析这个时间点的慢 sql ，首先没发现 select 语句，其次锁等待时间基本可以忽略，那么此时要考虑半同步复制机制的影响。
[root@big hao]# less slow.log |grep “2022-08-30T11:04:27” -A 6 |egrep -i “2022-08-30T11:04:27|insert|delete|update|select|commit|show” |sed -e ‘s/# Time:/ /g’|awk ‘{print $1,$2}’|awk ‘{print $1}’|awk -F ‘.’ ‘{print $1}’|termsql -0 “select COL0 ,count(COL0) count from tbl group by COL0”
COL0|count
2022-08-30T11:04:27|20
COMMIT;|1
DELETE|1
INSERT|5
update|13

[root@big hao]# less slow.log |grep “2022-08-30T11:04:27” -A 3 |grep “Lock_time”|awk ‘{print $4,$5,$8,$9}’
Lock_time: 0.000105 Rows_examined: 1
Lock_time: 0.000130 Rows_examined: 1
Lock_time: 0.000113 Rows_examined: 1
Lock_time: 0.000000 Rows_examined: 0
Lock_time: 0.000105 Rows_examined: 0
Lock_time: 0.000469 Rows_examined: 0
Lock_time: 0.000109 Rows_examined: 1
Lock_time: 0.000110 Rows_examined: 1
Lock_time: 0.000114 Rows_examined: 1
Lock_time: 0.000112 Rows_examined: 2
Lock_time: 0.000114 Rows_examined: 2
Lock_time: 0.000107 Rows_examined: 0
Lock_time: 0.000107 Rows_examined: 1
Lock_time: 0.000116 Rows_examined: 1
Lock_time: 0.000137 Rows_examined: 1
Lock_time: 0.000112 Rows_examined: 1
Lock_time: 0.000097 Rows_examined: 0
Lock_time: 0.000143 Rows_examined: 1
Lock_time: 0.000098 Rows_examined: 3
Lock_time: 0.000611 Rows_examined: 0
开启主库半同步复制的 strace 日志，开启步骤如下，开启之后会将半同步信息记录到 mysql-error.log 中，开启之后首先会占用大量磁盘空间，其次是占用磁盘 io ，所以生产环境最好不要长时间开启。
//开启半同步strace日志
mysql> show variables like ‘rpl_semi_sync_slave_trace_level’;
±--------------------------------±------+
| Variable_name | Value |
±--------------------------------±------+
| rpl_semi_sync_slave_trace_level | 32 |
±--------------------------------±------+
1 row in set (0.01 sec)

mysql> set global rpl_semi_sync_slave_trace_level = 16;
Query OK, 0 rows affected (0.00 sec)

//关闭半同步strace日志

mysql> set global rpl_semi_sync_slave_trace_level = 32;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like ‘rpl_semi_sync_slave_trace_level’;
±--------------------------------±------+
| Variable_name | Value |
±--------------------------------±------+
| rpl_semi_sync_slave_trace_level | 32 |
±--------------------------------±------+
1 row in set (0.01 sec)
查看半同步日志之前先分享两个日志标识：
ReplSemiSyncMaster::updateSyncHeader:主库更新packet头部标记位为Sync，紧接着就会发送binlog给从库；
ReplSemiSyncMaster::reportReplyPacket:主库接受到从库返回的ack信息，附带有log_file、log_pos、从库的server_id。

这两个标识之间的时间差可以理解为半同步复制机制对业务性能的主要影响，可以看到下面的日志中主库发送给从库 binlog 6s 之后才收到从库的ack信息；首先网络情况会影响半同步复制，其次从库的 io 能力也会影响半同步复制，因为当主库发送 binlog 给从库之后，从库要先将 binlog 写入自己的 relaylog 中然后再返回给主库 ack 。
//提取出的半同步部分日志
2022-08-30T11:04:21.919587+08:00 23176 [Note] [MY-011133] [Repl] ActiveTranx:insert_tranx_node: insert (mysql-bin.003497, 9432086) in entry(4191).
2022-08-30T11:04:21.920085+08:00 655 [Note] [MY-011134] [Repl] ActiveTranx::is_tranx_end_pos: probe (mysql-bin.003497, 9432086) in entry(4191).
2022-08-30T11:04:21.920102+08:00 655 [Note] [MY-011158] [Repl] ReplSemiSyncMaster::updateSyncHeader: server(11111), (mysql-bin.003497, 9432086) sync(1), repl(1).
2022-08-30T11:04:27.599408+08:00 0 [Note] [MY-011140] [Repl] ReplSemiSyncMaster::reportReplyPacket: Got reply(mysql-bin.003497, 9432086) from server 11111.
2022-08-30T11:04:27.599423+08:00 0 [Note] [MY-011146] [Repl] ReplSemiSyncMaster::reportReplyBinlog: Got reply at (mysql-bin.003497, 9432086).
查看这段时间主库跟从库的网络监控发现网络没有太大问题。
[root@big hao]# grep -A 20 “2022-08-30 11:04:” ping20220830.log
########2022-08-30 11:04:04
PING ... (...) 56(84) bytes of data.
64 bytes from ...: icmp_seq=1 ttl=64 time=0.050 ms
64 bytes from ...: icmp_seq=2 ttl=64 time=0.061 ms
64 bytes from ...: icmp_seq=3 ttl=64 time=0.044 ms
64 bytes from ...: icmp_seq=4 ttl=64 time=0.046 ms
64 bytes from ...: icmp_seq=5 ttl=64 time=0.057 ms
64 bytes from ...: icmp_seq=6 ttl=64 time=0.062 ms
64 bytes from ...: icmp_seq=7 ttl=64 time=0.067 ms
64 bytes from ...: icmp_seq=8 ttl=64 time=0.063 ms
64 bytes from ...: icmp_seq=9 ttl=64 time=0.057 ms
64 bytes from ...: icmp_seq=10 ttl=64 time=0.067 ms

— ... ping statistics —
10 packets transmitted, 10 received, 0% packet loss, time 9229ms
rtt min/avg/max/mdev = 0.044/0.057/0.067/0.010 ms
########2022-08-30 11:04:14
PING ... (...) 56(84) bytes of data.
64 bytes from ...: icmp_seq=1 ttl=64 time=0.057 ms
64 bytes from ...: icmp_seq=2 ttl=64 time=0.051 ms
64 bytes from ...: icmp_seq=3 ttl=64 time=0.059 ms
64 bytes from ...: icmp_seq=4 ttl=64 time=0.063 ms
64 bytes from ...: icmp_seq=5 ttl=64 time=0.070 ms
64 bytes from ...: icmp_seq=6 ttl=64 time=0.062 ms
64 bytes from ...: icmp_seq=7 ttl=64 time=0.069 ms
64 bytes from ...: icmp_seq=8 ttl=64 time=0.050 ms
64 bytes from ...: icmp_seq=9 ttl=64 time=0.049 ms
64 bytes from ...: icmp_seq=10 ttl=64 time=0.065 ms

— ... ping statistics —
10 packets transmitted, 10 received, 0% packet loss, time 9230ms
rtt min/avg/max/mdev = 0.049/0.059/0.070/0.010 ms
########2022-08-30 11:04:25
PING ... (...) 56(84) bytes of data.
64 bytes from ...: icmp_seq=1 ttl=64 time=0.057 ms
64 bytes from ...: icmp_seq=2 ttl=64 time=0.053 ms
64 bytes from ...: icmp_seq=3 ttl=64 time=0.045 ms
64 bytes from ...: icmp_seq=4 ttl=64 time=0.057 ms
64 bytes from ...: icmp_seq=5 ttl=64 time=0.063 ms
64 bytes from ...: icmp_seq=6 ttl=64 time=0.055 ms
64 bytes from ...: icmp_seq=7 ttl=64 time=0.061 ms
64 bytes from ...: icmp_seq=8 ttl=64 time=0.069 ms
64 bytes from ...: icmp_seq=9 ttl=64 time=0.062 ms
64 bytes from ...: icmp_seq=10 ttl=64 time=0.067 ms
查看从库磁盘 io 监控发现从库磁盘出现 io 异常，也就是说 slow.log 中其他时间点的慢 sql 是跟半同步复制有关系，但原因还是因为磁盘的 io 异常所导致。

总结
慢日志中被大量记录的sql是commit，其次是update和insert，这类sq相对比较吃io；
如果一批sql中带有简单的select语句，大概率跟半同步复制关系不大；
慢日志中记录了show master status语句，大家可以猜一猜它为什么也会慢呢？
小贴士
大多数监控平台对于磁盘io监控数据采集的频率为15s/次，此时查看监控平台很难看到磁盘的异常情况，所以本次通过手工部署监控脚本来检测磁盘io情况

墨力计划

「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」

关注作者

.mysql insert慢排查

评论