前往小程序,Get更优阅读体验!
立即前往
首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >故障分析 | 如何通过 blktrace 排查磁盘异常?

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

作者头像
爱可生开源社区
发布2023-08-18 20:37:03
5210
发布2023-08-18 20:37:03
举报

作者:张昊

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

本文来源:原创投稿

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


1背景描述

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

2日志分析

2.1 慢日志分析

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

代码语言:javascript
复制
[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 信息。

代码语言:javascript
复制

[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 的数据。

代码语言:javascript
复制
// blktrace 采集命令
blktrace -w 25 -d /dev/sda1  -o sda1$(date "+%Y%m%d%H%M%S")

5.2.2 统计分析

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

不同阶段的 IO 解释:

代码语言:javascript
复制
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 命令分析

代码语言:javascript
复制
// 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 层已经没有关系了。

5.2.4 对比试验

客户环境使用 SATA 盘做的 RAID5(这里使用了 DELL 的 RAID 控制器固件),客户找了一台相同配置的机器,直接用 SATA 盘做数据盘,没有发现磁盘异常,初步定位故障点在 RAID 设备层面。

6最终排查

6.1 问题原因

客户环境使用的 RAID 控制器固件版本为 25.5.6.0009,通过官网产品信息发现这个版本存在 BUG,会短暂影响磁盘 IO,修复版本为:25.5.8.0001[2]

6.2 问题解决

升级 RAID 控制器固件版本前:

升级 RAID 控制器固件版本后:

参考资料

[1]

blktrace 工具使用详情: https://developer.aliyun.com/article/698568

[2]

25.5.8.0001: https://www.dell.com/support/home/zh-cn/drivers/driversdetails?driverid=fy18x

本文关键字:#blktrace# #磁盘# #RAID#

本文参与 腾讯云自媒体同步曝光计划,分享自微信公众号。
原始发表:2023-08-08,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 爱可生开源社区 微信公众号,前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体同步曝光计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 1背景描述
  • 2日志分析
    • 2.1 慢日志分析
      • 2.2 错误日志分析
        • 2.3 page_cleaner 分析
          • 打印机制
          • 代码解释
          • 分析
      • 3持续观测磁盘 IO
      • 4客户诉求
      • 5blktrace 工具
        • 5.1 工具简述
          • 5.2 工具使用
            • 5.2.1 blktrace 采集命令
            • 5.2.2 统计分析
            • 5.2.3 也可以通过 blkparse 命令分析
            • 5.2.4 对比试验
        • 6最终排查
          • 6.1 问题原因
            • 6.2 问题解决
              • 参考资料
          相关产品与服务
          云数据库 MySQL
          腾讯云数据库 MySQL(TencentDB for MySQL)为用户提供安全可靠,性能卓越、易于维护的企业级云数据库服务。其具备6大企业级特性,包括企业级定制内核、企业级高可用、企业级高可靠、企业级安全、企业级扩展以及企业级智能运维。通过使用腾讯云数据库 MySQL,可实现分钟级别的数据库部署、弹性扩展以及全自动化的运维管理,不仅经济实惠,而且稳定可靠,易于运维。
          领券
          问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档