故障分析 | 如何通过 blktrace 排查磁盘异常？

爱可生开源社区

发布于 2023-08-18 20:37:03

8250

发布于 2023-08-18 20:37:03

文章被收录于专栏：爱可生开源社区

作者：张昊

DBA，主要负责 MySQL 故障处理、DMP 产品支持，擅长 MySQL。

本文来源：原创投稿

* 爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

1背景描述

客户业务反馈经常出现运行效率低的情况希望我们从数据库进行排查，之前已经定位到是磁盘问题，但是当时没有继续深入排查。详细背景：技术分享 | 客户说 insert 慢，我该怎么办

2日志分析

2.1 慢日志分析

发现 MySQL 慢日志中记录的慢日志是一批一批地被记录，并不是实时被记录。

[root@big hao]# less slow_back.log |grep "# Time: 2022-08-26T" | awk -F "." '{print $1}'|termsql -0 "select COL2 time,COUNT(COL2) sql_count from tbl group by COL2"
time|sql_count
2022-08-26T00:19:29|23
2022-08-26T00:34:58|14
2022-08-26T00:41:18|22
2022-08-26T00:56:41|20
...
...
2022-08-26T23:24:32|22
2022-08-26T23:32:53|19
2022-08-26T23:46:16|29
2022-08-26T23:54:41|28

2.2 错误日志分析

查看 mysql-error 日志发现，平均每 22 分钟左右会输出一次 page_cleaner 信息。


[root@dqynj142113 was]# grep "2022-08-26T" mysql-error.log  |grep flush
2022-08-26T00:19:29.317569+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10614ms to flush 9 and evict 0 pages
2022-08-26T00:41:18.053724+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 11653ms to flush 97 and evict 0 pages
2022-08-26T01:03:05.205966+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10077ms to flush 8 and evict 0 pages
2022-08-26T01:24:51.147325+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 10871ms to flush 10 and evict 0 pages
...
...
2022-08-26T22:49:24.264033+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 11051ms to flush 10 and evict 0 pages
2022-08-26T23:11:08.958039+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9625ms to flush 8 and evict 0 pages
2022-08-26T23:32:53.922992+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 9886ms to flush 8 and evict 0 pages
2022-08-26T23:54:41.143097+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12151ms to flush 19 and evict 0 pages

2.3 page_cleaner 分析

page_cleaner 输出信息解释 2022-08-26T23:54:41.143097+08:00 0 [Note] [MY-011953] [InnoDB] Page cleaner took 12151ms to flush 19 and evict 0 pages Page cleaner took 12151ms 意义：耗时时间为 12.121s flush 19 and evict 0 pages 意义：InnoDB 尝试刷新 19 个脏页

打印机制

代码解释

每一轮刷脏时间都超过 4s 的情况下，第一轮刷脏会被记录在 mysql-error 日志中，第二轮、第三轮刷脏不会被记录，第四轮刷脏会被记录在 mysql-error中。

分析

连续刷脏慢的情况下，两个 mysql-error 的 page_cleaner 记录之间最大可能相差 600 轮。

3持续观测磁盘 IO

通过 iostat 命令看到磁盘确实会出现一段时间的 IO 异常（此时磁盘 IO 使用基本为 0，但是磁盘使用率为 100%）。

4客户诉求

目前已知是磁盘 IO 这块的问题影响到了日常业务运行，还是希望我们能协助继续排查一下是 IO 的哪个环节出现的问题。

5blktrace 工具

5.1 工具简述

blktrace 工具[1]可以更好的追踪 IO 的过程，可以统计一个 IO 是在调度队列停留的时间长还是在硬件上消耗的时间长，利用这个工具可以协助分析和优化问题。

5.2 工具使用

5.2.1 blktrace 采集命令

根据磁盘 IO 异常规律使用 blktrace 工具采集磁盘异常期间 25s 的数据。

// blktrace 采集命令
blktrace -w 25 -d /dev/sda1  -o sda1$(date "+%Y%m%d%H%M%S")

5.2.2 统计分析

// blkparse 合并成一个二进制文件
blkparse -i sda120220915112930 -d blkpares2930.out
  
// btt 命令查看每个阶段的耗时
btt -i blkpares2930.out

不同阶段的 IO 解释：

Q2G – 生成 I/O 请求所消耗的时间，包括 remap 和 split 的时间；
G2I – I/O 请求进入 I/O Scheduler 所消耗的时间，包括 merge 的时间；
I2D – I/O 请求在 I/O Scheduler 中等待的时间，可以作为 I/O Scheduler 性能的指标；
D2C – I/O 请求在 Driver 和硬件上所消耗的时间，可以作为硬件性能的指标；
Q2C – 整个 I/O 请求所消耗的时间(Q2I + G2I + I2D + D2C = Q2C)，相当于 iostat 的 await。
Q2Q – 2个 I/O 请求的间隔时间。

分析结果来看 IO 卡在了 D2C 阶段（IO 请求在 Driver 和硬件上消耗的时间）。

5.2.3 也可以通过 blkparse 命令分析

// blkparse 直接进行分析
blkparse -i sda120220915112930 |less

// 下图中第六个字段表示 IO 事件，待表 IO 请求到了哪一阶段
  
A ：remap 对于栈式设备，进来的 I/O 将被重新映射到 I/O 栈中的具体设备。
X ：split 对于做了 Raid 或进行了 device mapper(dm) 的设备，进来的 I/O 可能需要切割，然后发送给不同的设备。
Q ：queued I/O 进入 block layer，将要被 request 代码处理（即将生成 I/O 请求）。
G ：get request I/O 请求（request）生成，为 I/O 分配一个 request 结构体。
M ：back merge 之前已经存在的 I/O request 的终止 block 号，和该 I/O 的起始 block 号一致，就会合并，也就是向后合并。
F ：front merge 之前已经存在的 I/O request 的起始 block 号，和该 I/O 的终止 block 号一致，就会合并，也就是向前合并。
I ：inserted I/O 请求被插入到 I/O scheduler 队列。
S ：sleep 没有可用的 request 结构体，也就是 I/O 满了，只能等待有 request 结构体完成释放。
P ：plug 当一个 I/O 入队一个空队列时，Linux 会锁住这个队列，不处理该 I/O，这样做是为了等待一会，看有没有新的 I/O 进来，可以合并。
U ：unplug 当队列中已经有 I/O request 时，会放开这个队列，准备向磁盘驱动发送该 I/O。这个动作的触发条件是：超时（plug 的时候，会设置超时时间）；或者是有一些 I/O 在队列中（多于 1 个 I/O）。
D ：issued I/O 将会被传送给磁盘驱动程序处理。
C ：complete I/O 处理被磁盘处理完成。

下图中第五个字段表示开始执行 blktrace 采集之后的时间（本次 blktrace 一共采集了 25s），第八列表示起始 block number；下图中被标记的这一片 IO，有不同时间发出的 D，都在同一时间完成 C。也就是说设备看上去是卡在某一个时间就突然活过来了，D 表示已经开始下发到 driver->RAID->Disk 路径，跟 OS 层已经没有关系了。