作为运维人员，可能经常碰到”应用慢了”、”数据库慢了”，需要定位、排查、解决，因为技术栈不同，不可能套用某一个通用的方案，但是排查路径上，有些是可以相互借鉴的，写过一些历史文章可以参考，

爱可生开源社区的这篇文章《技术分享 | 客户说 insert 慢，我该怎么办》讲了一个MySQL中insert慢的问题排查和解决过程，借鉴一下。

前段时间客户反馈有insert慢，查看slow.log ，发现确实慢，而且不光他慢，别的也慢，(客户只关注客户的重点，运维要全面的进行分析)。

排查过程：

(1) 先整体观察某一天或这某个时间段内慢SQL的记录情况，重点观察慢SQL记录时间点、SQL类型。

(2) 如果是insert之类的SQL慢，怀疑的维度大概是：磁盘IO、锁、半同步复制。

(3) 如果有批量慢SQL的情况，重点关注select，用以排查半同步复制。

[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"<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />time|sql_count<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T00:05:56|63<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T00:27:37|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T00:34:58|31<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T00:49:22|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T00:56:41|61<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T01:11:04|64<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T01:32:50|63<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T01:40:06|60<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T01:54:32|59<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:01:47|58<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:16:16|62<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:23:28|58<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:37:58|58<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:45:10|54<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T02:59:40|44<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T03:06:52|55<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T03:21:24|55<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T03:28:35|59<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T03:43:08|27<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T03:50:17|27<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T04:04:53|58<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T04:11:59|48<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T04:26:34|60<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T04:33:41|28<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T04:48:19|24<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T05:10:04|59<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T05:17:07|60<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T05:31:47|45<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T05:38:48|61<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T05:53:30|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:00:30|63<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:15:16|64<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:22:14|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:37:01|66<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:43:55|57<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T06:58:45|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T07:05:39|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T07:20:28|36<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T07:42:10|21<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T07:49:03|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:03:53|35<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:10:47|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:25:37|35<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:32:28|25<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:47:23|51<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T08:54:09|36<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:09:07|83<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:09:13|1<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:15:51|74<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:30:49|36<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:37:35|33<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:52:34|86<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T09:59:17|21<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T10:14:16|81<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T10:21:01|33<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T10:36:02|81<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T10:42:44|72<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T10:57:45|84<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T11:04:27|20<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T11:19:25|17<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T11:41:10|20<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T11:47:50|17<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:02:52|70<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:09:34|18<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:24:39|65<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:31:19|67<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:46:20|66<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T12:53:05|18<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T13:08:09|67<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T13:14:50|31<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T13:29:56|66<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />2022-08-30T13:36:33|66</p></pre><pre data-tool="mdnice编辑器" style="margin-top: 10px;margin-bottom: 10px;outline: 0px;max-width: 100%;border-radius: 5px;box-shadow: rgba(0, 0, 0, 0.55) 0px 2px 10px;box-sizing: border-box !important;overflow-wrap: break-word !important;"><p style="padding: 15px 16px 16px;outline: 0px;max-width: 100%;overflow-x: auto;color: rgb(171, 178, 191);display: -webkit-box;font-family: &quot;Operator Mono&quot;, Consolas, Monaco, Menlo, monospace;font-size: 12px;background: rgb(40, 44, 52);border-radius: 5px;margin-bottom: 0px;line-height: 1.5em;box-sizing: border-box !important;overflow-wrap: break-word !important;">[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

从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.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 5301ms to flush 121 and evict 0 pages
2022-08-30T00:27:37.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4028ms to flush 120 and evict 0 pages
2022-08-30T00:49:22.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4992ms to flush 24 and evict 0 pages
2022-08-30T01:11:04.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4947ms to flush 16 and evict 0 pages
2022-08-30T01:32:50.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6136ms to flush 112 and evict 0 pages
2022-08-30T01:54:32.+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.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4796ms to flush 16 and evict 0 pages
2022-08-30T02:59:40.+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.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4381ms to flush 16 and evict 0 pages
2022-08-30T06:15:16.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4380ms to flush 18 and evict 0 pages
2022-08-30T06:37:01.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7198ms to flush 24 and evict 0 pages
2022-08-30T06:58:45.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6052ms to flush 120 and evict 0 pages
2022-08-30T07:20:28.078480+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 5189ms to flush 26 and evict 0 pages
2022-08-30T07:42:10.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7349ms to flush 120 and evict 0 pages
2022-08-30T08:03:53.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7035ms to flush 40 and evict 0 pages
2022-08-30T08:25:37.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6982ms to flush 120 and evict 0 pages
2022-08-30T08:47:23.035222+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10264ms to flush 137 and evict 0 pages
2022-08-30T09:09:07.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8538ms to flush 136 and evict 0 pages
2022-08-30T09:30:49.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6570ms to flush 121 and evict 0 pages
2022-08-30T09:52:34.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8821ms to flush 120 and evict 0 pages
2022-08-30T10:14:16.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6419ms to flush 128 and evict 0 pages
2022-08-30T10:36:02.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7444ms to flush 128 and evict 0 pages
2022-08-30T10:57:45.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7926ms to flush 144 and evict 0 pages
2022-08-30T11:19:25.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4146ms to flush 11 and evict 0 pages
2022-08-30T11:41:10.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 5599ms to flush 9 and evict 0 pages
2022-08-30T12:02:52.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 6495ms to flush 10 and evict 0 pages
2022-08-30T12:24:39.010150+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8246ms to flush 10 and evict 0 pages
2022-08-30T12:46:20.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 4433ms to flush 11 and evict 0 pages
2022-08-30T13:08:09.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10607ms to flush 123 and evict 0 pages
2022-08-30T13:29:56.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 11156ms to flush 24 and evict 0 pages
2022-08-30T13:51:44.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12464ms to flush 19 and evict 0 pages
2022-08-30T14:13:30.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9677ms to flush 17 and evict 0 pages
2022-08-30T14:35:16.044102+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 11250ms to flush 185 and evict 0 pages
2022-08-30T14:57:01.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10031ms to flush 113 and evict 0 pages
2022-08-30T15:18:46.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 11545ms to flush 104 and evict 0 pages
2022-08-30T15:40:31.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9504ms to flush 10 and evict 0 pages
2022-08-30T16:02:18.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10029ms to flush 9 and evict 0 pages
2022-08-30T16:24:00.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 7106ms to flush 13 and evict 0 pages
2022-08-30T16:45:48.000669+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10248ms to flush 10 and evict 0 pages
2022-08-30T17:07:32.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10406ms to flush 24 and evict 0 pages
2022-08-30T17:29:19.041210+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10477ms to flush 24 and evict 0 pages
2022-08-30T17:51:06.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12039ms to flush 104 and evict 0 pages
2022-08-30T18:12:52.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10351ms to flush 16 and evict 0 pages
2022-08-30T18:34:40.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12176ms to flush 106 and evict 0 pages
2022-08-30T18:56:27.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8591ms to flush 25 and evict 0 pages
2022-08-30T19:18:12.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9778ms to flush 17 and evict 0 pages
2022-08-30T19:39:59.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10982ms to flush 17 and evict 0 pages
2022-08-30T20:01:43.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8925ms to flush 16 and evict 0 pages
2022-08-30T20:23:31.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12138ms to flush 18 and evict 0 pages
2022-08-30T20:45:16.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9932ms to flush 27 and evict 0 pages
2022-08-30T21:07:03.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10763ms to flush 25 and evict 0 pages
2022-08-30T21:28:48.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9139ms to flush 18 and evict 0 pages
2022-08-30T21:50:35.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10696ms to flush 16 and evict 0 pages
2022-08-30T22:12:20.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9216ms to flush 16 and evict 0 pages
2022-08-30T22:34:05.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 8703ms to flush 18 and evict 0 pages
2022-08-30T22:55:50.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9042ms to flush 16 and evict 0 pages
2022-08-30T23:17:36.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10405ms to flush 18 and evict 0 pages
2022-08-30T23:39:22.+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10440ms to flush 16 and evict 0 pages

分析部分时间点发现磁盘IO确实存在异常情况，跟mysql-error.log中flush的时间点完全重合。

//磁盘io监控脚本
#!/bin/bash
while sleep 1;
do
echo “#date '+%F %H:%M:%S'” &gt;&gt; /app/monitor/diskmoni\((date "+%Y%m%d").log<br style="outline: 0px;max-width: 100%;box-sizing: border-box !important;overflow-wrap: break-word !important;" />sar -d -p 1 10 &gt;&gt; /app/monitor/diskmoni\)(date “+%Y%m%d”).log
done

讯享网

4. 其他时间点的慢SQL分析

讯享网

[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> 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)
 
mysql> show variables like ‘rpl_semi_sync_slave_trace_level’;
+———————————+——-+
| Variable_name | Value |
+———————————+——-+
| rpl_semi_sync_slave_trace_level | 16 |
+———————————+——-+
1 row in set (0.04 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.+08:00 23176 [Note] [MY-011133] [Repl] ActiveTranx:insert_tranx_node: insert (mysql-bin.003497, ) in entry(4191).
2022-08-30T11:04:21.+08:00 655 [Note] [MY-011134] [Repl] ActiveTranx::is_tranx_end_pos: probe (mysql-bin.003497, ) in entry(4191).
2022-08-30T11:04:21.+08:00 655 [Note] [MY-011158] [Repl] ReplSemiSyncMaster::updateSyncHeader: server(11111), (mysql-bin.003497, ) sync(1), repl(1).
2022-08-30T11:04:27.+08:00 0 [Note] [MY-011140] [Repl] ReplSemiSyncMaster::reportReplyPacket: Got reply(mysql-bin.003497, ) from server 11111.
2022-08-30T11:04:27.+08:00 0 [Note] [MY-011146] [Repl] ReplSemiSyncMaster::reportReplyBinlog: Got reply at (mysql-bin.003497, ).

查看这段时间主库跟从库的网络监控发现网络没有太大问题，

讯享网[root@big hao]# grep -A 20 “2022-08-30 11:04:” ping.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异常所导致，

因此，

(1) 慢日志中被大量记录的SQL是commit，其次是update和insert，这类SQL相对比较吃IO。

(2) 如果一批SQL中带有简单的select语句，大概率跟半同步复制关系不大。

(3) 慢日志中记录了show master status语句，大家可以猜一猜他为什么也会慢呢？

小贴士，

大多数监控平台对于磁盘IO监控数据采集的频率为15s/次，此时查看监控平台很难看到磁盘的异常情况，所以本次通过手工部署监控脚本来检测磁盘IO情况。

如果您认为这篇文章有些帮助，还请不吝点下文章末尾的”点赞”和”在看”，或者直接转发pyq，

近期更新的文章：

《MySQL无监听端口的一个场景》

《MySQL8.0错误日志Error log介绍》

《sqlplus答疑解惑》

《MySQL的auto-rehash自动补全功能》

《MySQL借助于LIMIT和OFFSET实现的高性能分页功能》

近期的热文：

《”红警”游戏开源代码带给我们的震撼》

文章分类和索引：

《公众号1000篇文章分类和索引 》