一个mutex引发的血案——3.10内核 mount -a hung住问题看到的ext4 lazyinit那些坑
原创一个mutex引发的血案——3.10内核 mount -a hung住问题看到的ext4 lazyinit那些坑
原创
johnazhang
修改于 2022-11-02 16:48:15
修改于 2022-11-02 16:48:15
文章被收录于专栏：Linux问题笔记
接到一个问题，反馈D3.16XLARGE256（24块3T本地sata数据盘）机型，3.10内核，在初始化mkfs后mount -a，概率触发mount hung住，需要很长时间（半天左右）才能完成所有盘的挂载，需要排查根因。 本文记录复现场景分析的全过程，发现罪魁祸首源于一个mutex锁，而在高版本内核中对该锁的使用进行了优化，因此TencentOS 5.4内核可以根治这个问题。
复现
首先我们尝试复现问题。
复现方法
脚本mkfs：
#!/bin/sh
count=`ls /dev/ | grep vd|cut -c 1-3|uniq -u |wc -l`
for ((i=1;i<=$count;i++))
do
mkdir /data$i
done
for j in `ls /dev/ | grep vd|cut -c 1-3|uniq -u`
do
echo 'y' | mkfs.ext4 /dev/$j &
done一开始有怀疑和mount -a并行有关，于是脚本串行mount：
i=1
for j in `ls /dev/ | grep -E '^vd' | cut -c 1-3 | grep -v 'vda'`
do
mount /dev/$j /data$i
((++i))
done单机问题表现
mount D住（图分别为mount -a，和串行mount某个盘D住）：
image.png
image.png
堆栈在ext4_register_li_request上：
image.png
大部分时间D住，但没D死，不然也执行不完：
image.png
发现还有一个D进程ext4lazyinit，直觉告诉我就是他导致的问题： 注：ext4lazyinit的机制一句话就可以概括——让mkfs格式化磁盘的io在真正有需要的时候（mount）再去执行
image.png
发现每个盘都有写io：
image.png
结束后，仍然能看到存在ext4lazyinit单独D住的现象，说明ext4lazyinit本身的执行也很慢：
image.png
OS角度
TencentOS Server 3.10内核 , 2 台环境【必现】。 升级到5.4内核问题解决。
使用5.4内核。没有问题。 系统变更到3.10内核，问题【必现】。再升级回5.4问题解决。
到这里，基本能看出来3.10必现，5.4没有问题。
但是两个内核也存在以下共同点： ext4lazyinit会跑很久，大部分时间在D； 机器各盘都会有持续的io；
问题现象角度
存在以下几种复现的情况：
mkfs->mount概率复现
mkfs->mount如果没复现->直接umount必现
mkfs->mount复现后->umount->再mount不复现
mkfs->mount复现后->umount->重新mkfs->再mount复现(或再umount复现)
疑惑
- 3.10 mount为什么会卡慢，为什么5.4不会
- 为什么不是mount必现
- 为什么mount不复现后umount可以复现
- ext4lazyinit慢是否正常，为什么慢 下面会尝试解答这些疑问。
分析
是谁拖慢了mount？
在复现的现场，多来几次live crash大法，答案显而易见，凶手呼之欲出。 截取其中一次分析为例：
crash> ps -l | grep UN
[5241570371969] [UN] PID: 25036 TASK: ffff883ed30b8000 CPU: 0 COMMAND: "jbd2/vdl-8"
[5241560582065] [UN] PID: 24623 TASK: ffff881f8db1b3a0 CPU: 0 COMMAND: "ext4lazyinit"
[5241365143847] [UN] PID: 25759 TASK: ffff881f8c7019d0 CPU: 10 COMMAND: "mount"
crash> bt ffff881f8c7019d0 -z
PID: 25759 TASK: ffff881f8c7019d0 CPU: 10 COMMAND: "mount"
#0 [ffff881f7d807b70] __schedule () at ffffffff819d023e
#1 [ffff881f7d807bd8] schedule_preempt_disabled () at ffffffff819d1659
#2 [ffff881f7d807be8] __mutex_lock_slowpath (atomic_t * arg0= ffff881ea9af3658) at ffffffff819cf7c1
#3 [ffff881f7d807c48] mutex_lock (struct mutex * arg0= ffff881ea9af3658) at ffffffff819cf13f
#4 [ffff881f7d807c60] ext4_register_li_request (struct super_block * arg0= ffff883f5ee88000, ext4_group_t arg1= 0000000000000000) at ffffffff812586d4
#5 [ffff881f7d807ca8] ext4_fill_super (struct super_block * arg0= ffff883f5ee88000, void * arg1= 0000000000000000, int arg2= 0000000000000000) at ffffffff8125bf24
bt: invalid size request: -1 type: "read stack arg"
#6 [ffff881f7d807dc8] mount_bdev (struct file_system_type * arg0= ffffffff81f80880, int arg1= 0000000000000000, const char * arg2= ffffffff81f80880, void * arg3= 0000000000000000, int (*)(struct super_block * arg4= ffffffff812592d0, void * arg5= ffff883f620c5ba0, int) arg6= 0000000000000000) at ffffffff8118f8b8
#7 [ffff881f7d807e38] ext4_mount (struct file_system_type * arg0= ffffffff81f80880, int arg1= 0000000000000000, const char * arg2= ffffffff81f80880, void * arg3= 0000000000000000) at ffffffff8124f155
#8 [ffff881f7d807e48] mount_fs (struct file_system_type * arg0= ffffffff81f80880, int arg1= 0000000000000000, const char * arg2= ffff883f620c5ba0, void * arg3= 0000000000000000) at ffffffff81190255
#9 [ffff881f7d807e70] vfs_kern_mount (struct file_system_type * arg0= ffffffff81f80880, int arg1= 0000000000000000, const char * arg2= ffff883f620c5ba0, void * arg3= 0000000000000000) at ffffffff811aa84f
#10 [ffff881f7d807ea8] do_mount (const char * arg0= ffff883f620c5ba0, const char * arg1= ffff881f8f163020, const char * arg2= ffff883f5c8a3c98, unsigned long arg3= 00000000c0ed0000, void * arg4= 0000000000000000) at ffffffff811acced
#11 [ffff881f7d807f28] sys_mount () at ffffffff811ad616
#12 [ffff881f7d807f80] system_call_fastpath () at ffffffff81aab479
RIP: 00007f6230ac915a RSP: 00007ffe5419e0e8 RFLAGS: 00010246
RAX: 00000000000000a5 RBX: ffffffff81aab479 RCX: 0000000000000010
RDX: 00007f6233904600 RSI: 00007f6233902230 RDI: 00007f6233902140
RBP: 0000000000000000 R8: 0000000000000000 R9: 0000000000000010
R10: 00000000c0ed0000 R11: 0000000000000206 R12: 00007f6233902040
R13: 0000000000000000 R14: 00007f6233904600 R15: 00007f6233902140
ORIG_RAX: 00000000000000a5 CS: 0033 SS: 002b
crash> mutex ffff881ea9af3658
struct mutex {
count = {
counter = -1
},
wait_lock = {
{
rlock = {
raw_lock = {
lock = 0 '\000',
spinners = 0 '\000'
}
}
}
},
wait_list = {
next = 0xffff881f7d807bf0,
prev = 0xffff881f7d807bf0
},
owner = 0xffff881f8db1b3a0,
spin_mlock = 0x0
}
crash> bt 0xffff881f8db1b3a0
PID: 24623 TASK: ffff881f8db1b3a0 CPU: 0 COMMAND: "ext4lazyinit"
#0 [ffff881f7dddbb70] __schedule at ffffffff819d023e
#1 [ffff881f7dddbbd8] schedule at ffffffff819d0789
#2 [ffff881f7dddbbe8] schedule_timeout at ffffffff819cecc9
#3 [ffff881f7dddbc78] io_schedule_timeout at ffffffff819cff6b
#4 [ffff881f7dddbca8] wait_for_completion_io at ffffffff819d0e97
#5 [ffff881f7dddbd08] __blkdev_issue_zeroout at ffffffff812fa722
#6 [ffff881f7dddbd90] blkdev_issue_zeroout at ffffffff812fa819
#7 [ffff881f7dddbde8] ext4_init_inode_table at ffffffff81236140
#8 [ffff881f7dddbe60] ext4_lazyinit_thread at ffffffff8124f0c5
#9 [ffff881f7dddbec8] kthread at ffffffff8107366f
#10 [ffff881f7dddbf50] ret_from_fork at ffffffff81aab3c8逻辑非常简单，mount在等mutex，mutex被ext4lazyinit持有。 从堆栈看，我们推测事情的原委是这样的：
image.png
如何证明？
crash> bt 0xffff881f8db1b3a0 -z
PID: 24623 TASK: ffff881f8db1b3a0 CPU: 0 COMMAND: "ext4lazyinit"
#0 [ffff881f7dddbb70] __schedule () at ffffffff819d023e
#1 [ffff881f7dddbbd8] schedule () at ffffffff819d0789
#2 [ffff881f7dddbbe8] schedule_timeout (long arg0= 7fffffffffffffff) at ffffffff819cecc9
#3 [ffff881f7dddbc78] io_schedule_timeout (long arg0= 7fffffffffffffff) at ffffffff819cff6b
#4 [ffff881f7dddbca8] wait_for_completion_io (struct completion * arg0= ffff881f7dddbd38) at ffffffff819d0e97
#5 [ffff881f7dddbd08] __blkdev_issue_zeroout (struct block_device * arg0= ffff881f8ac88000, sector_t arg1= 000000003e806100, sector_t arg2= 0000000000001000, gfp_t arg3= 0000000000000000) at ffffffff812fa722
#6 [ffff881f7dddbd90] blkdev_issue_zeroout (struct block_device * arg0= ffff881f8ac88000, sector_t arg1= 00000000deadbeef, sector_t arg2= 00000000deadbeef, gfp_t arg3= 0000000000000050) at ffffffff812fa819
#7 [ffff881f7dddbde8] ext4_init_inode_table (struct super_block * arg0= ffff883f59fee800, ext4_group_t arg1= 0000000000000fa6, int arg2= 0000000000000000) at ffffffff81236140
#8 [ffff881f7dddbe60] ext4_lazyinit_thread (void * arg0= ffff881ea9af3640) at ffffffff8124f0c5
#9 [ffff881f7dddbec8] kthread (void * arg0= ffff881eecd23bc8) at ffffffff8107366f
#10 [ffff881f7dddbf50] ret_from_fork () at ffffffff81aab3c8
crash> ext4_lazy_init.li_list_mtx ffff881ea9af3640 -o
struct ext4_lazy_init {
[ffff881ea9af3658] struct mutex li_list_mtx;
}可以看到，ffff881ea9af3658这个地址就是mount持有的锁，至此案情已经初步侦破。
为什么ext4lazyinit这么慢？
从堆栈上看，是ext4lazyinit在等io完成：
image.png
结合代码，大概能猜到，ext4lazyinit是在随机init block group。 从live crash里每次都在写不同的盘也可以看出，还是以上面那次live crash为例：
crash> mount ffff883f59fee800
MOUNT SUPERBLK TYPE DEVNAME DIRNAME
ffff881f9312ef00 ffff883f59fee800 ext4 /dev/vdk /data9 可以看出这次是在vdk上做io，那么下次live crash可能是vdh、vdl或者其他的什么盘。 这也和我们抓到的iostat能够对上：
image.png
看一下文件系统的sb数据，能够跟进一步想明白很多东西。
Filesystem volume name: <none>
Last mounted on: /data1
Filesystem UUID: df1059f6-db77-45c0-b2be-be04291d574f
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index filetype needs_recovery extent 64bit flex_bg sparse_super large_file huge_fi
le uninit_bg dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: user_xattr acl
Filesystem state: clean
Errors behavior: Continue
Filesystem OS type: Linux
Inode count: 244195328
Block count: 976754646
Reserved block count: 48837732
Free blocks: 961367244
Free inodes: 244195317
First block: 0
Block size: 4096
Fragment size: 4096
Group descriptor size: 64
Reserved GDT blocks: 1024
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
Flex block group size: 16
Filesystem created: Thu Mar 17 20:30:19 2022
Last mount time: Thu Mar 17 20:33:56 2022
Last write time: Thu Mar 17 20:33:56 2022
Mount count: 1
Maximum mount count: -1
Last checked: Thu Mar 17 20:30:19 2022
Check interval: 0 (<none>)
Lifetime writes: 140 MB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
Default directory hash: half_md4
Directory Hash Seed: 3ba85377-6c71-46c3-9e90-ced666fd58d6
Journal backup: inode blocks
Directories: 2这里我们可以粗略算一下，一块盘需要init 的group count约为（Block count）/ （Blocks per group）= (976754646/32768) 越等于29808。 （Inodes per group） （Inode size） （group count）= 8192 256 29808 = 61046784 kb 60G的无规律（对磁盘而言）写，是一个非常大的数字了。
至此我猜测ext4lazyinit很慢其实符合预期？毕竟要去随机init这么一大堆东西。 而且这种磁盘几乎随机位置的写，os层面io调度貌似也没有什么好办法去拯救，对此我进一步验证了一把切换io调度器的效果，事实符合预期，无论换deadline还是cfq对ext4lazyinit慢的现象并没有任何改善。
数据说话
前面的说到底都是观察所得，还不够实锤。那么可能之前看过我文章的朋友们都知道接下来我又要祭出内核分析三板斧其二的systemtap去trace内核了（其实更主要的原因是，3.10用不了bcc）。 trace主要是要证明两件事：
- mount真的是被li_list_mtx锁住
- ext4lazyinit真的很慢
注1：为什么要证明mount被哪个锁锁住？
阅读代码可以发现，mount的这条路径上是要等两个mutex：
image.png
其中第一个锁ext4_li_mtx是全局锁，并发mount会受到该锁的影响。
其实我们的测试用例中，已经通过顺序mount证明了不是并发mount的影响，但是毕竟靠读代码得出来的理解很可能存在偏差，只有实践出真知。
注2:live crash看到的ext4lazyinit堆栈是否是真正的瓶颈？
为了确保去trace瓶颈，在复现的时候同时perf抓取一把可以看到：
image.png
submit_bio的尽头是blk_queue_bio，那么到底是等io本身慢还是有其他的可能，也只能用trace来证明了。
trace脚本
global t1, t2, t3
global h1, h2, h3
global c1, c2, c3
global lazy_li_list_mtx
global mount_li_list_mtx
global mount_ext4_li_mtx
global nr_sects_cnt
#这里是给三个地方拿锁计数，mount的两个锁和lazyinit拿锁
probe kernel.statement("*@fs/ext4/super.c: 2858")
{
lazy_li_list_mtx += 1
}
probe kernel.statement("*@fs/ext4/super.c: 3030")
{
mount_ext4_li_mtx += 1
}
probe kernel.statement("*@fs/ext4/super.c: 3057")
{
mount_li_list_mtx += 1
}
probe kernel.function("ext4_init_inode_table")
{
c1 += 1
t1 = gettimeofday_us()
}
probe kernel.function("ext4_init_inode_table").return
{
h1 <<< gettimeofday_us() - t1
}
probe kernel.function("__blkdev_issue_zeroout")
{
c2 += 1
t2 = gettimeofday_us()
nr_sects_cnt <<< $nr_sects
}
probe kernel.function("__blkdev_issue_zeroout").return
{
h2 <<< gettimeofday_us() - t2
}
probe kernel.function("blk_queue_bio")
{
c3 += 1
t3 = gettimeofday_us()
}
probe kernel.function("blk_queue_bio").return
{
h3 <<< gettimeofday_us() - t3
}
probe timer.s(3)
{
printf("### lazyinit eli->li_list_mtx mutex locked %d times\n\n", lazy_li_list_mtx)
lazy_li_list_mtx = 0
printf("### mount ext4_li_mtx mutex locked %d times\n\n", mount_ext4_li_mtx)
mount_ext4_li_mtx = 0
printf("### mount ext4_li_info->li_list_mtx) mutex locked %d times\n\n", mount_li_list_mtx)
mount_li_list_mtx = 0
print("### ext4_init_inode_table ###\n")
print(c1)
print("\n")
c1 = 0
if(@count(h1))
{
print(@hist_log(h1))
delete h1
}
print("### __blkdev_issue_zeroout ###\n")
print(c2)
print("\n")
c2 = 0
if(@count(h2))
{
print(@hist_log(h2))
delete h2
}
print("### __blkdev_issue_zeroout nr_sects ###\n")
if(@count(nr_sects_cnt))
{
print(@hist_log(nr_sects_cnt))
delete nr_sects_cnt
}
print("### blk_queue_bio ###\n")
print(c3)
print("\n")
c3 = 0
if(@count(h3))
{
print(@hist_log(h3))
delete h3
}
}trace数据
复现时的raw data如下，又臭又长不用看：
### lazyinit eli->li_list_mtx mutex locked 1 times
### mount ext4_li_mtx mutex locked 5 times
### mount ext4_li_info->li_list_mtx) mutex locked 5 times
### ext4_init_inode_table ###
0
### __blkdev_issue_zeroout ###
0
### blk_queue_bio ###
3977
value |-------------------------------------------------- count
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1078
1 |@@@@@@@@@@@@@ 502
2 |@ 61
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1838
8 | 8
16 |@@@@@@@@@@@@@ 487
32 | 3
64 | 0
128 | 0
### lazyinit eli->li_list_mtx mutex locked 44 times
### mount ext4_li_mtx mutex locked 7 times
### mount ext4_li_info->li_list_mtx) mutex locked 7 times
### ext4_init_inode_table ###
62
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
16384 |@@@@@@@@@@@@@@@@@@@ 19
32768 |@@@@ 4
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
62
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
16384 |@@@@@@@@@@@@@@@@@@@ 19
32768 |@@@@ 4
65536 | 0
131072 | 0
### blk_queue_bio ###
5528
value |-------------------------------------------------- count
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1286
1 |@@@@@@@@@@@@@@@@ 576
2 |@@@@@@ 218
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1592
8 |@ 50
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1714
32 |@@ 72
64 | 20
128 | 0
256 | 0
### lazyinit eli->li_list_mtx mutex locked 29 times
### mount ext4_li_mtx mutex locked 3 times
### mount ext4_li_info->li_list_mtx) mutex locked 3 times
### ext4_init_inode_table ###
143
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 58
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 73
32768 |@@@@@ 11
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
143
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 58
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 73
32768 |@@@@@ 11
65536 | 0
131072 | 0
### blk_queue_bio ###
2616
value |-------------------------------------------------- count
0 |@@@@@@@@@@@@@@@@ 392
1 |@@@@@@@@@ 239
2 |@@@@@@@@@@@@ 291
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1195
8 |@@@@ 106
16 |@@@@@@@@@ 216
32 |@@@@@ 136
64 |@ 41
128 | 0
256 | 0
### lazyinit eli->li_list_mtx mutex locked 12 times
### mount ext4_li_mtx mutex locked 0 times
### mount ext4_li_info->li_list_mtx) mutex locked 0 times
### ext4_init_inode_table ###
141
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@ 43
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 86
32768 |@@@@@@ 12
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
141
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@ 43
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 86
32768 |@@@@@@ 12
65536 | 0
131072 | 0
### blk_queue_bio ###
818
value |-------------------------------------------------- count
0 |@@@@@@@@@@ 64
1 |@@@@@@@@@@@@@@@@@@@@@ 126
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 291
4 |@@@@@@@@@@@ 71
8 |@@@@@@@@@@ 63
16 |@@@@@@@ 43
32 |@@@@@@@@@@@@@@@@@@@@ 123
64 |@@@@@@ 37
128 | 0
256 | 0
### lazyinit eli->li_list_mtx mutex locked 9 times
### mount ext4_li_mtx mutex locked 0 times
### mount ext4_li_info->li_list_mtx) mutex locked 0 times
### ext4_init_inode_table ###
127
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@ 18
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 98
32768 |@@@@@ 11
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
127
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@ 18
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 98
32768 |@@@@@ 11
65536 | 0
131072 | 0
### blk_queue_bio ###
676
value |-------------------------------------------------- count
0 |@@@@ 26
1 |@@@@@@@@@@@@@@@@ 100
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 275
4 |@@@@@@@@@ 57
8 |@@@@@@@@@@@ 71
16 |@@@@@ 30
32 |@@@@@@@@@@@@@@ 89
64 |@@@@ 28
128 | 0
256 | 0数据分析
从上面的数据，提炼出几个结论
证明mount确实在等ext4lazyinit释放li_list_mtx锁
论据：
### lazyinit eli->li_list_mtx mutex locked 44 times
### mount ext4_li_mtx mutex locked 7 times
### mount ext4_li_info->li_list_mtx) mutex locked 7 times可以看到在一个时间周期内，mount获取ext4_li_mtx和li_list_mtx锁的次数是一样的，也就是获取完ext4_li_mtx就可以获取到li_list_mtx，说明瓶颈是li_list_mtx。
而lazyinit获取li_list_mtx的次数远大于mount，说明lazyinit本身也更容易抢到这个锁。
- ext4lazyinit慢的瓶颈不是在ext4lazyinit的代码本身，而是等待io上 论据：
image.png
ext4lazyinit不是一开始就慢，而是跑了一会才变慢
论据：
开始的trace：
### lazyinit eli->li_list_mtx mutex locked 44 times
### mount ext4_li_mtx mutex locked 7 times
### mount ext4_li_info->li_list_mtx) mutex locked 7 times
### ext4_init_inode_table ###
62
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
16384 |@@@@@@@@@@@@@@@@@@@ 19
32768 |@@@@ 4
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
62
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 39
16384 |@@@@@@@@@@@@@@@@@@@ 19
32768 |@@@@ 4
65536 | 0
131072 | 0
### blk_queue_bio ###
5528
value |-------------------------------------------------- count
0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1286
1 |@@@@@@@@@@@@@@@@ 576
2 |@@@@@@ 218
4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1592
8 |@ 50
16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1714
32 |@@ 72
64 | 20
128 | 0
256 | 0慢下来后的trace：
### lazyinit eli->li_list_mtx mutex locked 12 times
### mount ext4_li_mtx mutex locked 0 times
### mount ext4_li_info->li_list_mtx) mutex locked 0 times
### ext4_init_inode_table ###
141
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@ 43
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 86
32768 |@@@@@@ 12
65536 | 0
131072 | 0
### __blkdev_issue_zeroout ###
141
value |-------------------------------------------------- count
2048 | 0
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@ 43
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 86
32768 |@@@@@@ 12
65536 | 0
131072 | 0
### blk_queue_bio ###
818
value |-------------------------------------------------- count
0 |@@@@@@@@@@ 64
1 |@@@@@@@@@@@@@@@@@@@@@ 126
2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 291
4 |@@@@@@@@@@@ 71
8 |@@@@@@@@@@ 63
16 |@@@@@@@ 43
32 |@@@@@@@@@@@@@@@@@@@@ 123
64 |@@@@@@ 37
128 | 0
256 | 0可以看到，如同上面2中的计算方法，ext4lazyinit刚开始时，等待io的时间没有那么长，而随着时间的推移，io处理变慢（这里为什么会变慢我觉得不单单是因为随机位置写盘导致的寻址等延迟，后续有时间还需进一步深挖下），queue bio的频率也变低。
有了这个发现后，我多测试了几次，意料之外情理之中的发现了mount没卡住的时候都还处在ext4lazyinit比较快的阶段，一旦进入了比较慢的阶段，mount抢不到锁，就寄了，慢慢等吧。
拿到io延迟数据
从上面的分析来看，要证明ext4lazyinit的瓶颈，最直观的办法还是直接看io延迟。 由于3.10不支持bcc，没办法用biolat直观的看看io延迟，只能自己动手丰衣足食了。
一个极简的systemtap biolat脚本：
global map, dist, req_cnt
probe kernel.function("blk_start_request")
{
map[$req] = gettimeofday_us()
req_cnt += 1
}
probe kernel.function("blk_finish_request")
{
if( [$req] in map )
{
dist <<< gettimeofday_us() - map[$req]
delete map[$req]
}
}
probe timer.s(3)
{
print("##################################\n")
printf("req num is %d\n", req_cnt)
req_cnt = 0
if(@count(dist))
{
print(@hist_log(dist))
delete dist
}
}对比上一小节中的第3个结论，可以拿到，刚开始ext4lazyinit时的request数量明显更大，延迟更低：
##################################
req num is 9832
value |-------------------------------------------------- count
4 | 0
8 | 0
16 | 4
32 | 82
64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 8187
128 |@@@@@ 982
256 |@ 171
512 | 139
1024 | 83
2048 | 4
4096 | 20
8192 | 27
16384 | 43
32768 | 84
65536 | 0
131072 | 03s内完成了快1w个request，延迟大多在64-128us之间。
而ext4lazyinit慢下来，表现为大部分时间D住时：
##################################
req num is 551
value |-------------------------------------------------- count
4 | 0
8 | 0
16 | 1
32 | 5
64 | 0
128 | 0
256 | 2
512 | 1
1024 | 0
2048 | 3
4096 | 2
8192 |@@@@@@@@@@@@ 85
16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 308
32768 |@@@@@@@@@@@@@@@@@@@ 134
65536 |@ 10
131072 | 0
262144 | 3s内只完成了500个request，且大部分延迟在16ms-32ms。 至此，可以确认ext4lazyinit是由快到慢的，而这中间只有不到10s的过程（统计脚本是3s一个周期，可以观察到3个周期左右会变慢，要求证的话可以回去看看raw data），后面就一直慢了。
umount复现
image.png
对于mount完成的机器，直接umount也会复现，想必经过上面的分析，原因已经很明确了： umount也需要获取li_list_mtx（live crash同样可以看到，此处不再放上crash推导），而ext4lazyinit由于已经进入了比较慢的状态，导致umount很难获取到锁，从而表现为卡慢。
优秀的5.4内核
首先需要澄清的是，5.4的ext4lazyinit一样很慢，即使io调度默认更换为了mq-deadline也并不能改变什么。
注：笔者浅显的理解是，这是一个ext4的缺陷，要去随机init所有group，对于盘比较大的场景就不太适用；相比之下xfs按需分配ag的策略理论上应该能优化这个问题，测了一下，果然如此（此处原谅笔者时间精力有限，没再去回过头来测一把两个文件系统的每一步的详细耗时对比）。
而5.4 mount不会卡住的原因，答案就在代码里：
image.png
不去拿这个锁，也就从根源上规避了这个问题。
解惑
现在回头，可以把之前的疑惑一一解答下了。
1）3.10 mount为什么会卡慢，为什么5.4不会
5.4的ext4lazyinit在init inode table时优化掉了li_list_mtx锁，从而不会因为ext4lazyinit慢而阻塞mount。
2）ext4lazyinit慢是否正常，为什么慢
无法定义他到底是否“正常”，可能是这个机制本身的缺陷。可以确定的是，他在3.10和5.4上都很慢；他会经历一个很快的开始，等这个快的阶段过去后，后面就一直很慢；慢的原因是在等io完成，目前怀疑跟盘太大，随机位置写，来回寻址路径太长导致的。
3） 为什么不是mount必现
mount只要侥幸在ext4lazyinit比较快的启动阶段成功执行完了（抢24次锁），就不会卡死。
4 为什么mount不复现后umount可以复现
mount完成后，ext4lazyinit还处在慢慢写，大部分时间D的状态，这时候如果umount还是很难能够抢到锁，因此很慢，问题复现。
结局
至此，这个问题的根治方案是切换5.4，又一个case再次证明了5.4的优秀是3.10所不能及的。
不过如果不切5.4，也有规避方案。
- 在mkfs的时候使用：mkfs.ext4 -E lazy_itable_init=0,lazy_journal_init=0来关掉lazyinit功能能够规避问题，虽然会导致mfs本身变得很慢，但不会出现mount一下午的情况。
- 使用xfs，原因参考"优秀的5.4内核"中开头的注解部分。
// 由于本人对文件系统的理解尚浅，ext4lazyinit机制的详解比如为什么这么慢，锁为什么会被优化掉，就不再多班门弄斧了，留给文件系统大佬来解答。另外如有说的不对/不到位的地方欢迎拍砖。
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。
评论
登录后参与评论
推荐阅读
目录
相关产品与服务
云服务器
云服务器（Cloud Virtual Machine，CVM）提供安全可靠的弹性计算服务。 您可以实时扩展或缩减计算资源，适应变化的业务需求，并只需按实际使用的资源计费。使用 CVM 可以极大降低您的软硬件采购成本，简化 IT 运维工作。
腾讯云开发者
