使用 iodump 一步定位磁盘 IO Util 高的元凶

用户1278550

发布于 2024-04-11 10:20:06

1910

发布于 2024-04-11 10:20:06

文章被收录于专栏：idbaidba

在之前的文章：《BPF 性能之巅》- 使用 perf tools 做性能分析（1）中，我们使用了 iosnoop、strace 和 opensnoop 来排查磁盘 IO 满的问题，最终可以大致定位哪些进程执行了哪些文件相关的操作，导致磁盘 IOUtil 高。

那有没有工具可以一步到位（即用一条命令）来定位问题呢？

由广成子开发的 iodump 命令就是我们需要的工具（最重要的是 fullpath 字段非常有用）。

地址：https://gitee.com/anolis/iodump

工具介绍

iops dump 工具（简称 iodump）是利用内核 tracepoint 静态探针点技术实现的一个 IO 问题排查工具。通过 iops dump 工具，我们可以获取每一个 IOPS（w/s和r/s）的详细信息，不仅包括 IO 请求的 size 大小，还包括 IO 请求的扇区地址，同时还包含 IO 请求的发生时间、读写的文件全路径、产生 IO 请求的进程、产生 IO 请求的系统调用和扩展 IO 类型等信息。这其中最具有特色的就是读写的文件全路径功能。

工具特点

当我们要排查操作系统磁盘 IO 问题时，可以使用 iostat 扩展命令进行具体分析。当 iostat 工具显示此时磁盘 IO 并发很高，磁盘使用率接近饱和时，还需要依赖更多的工具进一步查看影响磁盘 IO 使用率高的进程信息和读写文件信息。

常见的工具或者方法有 iotop、blktrace、ftrace和 block_dump 等。实际使用中，它们都有各种不足：

iotop 工具，可以细化到进程带宽信息，但缺乏进程级的IOPS信息，也没有对应的磁盘分区信息。
blktrace 工具，功能强大，但使用较复杂。获取 sector 信息后，进一步通过debugfs 等其他方式解析文件路径也比较低效。
ftrace 工具，当跟踪块设备层静态探针点时，功能和blktrace工具类似，也需要通过 debugfs 等工具进一步解析文件路径。当跟踪文件系统层探针点函数时，无法精确对应IOPS数量。
block_dump 工具，也同样存在以上ftrace工具的2个不足。

相比其他磁盘 IO 类工具，iodump 有如下几个特色优势：

支持自定义选择 blk 层探针点函数。
支持自定义输出字段信息，包括时间、进程名、进程 ID、IO 大小、扇区地址、磁盘分区、读写类型、扩展 IO 类型、IO 来源、Inode 号，文件全路径。
当采集进程异常退出后，支持内核态自动关闭探针。
支持从 2.6.32 以上的各内核版本。
当 IOPS 高时，支持抽样输出。

iodump 功能虽然强大，但 iodump 本质上采用的是加载内核模块方式实现，可能会引起操作系统crash，请在重要的生产环境使用前，提前进行充分测试。从计算平台的实际使用情况，未发生生产环境宕机。

工具安装

具体请参考官方文档，可以自己构建 rpm 或者使用源码安装。

诊断磁盘 IO 打满

生产中遇到一个案例，磁盘分区 sda 平时读 IOPS 是 20 多，但有时候读 IOPS会瞬时高出数倍，并将磁盘 io util 打满，此时我们就可以使用如下方式来查看 sda 盘上的 IO 操作：

sudo iodump -p sda -t 15
datetime                   comm                pid iosize      sector rw rwsec launcher       fullpath
2024-03-19T15:18:55.973146 kworker/u546:0  2683970   4096   527212928  W     V ret_from_fork_nospec_begin  /var/log/audit/audit.log
2024-03-19T15:18:55.973215 kworker/u546:0  2683970   4096    75002816  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973236 kworker/u546:0  2683970   4096   103445480  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973252 kworker/u546:0  2683970   4096   103458376  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973267 kworker/u546:0  2683970   4096   103461040  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973282 kworker/u546:0  2683970   4096   103480128  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973297 kworker/u546:0  2683970   4096   103482472  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973311 kworker/u546:0  2683970   4096   103487648  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973326 kworker/u546:0  2683970   4096   103490904  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973342 kworker/u546:0  2683970   4096   103490976  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973359 kworker/u546:0  2683970   8192   103500688  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973376 kworker/u546:0  2683970   4096   103501784  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973392 kworker/u546:0  2683970   4096   103616688  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973416 kworker/u546:0  2683970   8192   103620928  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973431 kworker/u546:0  2683970   4096   103623504  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973447 kworker/u546:0  2683970   4096   103627824  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973462 kworker/u546:0  2683970   4096   103630496  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973477 kworker/u546:0  2683970   4096   103633160  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973492 kworker/u546:0  2683970   4096   103635824  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973507 kworker/u546:0  2683970   4096   103638504  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973522 kworker/u546:0  2683970   4096   103641224  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973538 kworker/u546:0  2683970   4096   103643896  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973555 kworker/u546:0  2683970   4096   103646584  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973571 kworker/u546:0  2683970   4096   103803304  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973587 kworker/u546:0  2683970   8192   103803848  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973607 kworker/u546:0  2683970   8192   103807088  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973623 kworker/u546:0  2683970   4096   103807464  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973638 kworker/u546:0  2683970   4096   103810136  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973652 kworker/u546:0  2683970   4096   103810320  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973667 kworker/u546:0  2683970   4096   103810336  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973682 kworker/u546:0  2683970   8192   103810352  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973696 kworker/u546:0  2683970   4096   103813960  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973713 kworker/u546:0  2683970  12288   103817672  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973727 kworker/u546:0  2683970   4096   103817696  W     V ret_from_fork_nospec_begin  /var/log/journal/139ca3191d0842efa10f74b369c73252/system.journal
2024-03-19T15:18:55.973777 kworker/u546:0  2683970   4096   531137256  W     V ret_from_fork_nospec_begin  /var/tmp/sclgZX5ki
2024-03-19T15:18:55.973794 kworker/u546:0  2683970   4096   963358840  W     V ret_from_fork_nospec_begin  /var/log/messages
datetime                   comm                pid iosize      sector rw rwsec launcher       fullpath

相比 iosnoop，这里最妙的是 fullpath 字段，以及 launcer 字段：

Tracing block I/O for 30 seconds (buffered)...
STARTs          ENDs            COMM         PID    TYPE DEV      BLOCK        BYTES     LATms
1276585.460147  1276585.460817  <...>        3559925 W    8,0      592043960    4096       0.67
1276585.460214  1276585.460842  <...>        3559925 W    8,0      526997432    4096       0.63
1276594.259996  1276594.260503  <...>        3710230 WSM  8,0      526514096    8192       0.51

Ending tracing...

我们来看一下 iodump 输出字段的含义：

datetime：日期时间格式，小数点后是微秒信息。
timestamp：时间戳信息，单位微秒（us）。
comm：上下文环境中的进程名。
pid：上下文环境中的进程ID。
tid：上下文环境中的线程ID。
iosize：一次发向磁盘的io的数据大小，例如4096、524288等，单位为字节，数值必须是4096的倍数，4096是一个page的大小。
sector：一次发向磁盘的request的数据在磁盘中的扇区地址。扇区地址是硬盘出厂时，低级格式化时的一个扇区顺序号。一个扇区地址在一块磁盘中是唯一的。
partition：一次发向磁盘的request的数据所在磁盘分区信息，例如sda5，sda，nvme0n1p3和nvme0n1。
rw：IO基本类型，R是READ，W是WRITE，D是DISCARD，E是SECURE_ERASE和DISCARD，F是FLUSH，N是Other，值单选。
rwsec：IO扩展类型，F是FUA(forced unit access)，A是RAHEAD(read ahead)，S是SYNC，M是META，E是SECURE。可多选，以上都没有时，显示V。
launcher：对于从用户态发起的IO调用栈，这里将显示出系统调用名称信息。
ino：一次发向磁盘的request的数据在磁盘分区中的inode号信息，有些操作元数据信息的request请求这个inode信息为0。
fullpath：如果inode信息不为0时，所对应的文件名以及其磁盘路径。这里解析了所在磁盘分区的完整文件路径。当磁盘IO打满时，我们可以通过对FilePath字段的分析，迅速定位问题。

我们可以写脚本对输出结果做统计，这样就能分析出磁盘 IO 满到底是什么进程在做什么样的文件操作。

内存颠簸型磁盘io打满

内存颠簸是指在计算机系统中内存的分配与回收过程中，频繁地执行内存分页，从而使得系统性能下降的情况。这种情况往往是由于程序内存分配不合理，导致频繁地进行内存分页，同时内存碎片过多，导致内存管理效率变低。

当出现内存颠簸时，系统会需要频繁地将内存数据从硬盘或其他存储设备中读取，再放回内存中进行处理。这样，就会大大降低系统的运行效率，甚至造成系统卡顿或崩溃的情况。

解决内存颠簸问题的方式是尽量避免过度使用大型内存分配，并优化内存回收策略，尽可能减少内存碎片产生。同时，可以采用内存复用技术，将已使用的内存块再次利用，从而避免内存的浪费。

有些情况下，我们会看到 launcher 字段是 page_fault 或 async_page_fault，并且 rw 字段是 R 读。最重要的是，如果观察一个时间区间内（比如60秒）的数据，我们会发现同一个扇区地址 sector 字段，会重复读取几百，几千或上万次。那么这种情况就是内存颠簸引起的读磁盘 IO。同时可能伴有 iosize 是 4096 等小io，fullpath 的文件为 binary 文件等特征。

datetime                   comm    pid iosize    sector rw   launcher     fullpath
2022-06-01T19:52:44.200717 task  48309 4096   242275424  R   page_fault   /lib64/libmodx.so
2022-06-01T19:52:44.215145 task  48309 4096   242280736  R   page_fault   /lib64/libmodx.so
2022-06-01T19:52:44.236601 task  48309 4096   242278216  R   page_fault   /lib64/libmodx.so

字段 launcher 为 page_fault，说明 io 产生的原因是发生了主缺页中断。一次主缺页中断代表程序执行代码段时，内存中不存在这块代码段，进而引起一次读 IO，从磁盘中读取这部分代码段内容。内存颠簸时就会发生内存中频繁且反复出现代码段不存在的情况。

引起内存颠簸可能是单 cgroup 层面、单 numa 节点或整机层面内存紧张引起。当通过上述特征判断出是内存颠簸引起的读 io 打满时，以单 cgroup 内存紧张为例，pid 是 48309，进一步排查方法如下。

$ cat /proc/48309/cgroup | grep memory
9:memory:/system.slice/sshd.service
$ cat /sys/fs/cgroup/memory/system.slice/task.service/memory.limit_in_bytes 
8615100416
$ ps h -p  48309 -o rss  
8240736
$ echo $(((8615100416/1024-8240736)/1024))
168

进程的 rss 内存是 8240736kB，此时这个进程的 cgroup 的memory.limit_in_bytes 是 8615100416。说明在 cgroup 的限额内，已经被 rss 占据了绝大部分配额，只留下 168Mb 配额，不足以完全融下进程的代码段，从而引起代码段的不同部分频繁被丢弃和磁盘读取。

性能开销

说到性能开销，需要先简单介绍下目前行业内各种主流的trace工具的技术实现原理。一般都是在进程上下文环境的tracepoint钩子函数中向一个ring buffer中写入数据，另外一个用户态进程再从ring buffer中读取数据。这样性能开销就需要分两部分计量。

我们构造了一个每秒 1.2 万读 IOPS 和 250 写 IOPS 的测试环境，开启 iodump后，CPU 性能开销如下。

-	CPU	MEM
iodump进程	单核0.3%	876KB
1比100抽样	单核1.6%	1MB/核
全量采集	单核10%	1MB/核

参数说明

为了完整的了解使用方法，我们可以查看帮助信息。

$ iodump -h

Usage: iodump [OPTIONS] 

Summary: this is a io tools. it can dump the details of struct request or struct bio.

Options:
  -h             Get the help information.
  -H             Hiding header information.
  -a <G>         Set blk tracepoint action which is fully compatible with blktrace, default G, See Actions.
  -o <pid,comm>  Set the output field, such as datetime,comm,pid, See Formats.
  -p <sda2>      Set partition parameter, this option is necessary.
  -s <filepath>  Set saving output to the file. if not set, it will output to standard output.
  -t <time>      Set tracing last time, default last time is 300 second, default 300 seconds.
  -O <ino>       Set the extra output field, such as tid,ino, See Formats.
  -S <number>    Set sample number, Only 1/number output is displayed, default 1.
  -c <comm>      Just output exact match comm string record.
  -C <comm>      Just output record which comm contain the comm string.
  -P <pid>       Just output exact match pid record.

Major Actions:
   ACTION  TRACEPOINT             UNIT
   Q       block_bio_queue        bio
   G       block_getrq            bio
   I       block_rq_insert        request
   D       block_rq_issue         request
   C       block_rq_complete      request
Minor Actions:
   B       block_bio_bounce       bio
   F       block_bio_frontmerge   bio
   M       block_bio_backmerge    bio
   S       block_sleeprq          bio
   X       block_split            bio
   R       block_rq_requeue       request

Formats:
   FIELD          DESCRIPTION
   datetime       Such as 2022-03-23T16:42:05.315695, Precision millisecond.
   timestamp      Such as 1648025082259168, Precision millisecond.
   comm           Such as iodump, process short name.
   pid            tgid 
   tid            task id
   iosize         IO size, the unit is byte.
   sector         Sector address on the disk.
   partition      Such as sda5.
   rw             The value list is R(read) or W(write).
   rwsec          The value list is A(ahead) E(secure) F(force unit access) M(meta) S(sync) V(vacant)
   launcher       The bottom function of the call stack.
   ino            Inode number.
   fullpath       Read or Write file full path.

下面介绍各主要参数的含义：

-p参数：设置需要追踪的磁盘或磁盘分区，例如 -p sda 或 -p sda5。这个参数是必选参数，不设置程序运行报错。
-t参数：设置追踪程序运行的时长，例如 -t 60 或-t -1，此时程序运行60秒后会自动终止，-1表示永远运行。不指定-t参数，程序默认运行300秒结束。
-s参数：设置追踪信息存储的文件，例如 -s /tmp/log。不指定-s参数时，追踪信息会打印到屏幕标准输出，此时也可以通过重定向将追踪信息保存到磁盘文件。
-S参数：设置抽样输出的比例。例如 -S 30，此时iodump将每隔30次只输出一次。
-H参数：设置屏蔽标题栏信息的输出，例如 -H。
-a参数：设置iodump追踪的内核静态探针点，选项值可以是5个主要跟踪点Q、G、I、D、C，以及其他几个辅助跟踪点B、F、M、R、S和X。默认缺省为G，即block_getrq，UNIT为bio。其他一些探针点UNIT也可能是request。
-o参数：设置输出信息字段，例如 -o pid,comm。字段值可以是datetime、timestamp、comm、pid、tid、iosize、sector、partition、rw、rwsec、launcher、ino和fullpath，多选逗号隔开。
-O参数：设置额外追加的输出信息字段，例如 -O tid,ino。默认输出信息字段组合为datetime,comm,pid,iosize,rw,rwsec,launcher,fullpath。
-c参数：仅输出和输入的进程名精准匹配的结果，例如，-c kworker/1:0.
-C参数：仅输出和输入的进程名模糊匹配的结果，例如，-C kworker.
-P参数：仅输出和输入的PID精准匹配的结果，例如，-P 1234.

下面是一些各种参数组合运行的实例：

$ sudo iodump -p sda
$ sudo iodump -p sda5 -t -1 -H >/tmp/log
$ sudo iodump -p nvme -t 600 -H -s /tmp/log
$ sudo iodump -p nvme0n1p1 -S 10
$ sudo iodump -p sda -a G
$ sudo iodump -p sda -o comm,pid
$ sudo iodump -p sda -O tid,ino
$ sudo iodump -p sda -c kworker/1:0
$ sudo iodump -p sda -C kworker
$ sudo iodump -p sda -P 1234

详细请参考：https://gitee.com/anolis/iodump

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2024-04-10，如有侵权请联系 cloudcommunity@tencent.com 删除

内存