看Linux内核前辈解Bug你会有什么感想

2021年11月20日 阅读数:1
这篇文章主要向大家介绍看Linux内核前辈解Bug你会有什么感想,主要内容包括基础应用、实用技巧、原理机制等方面,希望对大家有所帮助。

一名叫John Garry的人给Linux内核社区上报了一个bug, 说有人升级内核到V5.10-rcX以后,执行dd和sync以后看到进程有hang住的状况:
git


Some guys internally upgraded to v5.10-rcX and start to see a hang after 
dd + sync for a large file:
- mount /dev/sda1 (ext4 filesystem) to directory /mnt;
- run "if=/dev/zero of=test1 bs=1M count=2000" on directory /mnt;
- run "sync"


系统提示打印hang住进程的堆栈信息:web

and get:

[  367.912761] INFO: task jbd2/sdb1-8:3602 blocked for more than 120
seconds.
[  367.919618]       Not tainted 5.10.0-rc1-109488-g32ded76956b6 #948
[  367.925776"echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  367.933579] task:jbd2/sdb1-8     state:D stack:    0 pid: 3602
ppid:     2 flags:0x00000028
[  367.941901] Call trace:
[  367.944351] __switch_to+0xb8/0x168
[  367.947840] __schedule+0x30c/0x670
[  367.951326] schedule+0x70/0x108
[  367.954550] io_schedule+0x1c/0xe8
[  367.957948] bit_wait_io+0x18/0x68
[  367.961346] __wait_on_bit+0x78/0xf0
[  367.964919] out_of_line_wait_on_bit+0x8c/0xb0
[  367.969356] __wait_on_buffer+0x30/0x40
[  367.973188] jbd2_journal_commit_transaction+0x1370/0x1958
[  367.978661] kjournald2+0xcc/0x260
[  367.982061] kthread+0x150/0x158
[  367.985288] ret_from_fork+0x10/0x34
[  367.988860] INFO: task sync:3823 blocked for more than 120 seconds.
[  367.995102]       Not tainted 5.10.0-rc1-109488-g32ded76956b6 #948
[  368.001265"echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  368.009067] task:sync            state:D stack:    0 pid: 3823 ppid:
3450 flags:0x00000009
[  368.017397] Call trace:
[  368.019841] __switch_to+0xb8/0x168
[  368.023320] __schedule+0x30c/0x670
[  368.026804] schedule+0x70/0x108
[  368.030025] jbd2_log_wait_commit+0xbc/0x158
[  368.034290] ext4_sync_fs+0x188/0x1c8
[  368.037947] sync_fs_one_sb+0x30/0x40
[  368.041606] iterate_supers+0x9c/0x138
[  368.045350] ksys_sync+0x64/0xc0
[  368.048569] __arm64_sys_sync+0x10/0x20
[  368.052398] el0_svc_common.constprop.3+0x68/0x170
[  368.057177] do_el0_svc+0x24/0x90
[  368.060482] el0_sync_handler+0x118/0x168
[  368.064478]  el0_sync+0x158/0x180


并反馈8号硬队列绑定的第100号cpu上派发队列和完成队列不一致,可是没有inflight的状况,由于这个状况,苦恼了三天三夜,头发掉满了整个键盘。微信


estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu100/dispatched
3 0
estuary:/sys/kernel/debug/block/sda/hctx8$ cat cpu100/completed
2 0
On cpu100, it seems completed is less than number dispatched.

/sys/devices/pci0000:74/0000:74:02.0/host0/port-0:0/end_device-0:0/target0:0:0/0:0:0:0/block/sda/sda1/inflight), 
the number of inflight is 0.


而后Ming Lei (自带音响出场)给出意见,须要收集/sys/kernel/debug/block/sda 目录和/sys/block/sda/device  目录下全部文件的输出:app

hello chenxiang, Can you collect the debugfs log via the following commands after the io
hang is triggered?

1) debugfs log:

        (cd /sys/kernel/debug/block/sda && find . -type f -exec grep -aH . {} \;)

2) scsi sysfs info:

        (cd /sys/block/sda/device && find . -type f -exec grep -aH . {} \;)

Suppose the disk is /dev/sda.


chenxiang 反馈:
~$ cd /sys/kernel/debug/block/sdb && find . -type f -exec grep 
-aH . {} \;
...
./hctx9/tags:cleared=3891
./hctx9/tags:bits_per_word=64
./hctx9/tags:map_nr=63
./hctx9/tags:alloc_hint={3264, 3265, 0, 3731, 2462, 842, 0, 0, 1278, 27, 
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 2424, 0, 0, 0, 
346, 3, 3191, 235, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 88, 0, 0, 285, 0, 0, 0, 0, 0, 0, 0, 0, 0, 
0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 1165, 538, 0, 
372, 277, 3476, 0, 0, 0, 111, 0, 2081, 0, 112, 0, 0, 0, 0, 904, 1127, 0, 
0, 0, 113, 0, 0, 0, 0, 0, 0, 321, 0}
./hctx9/tags:wake_batch=8
./hctx9/tags:wake_index=7
./hctx9/tags:ws_active=0
./hctx9/tags:ws={
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:   {.wait_cnt=8, .wait=inactive},
./hctx9/tags:}
./hctx9/tags:round_robin=1
./hctx9/tags:min_shallow_depth=4294967295
./hctx9/ctx_map:00000000: 00
...


Ming Lei 大神看了一下debug输出,小喝一杯大红袍,就直接建议去测试这个patch:less

Please try the following patch:

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 60c7a7d74852..03c6d0620bfd 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1703,8 +1703,7 @@ static blk_status_t scsi_queue_rq(struct blk_mq_hw_ctx *hctx,
         break;
     case BLK_STS_RESOURCE:
     case BLK_STS_ZONE_RESOURCE:
-        if (atomic_read(&sdev->device_busy)
 ||
-            scsi_device_blocked(sdev))
+        if (scsi_device_blocked(sdev))
             ret 
= BLK_STS_DEV_RESOURCE;
         break;
     default:


chenxiang 测试反馈之后,问题解决,心里洋溢着Linux从业者单纯的喜悦,眼神中流露出满满的崇敬之情,巴不得以身相许:
I have tested the patch  100times on two envirments(on which the issue 
occurs frequently before)
and
the issue doesn't occur.


这样问题就解决了,我想若是是小编处理这个问题,我会要他触发一下crash,而后再慢慢分析,真是low了几百个 levels :)测试


正是只凭借这些debug信息,准确分析问题所在,才能体现出对block子系统的专业性,坐稳在这个子系统中的地位。this

如此熟练掌握一个子系统,真不易!atom

(详情阅读原文)spa

--The end---
.net


本文分享自微信公众号 - 相遇Linux(LinuxJeff)。
若有侵权,请联系 support@oschina.cn 删除。
本文参与“OSC源创计划”,欢迎正在阅读的你也加入,一块儿分享。