OPPO内核性能追踪平台技术实践——记一次奇怪的IO 100%忙问题定位过程
我们通过监控发现，线上多台机器周期性出现IO 100%忙问题，该案例用常规的IO忙排查方法很难解决，最后从文件系统层一直跟到磁盘控制器那部分代码，才确认最终原因。
本文首先简单介绍使用iostat/iotop/strace这些工具，如何排查常规的IO忙问题。然后结合ext4文件系统层、块设备block层、磁盘控制器层内核代码，介绍本案例的排查过程，希望看过本文的小伙伴会有新的内核技能增长。
1、前期使用iostat/iotop/strace的排查
因为IO忙的问题会周期性出现，20多分钟出现一次，CPU和内存使用都正常，每次IO忙持续的时间在7s左右，之后系统就会恢复正常。首先用iostat工具查看IO忙时，系统磁盘使用情况：
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 1.00 0.00 0.00 0.00 0.00 0.00 5.12 0.00 0.00 0.00 0.00 100.00
sdb 0.00 1.00 0.00 0.00 0.00 0.00 0.00 3.11 0.00 0.00 0.00 0.00 100.00
%util为100，说明系统进程消耗在IO处理的时间非常长，貌似此时IO负荷很高？同时结合iotop工具抓到IO忙的进程：
Total DISK READ : 0.00 B/s | Total DISK WRITE : 1653.33 K/s
Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 844.51 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
343092 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % nethouse
303116 be/3 root 0.00 B/s 5.95 K/s 0.00 % 99.99 % [jbd2/dm-42-8]
341322 be/0 root 0.00 B/s 347.91 K/s 0.00 % 99.99 % [loop0]
345740 be/4 root 0.00 B/s 2.97 K/s 0.00 % 99.99 % logtail
365711 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % [jbd2/dm-18-8]
389998 be/3 root 0.00 B/s 8.92 K/s 0.00 % 99.99 % [jbd2/dm-45-8]
390589 be/4 1000 0.00 B/s 0.00 B/s 0.00 % 99.99 % python
188427 be/3 root 0.00 B/s 2.97 K/s 0.00 % 99.99 % [jbd2/dm-19-8]
349669 be/4 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % logtail
151892 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % [jbd2/dm-46-8]
204845 be/3 root 0.00 B/s 0.00 B/s 0.00 % 99.99 % [jbd2/dm-37-8]
..............................
另外一次的打印：
Actual DISK READ: 0.00 B/s | Actual DISK WRITE: 1428.23 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
447237 be/4 root 0.00 B/s 0.00 B/s 0.00 % 87.24 % nethouse
341322 be/0 root 0.00 B/s 1033.54 K/s 0.00 % 86.79 % [loop0]
280587 be/3 root 0.00 B/s 978.59 B/s 0.00 % 85.52 % [jbd2/dm-24-8]
342706 be/4 root 0.00 B/s 978.59 B/s 0.00 % 80.06 % nethouse-ag
160037 be/4 agent 0.00 B/s 978.59 B/s 0.00 % 77.77 % ./process_exporter
389998 be/3 root 0.00 B/s 0.00 B/s 0.00 % 77.18 % [jbd2/dm-45-8]
151892 be/3 root 0.00 B/s 1467.88 B/s 0.00 % 76.65 % [jbd2/dm-46-8]
151246 be/3 root 0.00 B/s 489.29 B/s 0.00 % 73.67 % [jbd2/dm-39-8]
402535 be/3 root 0.00 B/s 1957.18 B/s 0.00 % 73.67 % [jbd2/dm-15-8]
390578 be/4 1000 0.00 B/s 0.00 B/s 0.00 % 70.28 % python
345741 be/4 root 0.00 B/s 1467.88 B/s 0.00 % 68.48 % logtail
这些进程有业务相关的进程，也有ext4 jbd2和loop0这些内核线程，看IO 使用率确实挺高的，与iostat监控的结果基本一致。既然找到了几个IO忙的进程，按照常规的IO忙排查方法，需要使用strace跟踪IO使用率高的进程的系统调用，诸如write、fsync这些系统调用都是有嫌疑的。命令是strace -f -p 进程ID。注意，进程ID是业务进程的(如python 、nethouse)，因为造成IO忙的根源，一般都是业务程序大量频繁文件写导致的。
使用该命令观察python 、nethouse这些业务进程的系统调用，会有刷屏打印，监控一段时间后，在日志中搜索wrtie、fsync等关键字，确实找到了有进程调用这些系统调用，但执行的并不很频繁，读写的文件也是诸如日志等常见的文件，没有发现疑点。并且程序之前在物理机上运行时挺正常的，最近迁移到容器上后才出现了IO 100%忙问题。
2、IO 100%忙问题是否与内核jbd2进程有关？
每次IO忙时，都有ext4 jbd2进程参与。当读写文件时，会触发文件元数据的修改，然后发起一次ext4 jbd2事件，比如内核vfs层文件写，会执行到如下函数流程：
update_time->__mark_inode_dirty->ext4_dirty_inode
ext4_dirty_inode中会把本次修改的inode元数据提交给jbd2。jbd2/dm-24-8这些内核线程会被定时唤醒，负责把这些元数据写入ext4 jbd2备份分区，函数执行流程如kjournald2->jbd2_journal_commit_transaction->submit_bh。
如果内存中的文件元数据由于异常掉电发生丢失，可以从ext4 jbd2备份分区还原。想过submit_bh函数中根据bh，反推出来这些元数据自哪些文件，但是有一定难度。IO 100%忙问题发生时，也有不少业务进程在写文件，所以不一定就是内核jbd2进程导致的。网上找到了一篇《JDB2导致磁盘io使用率高》的文章，但是该问题发生在centos 6.5环境，我们用的是centos 7.6。
3、IO 100%忙时发现异常
之前监控IO 100%忙时用的命令是iostat -dmx 5，即5s打印一次IO数据，怀疑监控的数据不完整。监控周期改成1s，即iostat -dmx 1，再次跟踪IO 100%忙时的数据，有了新的发现，这里是监控到的IO 100%忙时连续3s的数据。
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 7.00 0.00 0.00 0.00 0.00 100.00
sdb 0.00 1.00 0.00 0.00 0.00 0.00 0.00 2.48 0.00 0.00 0.00 0.00 100.10
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 10.00 0.00 0.00 0.00 0.00 0.00 8.26 0.00 0.00 0.00 0.00 100.00
sdb 0.00 4.00 0.00 0.00 0.00 0.00 0.00 3.44 0.00 0.00 0.00 0.00 100.00
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 25.00 0.00 0.00 0.00 0.00 100.00
sdb 0.00 2.00 0.00 0.00 0.00 0.00 0.00 6.80 0.00 0.00 0.00 0.00 100.00
可以发现这段时间wMB/s都是0，写入磁盘的文件数据量是0？
这有点奇怪，IO忙时一般wMB/s都是1s几M级别的。avgqu-sz表示“平均等待处理的IO请求队列长度”，这个IO队列长度也一直在增加，正常这个数据接近0。怀疑写文件的进程可能因为某种原因，处于阻塞状态，也就是说都休眠了。
怎么验证这个猜想？抓取到这段时间系统所有进程的栈回溯信息，验证了猜想，列出了其中两个进程栈回溯信息：
[2511670.778377] jbd2/dm-18-8 D ffff9d69b07cb0c0 0 365711 2 0x00000080
[2511670.778379] Call Trace:
[2511670.778394] [<ffffffff99d69f19>] schedule+0x29/0x70
[2511670.778396] [<ffffffff99d67a21>] schedule_timeout+0x221/0x2d0
[2511670.778416] [<ffffffff99d695ed>] io_schedule_timeout+0xad/0x130
[2511670.778418] [<ffffffff99d69688>] io_schedule+0x18/0x20
[2511670.778420] [<ffffffff99d68071>] bit_wait_io+0x11/0x50
[2511670.778423] [<ffffffff99d67b97>] __wait_on_bit+0x67/0x90
[2511670.778429] [<ffffffff99d67d01>] out_of_line_wait_on_bit+0x81/0xb0
[2511670.778434] [<ffffffff9987a38a>] __wait_on_buffer+0x2a/0x30
[2511670.778442] [<ffffffffc042d801>] jbd2_journal_commit_transaction+0x1781/0x19b0 [jbd2]
[2511670.778452] [<ffffffffc0432e89>] kjournald2+0xc9/0x260 [jbd2]
[2511670.754179] nethouse D ffff9d5d226c4100 0 632811 342699 0x00000080
[2511670.754181] Call Trace:
[2511670.754189] [<ffffffff99d69f19>] schedule+0x29/0x70
[2511670.754191] [<ffffffff99d67a21>] schedule_timeout+0x221/0x2d0
[2511670.754204] [<ffffffff99d695ed>] io_schedule_timeout+0xad/0x130
[2511670.754207] [<ffffffff99d69688>] io_schedule+0x18/0x20
[2511670.754209] [<ffffffff99d68071>] bit_wait_io+0x11/0x50
[2511670.754211] [<ffffffff99d67b97>] __wait_on_bit+0x67/0x90
[2511670.754214] [<ffffffff997b6b81>] wait_on_page_bit+0x81/0xa0
[2511670.754218] [<ffffffff997b6cb1>] __filemap_fdatawait_range+0x111/0x190
[2511670.754224] [<ffffffff997b6d44>] filemap_fdatawait_range+0x14/0x30
[2511670.754227] [<ffffffff997b91a6>] filemap_write_and_wait_range+0x56/0x90
[2511670.754237] [<ffffffffc067e5aa>] ext4_sync_file+0xba/0x320 [ext4]
[2511670.754240] [<ffffffff99877367>] do_fsync+0x67/0xb0
[2511670.754242] [<ffffffff99877650>] SyS_fsync+0x10/0x20
根据这些进程栈回溯信息，基本确认了IO 100%忙时，iotop监控到IO使用率很高的进程都处于休眠状态，因为这段时间执行了多次栈回溯的命令，这些进程的函数执行流程及进程状态都一样。
这样就可以解释之前的疑问了。这些写文件的进程在IO 100%忙的7s内都处于休眠状态，也就是说一直占着CPU，所以iotop监控到这些进程IO使用率接近100%，iostat监控的%util是100%也是这个原因。并且因为这7s内，写文件的进程都休眠了，wMB/s为0就可以解释了，avgqu-sz表示的IO队列长度一直在增加也可以解释了，因为系统不处理文件写了，新的写文件IO请求又不断到来累加。
根据业务进程的栈回溯信息，发现它们写文件比较频繁的调用了fsync或者write（文件标志位有O_SYNC）这些系统调用。这相当于直接把文件数据写入磁盘，估计这些数据比较关键。但这种用法对系统性能有不良影响，写磁盘会消耗不少时间。一般写文件是先把文件数据写入page cache就返回，等page cache总量达到一定数值，系统进程自动把部分page cache刷入磁盘。
虽然业务程序写文件的用法不太合理，但不至于导致这些进程在长达7s左右的时间内都休眠，进一步导致IO使用率100%这种IO忙的假象。需要跟踪业务程序fsync或者write（文件标志位有O_SYNC）这些系统调用的内核函数执行流程，看能否抓到IO 100%忙时的一些异常调用？
4、进程写文件后休眠的跟踪
以跟踪fsync系统调用为例，内核版本3.10.0。
SyS_fsync->do_fsync->ext4_sync_file->filemap_write_and_wait_range，源码有删减，只保留核心的。
int filemap_write_and_wait_range(struct address_space *mapping,
loff_t lstart, loff_t lend)
{
//发起文件数据写入磁盘IO请求
err = __filemap_fdatawrite_range(mapping, lstart, lend,WB_SYNC_ALL);
//等待文件数据写入磁盘
int err2 = filemap_fdatawait_range(mapping,lstart, lend);
}
对于__filemap_fdatawrite_range()函数，常见的执行流程是：
__filemap_fdatawrite_range->do_writepages->ext4_writepages->ext4_io_submit->submit_bio
submit_bio函数比较常见，把本次要写入的文件数据块提交给block层，最后再由block层调用底层磁盘驱动程序，把文件数据真正写入磁盘。
filemap_fdatawait_range()中执行__filemap_fdatawait_range->wait_on_page_writeback->wait_on_page_bit函数休眠，然后等待文件数据传输完成后，由磁盘驱动注册的中断函数逐层调用回调函数，把它唤醒。
大体列一下相关函数的源码：
static int __filemap_fdatawait_range(struct address_space *mapping,
loff_t start_byte, loff_t end_byte)
{
.....................
//pagevec_lookup_tag()取出写入磁盘文件页对应的page存入pvec
while ((index <= end) &&
(nr_pages = pagevec_lookup_tag(&pvec, mapping, &index,
PAGECACHE_TAG_WRITEBACK,
min(end - index, (pgoff_t)PAGEVEC_SIZE-1) + 1)) != 0)
{
for (i = 0; i < nr_pages; i++) {
struct page *page = pvec.pages[i];
//在这里休眠，等待page对应的文件页数据写回磁盘
wait_on_page_writeback(page);
}
}
}
void wait_on_page_bit(struct page *page, int bit_nr)
{
DEFINE_WAIT_BIT(wait, &page->flags, bit_nr);
if (test_bit(bit_nr, &page->flags))
//等待队列head是page_waitqueue(page)，每个page特有
__wait_on_bit(page_waitqueue(page), &wait, bit_wait_io,
TASK_UNINTERRUPTIBLE);
}
void end_page_writeback(struct page *page)
{
//唤醒等待文件传输完成而休眠的进程
wake_up_page(page, PG_writeback);
}
简单总结一下，写文件的进程执行submit_bio函数把待写入的文件数据块提交到block层，然后执行filemap_fdatawait_range->__filemap_fdatawait_range->wait_on_page_writeback->wait_on_page_bit函数休眠。等文件数据块最终写入磁盘，由底层驱动的中断函数调用回调函数，最终执行到end_page_writeback函数唤醒休眠的写文件进程。
在wait_on_page_bit、submit_bio、end_page_writeback这3个函数中加入调试信息，IO 100%问题发生时，是否能抓到有用的信息？centos系统有Systemtap工具，添加调试信息很方便，否则就得修改内核printk添加打印了。
这里列举一下wait_on_page_bit()函数中需要捕捉的调试信息。
probe kernel.function("wait_on_page_bit")
{
//限制只有loop0进程执行wait_on_page_bit()才打印，防止刷屏打印，否则可以放开进程限制，以免漏掉有用信息
if(execname() == "loop0")
{
printf("wait_on_page_bit %s pid:%d page:%p bit_nr:%d cpu:%d\n",
execname(),tid(),$page,$bit_nr,cpu())}
}
}
execname()是当前进程的名称，tid()是进程ID，cpu()是当前进程运行的CPU编号，page和bit_nr都是wait_on_page_bi()函数的形参。实现的效果相当于把下边这行代码添加到wait_on_page_bit()函数开头。
printk(“wait_on_page_bit %s pid:%d page:%p bit_nr:%d cpu:%d\n”,
current->comm,current->pid,page,bit_nr,smp_processor_id());
submit_bio和end_page_writeback函数中Systemtap捕捉信息的形式类似，不再列举。把这三个函数的捕捉命令写入一个文件中，比如stap.stp，执行stap stap.stp即可开启捕捉打印。然后在终端就能实时看到进程写文件过程，执行内核wait_on_page_bit()、submit_bio()、end_page_writeback()三个函数的所有打印信息，如下所示：
submit_bio loop0 pid:213460 cpu:3
wait_on_page_bit loop0 pid:213460 page:0xfffff2f8e05cdbc0 bit_nr:13 cpu:3
end_page_writeback swapper/3 pid:0 page:0xfffff2f8e05cdbc0 cpu:3
然后等待20多分钟后IO 100%忙问题的出现，确实抓到了异常的打印，是下边这个打印：
end_page_writeback jbd2/dm-4-8 pid:39805 page:0xfffff2f909e7d600 cpu:4
在IO 100%忙持续的7s时间内，有1~2s时间内，共有1000多次“end_page_writeback jbd2/dm-4-8 pid:39805...............”这类打印。正常情况，1s只有几次这种打印。
这点很明显，按照最初的理解，end_page_writeback()函数用于唤醒等待文件数据传输到磁盘而休眠的进程，现在突然有1000多次唤醒，说明这个时间点前有非常多的文件IO传输？是不是这个原因导致IO 100%忙问题的发生？会不会是与page cache回收有关？就是说，因为page cache过多，所以每隔20多分钟就会触发一次page cache回收，占用IO，导致业务进程写文件流程暂时阻塞，进而发生IO 100%忙问题？
但是有一个很大的疑点，我们用iostat工具监控IO 100%忙的那7s内，发现文件写入数据速率wMB/s基本是0，这说明没有文件数据写入磁盘，到底问题出在哪里，难道是iostat统计有问题？没有研究过iostat统计wMB/s参数的原理，没办法保证wMB/s是0，就一定没有文件数据写入磁盘。
疑问有很多，这时想到在排查问题初期，在另一台IO 100%忙的机器上做过一个实验。因为cat /proc/meminfo执行后发现这台机器cache有50G左右，free内存只有12G左右，于是drop_cache释放了一下缓存(这台机器上运行的业务已经异常，确保drop_cache不会影响业务，正常是不能直接drop_cache的)，结果20多分钟后发现IO 100%忙问题还是会发生，但是只持续了1s，以前是持续7s。
这好像传达了一个信息，cache越少，每20多分钟回收cache占用的内存时，page cache回写磁盘占用IO的时间就越少，IO 100%忙持续的时间就会变短。如果IO 100%忙的真正原因是这个，可以通过设置内存回收参数，控制page cache的最大值，不至于内存回收时占用IO时间过长，应该会有效果。可惜我们遇到的问题，不是这个原因导致的。
首先观察IO 100%忙前后20多分钟时间内，free命令观察cache、free这些内存参数的变化，发现cache和free内存并没有明显的增加或者减少，最多上下波动了几M大小。并且drop_cache那台机器，继续iostat观察IO 100%持续的时间，发现是7s，推测，也就drop_cache那次，IO 100%持续的时间是1s。这些验证说明IO 100%忙与内存回收没有关系。
但还有一点疑问，为什么IO 100%持续的7s内，有1000多个“end_page_writeback jbd2/dm-4-8 pid:39805...............”这类打印？这点排查了一下，导致这个打印的函数执行流程是：
kjournald2->jbd2_journal_commit_transaction->generic_writepages->write_cache_pages->__writepage->ext4_writepage->ext4_bio_write_page->end_page_writeback
并不是磁盘传输完文件数据，产生中断，执行回调函数后执行的end_page_writeback函数。这里在ext4_bio_write_page函数最后执行的end_page_writeback函数，意思是，当前的文件page页并没有发起IO传输，执行end_page_writeback只是终止传输而已，并不是唤醒休眠的进程，感兴趣的小伙伴可以看下ext4_bio_write_page函数源码。
好不容易有的一个明显发现，还得花时间验证它是无效的，排查内核问题就是一个不断试错的过程。
之后又在__filemap_fdatawait_range、pagevec_lookup_tag等有关函数加入调试信息，始终没有明显发现。
从submit_bio提交文件数据传输IO请求，到真正文件数据传输完成，其实还有很长一段路要走，比如block层要对本次提交的文件IO进行合并，还有elv调度算法，然后才会调用磁盘驱动程序进行真正的文件数据传输，文件数据传输完成，先产生硬中断，然后发起软中断，在软中断函数中唤醒等待文件数据传输完成的进程，写文件流程才算结束。
这个过程任何一个环节有问题，都有可能导致本次的IO 100%忙问题发生。最好是找到每个环节的关键函数，添加简单的调试信息，观察IO 100%忙时是否有异常行为？
5、block层的排查
submit_bio发送文件IO请求前，会生成一个struct bio结构，它保存了本次IO传输在磁盘中的扇区首地址、传输数据量、IO传输完成的回调函数等等。
然后执行submit_bio->generic_make_request，在generic_make_request函数获取磁盘disk的IO请求队列，即struct request_queue *q = bdev_get_queue(bio->bi_bdev))那行代码。接着执行q->make_request_fn(q, bio)，把本次传输的bio插入IO队列，q->make_request_fn指向blk_queue_bio函数。
blk_queue_bio函数中引入了一个新的结构struct request，request个人觉也代表IO请求，但是它可以合并bio。举个例子，bio0传输的文件IO对应的磁盘地址范围0~5，bio1传输的磁盘地址范围6~10，内核会把bio0和bio1传输的磁盘地址范围合并到request，如果再来一个bio2，传输的磁盘地址范围11~15，继续合并到request。
内核这样做的目的为了提高效率，对磁盘地址范围0~15的写，只用对磁盘发送一次写命令，不然就得发送三次写命令。当系统有大量进程写文件时，一个request对应磁盘空间范围可能合并了N多个bio的地址范围，这样写一次比写多次效率提升更明显。
blk_queue_bio->elv_merge对bio进行合并操作，该函数中执行blk_try_merge()尝试将本次的bio合并到上次合并过的request中，合并的规则就是，二者对应的磁盘空间范围是否挨着，否则调用elv调度算法对bio进行合并。
在blk_queue_bio函数最后，会执行__blk_run_queue->blk_run_queue_uncond->scsi_request_fn。（这个调用流程一般不多，fsync场景下__blk_run_queue函数的调用流程是ext4_writepages->blk_finish_plug->blk_flush_plug_list->queue_unplugged->__blk_run_queue）这个流程是触发request IO传输请求给磁盘驱动层，否则就只能等IO队列满了，才会触发request传输。
scsi_request_fn函数中执行cmd->scsi_done = scsi_done，注册磁盘数据传输完成，产生中断执行的回调函数。然后scsi_request_fn函数执行scsi_dispatch_cmd发送SCSI命令给磁盘控制器层，这样就相当于把本次的request IO请求发送给磁盘控制器了。
磁盘控制器应该根据SICI命令解析出本次要传输的文件数据IO相关数据，之后等磁盘控制器把文件数据传输到磁盘后，产生中断，回调scsi_done函数，这个函数执行流程是:
handle_irq->......__handle_irq_event_percpu->megasas_isr_fusion->complete_cmd_fusion->scsi_done->blk_complete_request
在blk_complete_request函数往后流程会触发软中断，最终执行到bio注册的回调函数，最后再把等待文件数据传输完成的进程唤醒，这个函数流程是：
do_softirq->...->blk_done_softirq->scsi_softirq_done->.....bio_endio->ext4_end_bio->ext4_finish_bio->end_page_writeback。
现在把文件IO请求提交给block层，block层再把IO请求提交给磁盘驱动的流程大致讲解过了，下一步就用Systemtap技术在关键函数添加调试信息，看IO 100%忙问题到底是在哪一步出了问题？
我们选择的函数有：bio传输发起函数submit_bio，发起磁盘数据传输函数scsi_request_fn，发送SCSI命令给磁盘控制器函数scsi_dispatch_cmd，磁盘数据传输完成中断回调函数blk_complete_request，唤醒等待文件数据传输完成的进程的end_page_writeback函数。
这些调试信息不能多加也不能少加，多了容易刷屏，少了容易漏掉关键信息，可以用进程名字、进程ID、中断名称限制部分打印，有一定调试技巧。
有些函数的返回值需要打印出来，有些函数的形参也需要打印出来，比如一般会把这些函数涉及到的struct bio、struct gendisk、struct request、struct page、struct request_queue打印出来，这样方便观察一次写入的文件页page，从ext4文件系统层到block层，再到磁盘驱动层的处理细节。
调试信息加好后，开始打印，20多分钟后，总算抓到了异常信息，整理后如下：
[10:08:50]submit_bio nethouse pid:298171 bio:0xffff9777cd34e600 queue:0xffff9770019d9330 cpu:10
[10:08:50]scsi_request_fn nethouse pid:298171 rq queue:0xffff9770019d9330 cpu:10
[10:08:50]scsi_dispatch_cmd nethouse pid:298171 return:0 cpu:10
[10:08:50]wait_on_page_bit nethouse pid:298171 page:0xfffff2f917d96700 bit_nr:13 cpu:10
...................
[10:08:57] blk_complete_request swapper/25 pid:0 req->q:0xffff9770019d9330 req:0xffff977713793900 cpu:25
[10:08:57] end_page_writeback swapper/10 pid:0 page:0xfffff2f917d96700 cpu:10
日志信息很明显，nethouse进程执行wait_on_page_bit后休眠，然后等7s后才执行磁盘数据传输完成产生中断后调用的回调函数blk_complete_request，接着nethouse进程才被唤醒。
难道真的是这7s内没有产生磁盘数据传输完成产生中断？怎么更准确的确认，可以在complete_cmd_fusion函数捕捉打印，还有一个简单的方法，就是执行cat /proc/interrupts查看这7s内磁盘的中断计数。
多方确认后，确定确实没有产生磁盘数据传输完成产生中断。也就是说，这7s，系统写文件的进程休眠的原因，竟然是，它们提交文件传输IO请求后开始休眠，磁盘驱动罢工了，7s后才产生磁盘数据传输完成产生中断，把它们唤醒。
那怪不得iostat监控到这7s内监控到这些进程wMB/s为0，%util 100%的原因是这7s内写文件的进程都休眠了，始终占着IO，看来%util 100%确实说明不了IO忙，还要看其他iostat参数。
6、问题解决
为什么这7s内没有产生磁盘数据传输完成产生中断呢，这可是硬件级别的。我们分析有3种可能：
一种是这7s内发生了关中断的hard lock；
第二种是给磁盘控制器发送SCSI命令的驱动程序没有做好同步，上一个SCSI命令还没有传输完成，就发送了新的SCSI命令，导致磁盘控制器异常；
第三种是磁盘控制器本身出问题，比如磁盘控制器内部忙着处理这20多分钟写入文件的数据，负载均衡，磨损均衡这些的，磁盘控制器内部也有一套复杂的软件处理，搞不好真的是出bug了。
现在有三种怀疑，前两种可以归为软件问题，scsi_request_fn和scsi_dispatch_cmd两个函数嫌疑很大。我们用的内核版本是3.10.0，比较了3.10.1版本内核两个函数的区别，差异还不小，难道3.10.0版本的这两个函数真的有软件bug？要不要向这个方向排查，搞不好又是个不归路？
极度纠结时，我们做了一个实验，在20多分钟内，关闭一部分业务程序，减少文件数据写入，然后等20多分钟时间到，还是会出现IO 100%忙问题，但是IO 100%持续的时间只有1s。这告诉我们一个信息，写入的文件数据多，IO 100%持续的时间就长，因为磁盘控制器处理的文件数据量大，当然时间就长，反之时间就短。
种种怀疑之下，磁盘控制器有问题的可能性最大，询问下服务器供应商，详细描述一下排查的结果，很快得到答复。服务器某部分固件存在这个问题，更新固件后，问题得到解决，这个过程只花了几个小时。
7、总结
我们现在用的磁盘是MegaSAS RAID卡，大体工作原理是，业务程序把文件写入磁盘，是把文件数据写入RAID卡缓存，就认为文件数据写入磁盘了，然后RAID卡控制器在适当时机再把缓存中的文件数据真正写入磁盘，这样可以提高效率。
我们这次出的问题，厂家没有解释清楚，个人估计是每20多分钟，RAID卡控制器忙着处理这段时间写入的文件数据，持续了几秒，处理完后才产生中断。当然RAID卡的缓存写控制策略有WriteBack和WriteThrough，如果没有设置正确，也会导致IO忙问题出现，但不会像本案例这么严重。
IO忙问题还是经常遇到的。个人觉得，用现用的工具解决这类问题很麻烦，如果是偶然出现的IO忙，估计就更头疼了。
在解决本案例时，想过如果能在内核层面开发一个工具，模仿iostat工具，统计进程写文件过程，文件系统层到block层文件数据传输信息，能根据page或者buffer_head结构直接计算出所属文件，并且也能统计IO使用率，设定IO使用率达到某个阈值后就把文件读写信息打印出来，这样对排查偶现的IO忙问题，应该有一定帮助吧。
☆ END ☆
OPPO互联网云平台团队招聘一大波岗位，涵盖Java、容器、Linux内核开发、产品经理、项目经理等多个方向，请在公众号后台回复关键词“云招聘”查看查详细信息。
更多技术干货
扫码关注
OPPO互联网技术