作者:张昊
DBA,主要负责MySQL故障处理、DMP擅长产品支持MySQL,喜欢打球~唱歌~。
本文来源:原稿
*爱可生开源社区生产,原创内容未经授权不得随意使用。请联系小编,注明来源。
本文更注重分析过程,细节可能不足。
唠嗑环节前段时间客户反馈有 insert 慢,查看 slow.log ,发现真的很慢,不仅慢,其他也慢;(客户只关注客户的重点,综合分析运维)。
以前也遇到过类似的问题,从领导那里求真经,下面简单分享一下真经的内容:
首先观察一天或一段时间内的整体观察sql记录,重点慢慢观察sql记录时间点,sql类型;如果是insert之类的sql慢,怀疑的维度大概是:磁盘io、锁,半同步复制;如果批量慢;sql的情况,重点关注select,用于检查半同步复制。开始实战1. 宏观统计 slow.log ,统计发现慢 sql 呈现批量慢的情况记录到 slow.log 的 sql 有很多类型,有 select 、insert 、delete 、update 、commit 和 show 开头的管理 sql 。
[root@big hao]# less slow.log |grep "# Tim"|awk -F "." ' rint $1}'|termsql -0 "select COL2 time,COUNT(COL2) sql_count from tbl group by COL2"time|sql_count2022-08-30T00:05:56|632022-08-30T00:27:37|652022-08-30T00:34:58|312022-08-30T00:49:22|652022-08-30T00:56:41|612022-08-30T01:11:04|642022-08-30T01:32:50|632022-08-30T01:40:06|602022-08-30T01:54:32|592022-08-30T02:01:47|582022-08-30T02:16:16|622022-08-30T02:23:28|582022-08-30T02:37:58|582022-08-30T02:45:10|542022-08-30T02:59:40|442022-08-30T03:06:52|552022-08-30T03:21:24|552022-08-30T03:28:35|592022-08-30T03:43:08|272022-08-30T03:50:17|272022-08-30T04:04:53|582022-08-30T04:11:59|482022-08-30T04:26:34|602022-08-30T04:33:41|282022-08-30T04:48:19|242022-08-30T05:10:04|592022-08-30T05:17:07|602022-08-30T05:31:47|452022-08-30T05:38:48|612022-08-30T05:53:30|652022-08-30T06:00:30|632022-08-30T06:15:16|642022-08-30T06:22:14|652022-08-30T06:37:01|662022-08-30T06:43:55|572022-08-30T06:58:45|652022-08-30T07:05:39|652022-08-30T07:20:28|362022-08-30T07:42:10|212022-08-30T07:49:03|652022-08-30T08:03:53|352022-08-30T08:10:47|652022-08-30T08:25:37|352022-08-30T08:32:28|252022-08-30T08:47:23|512022-08-30T08:54:09|362022-08-30T09:09:07|832022-08-30T09:09:13|12022-08-30T09:15:51|742022-08-30T09:30:49|362022-08-30T09:37:35|332022-08-30T09:52:34|862022-08-30T09:59:17|212022-08-30T10:14:16|812022-08-30T10:21:01|332022-08-30T10:36:02|812022-08-30T10:42:44|722022-08-30T10:57:45|842022-08-30T11:04:27|202022-08-30T11:19:25|172022-08-30T11:41:10|202022-08-30T11:47:50|172022-08-30T12:02:52|702022-08-30T12:09:34|182022-08-30T12:24:39|652022-08-30T12:31:19|672022-08-30T12:46:20|662022-08-30T12:53:05|182022-08-30T13:08:09|672022-08-30T13:14:50|312022-08-30T13:29:56|662022-08-30T13:36:33|66
[root@big hao]# less slow.log |grep "# Time" -A 6 |egrep -i "insert|delete|update|select|commit|show" |awk ' rint $1}'|sed -e 's/;/ /g' |termsql -0 "select COL0 sql_stat,count(COL0) sql_count from tbl group by COL0"sql_stat|sql_countCOMMIT|59DELETE|11INSERT|321SELECT|18UPDATE|6commit|2627select|16show|17update|628
2. 结合 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 flush2022-08-30T00:05:56.685140 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 5301ms to flush 121 and evict 0 pages2022-08-30T00:27:37.800463 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4028ms to flush 120 and evict 0 pages2022-08-30T00:49:22.874045 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4992ms to flush 24 and evict 0 pages2022-08-30T01:11:04.900200 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4947ms to flush 16 and evict 0 pages2022-08-30T01:32:50.117427 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 6136ms to flush 112 and evict 0 pages2022-08-30T01:54:32.106385 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4912ms to flush 18 and evict 0 pages2022-08-30T02:16:16.060394 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4870ms to flush 16 and evict 0 pages2022-08-30T02:37:58.933258 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4796ms to flush 16 and evict 0 pages2022-08-30T02:59:40.755206 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4741ms to flush 24 and evict 0 pages2022-08-30T03:43:08.053816 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4230ms to flush 105 and evict 0 pages2022-08-30T04:04:53.504756 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4381ms to flush 16 and evict 0 pages2022-08-30T06:15:16.414777 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 4380ms to flush 18 and evict 0 pages2022-08-30T06:37:01.679180 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 7198ms to flush 24 and evict 0 pages2022-08-30T06:58:45.807908 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 6052ms to flush 120 and evict 0 pages2022-08-30T07:20:28.078480 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 5189ms to flush 26 and evict 0 pages2022-08-30T07:42:10.509536 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 7349ms to flush 120 and evict 0 pages2022-08-30T08:03:53.622772 08:00 0[Note][MY-011953][InnoDB]Page cleaner took 7035ms to flush 40 and evict 0
p