Re: [Regression] ext4: changes to mb_optimize_scan cause issues on Raspberry Pi

[Stefan Wahren <stefan.wahren@i2se.com>]

Hi,

Am 06.08.22 um 17:23 schrieb Stefan Wahren:
> Hi,
>
> Am 31.07.22 um 22:42 schrieb Stefan Wahren:
>> Hi Jan,
>>
>> Am 28.07.22 um 12:00 schrieb Jan Kara:
>>>
>>> Also can get filesystem metadata image of your card like:
>>>    e2image -r <fs-device> - | gzip >/tmp/ext4-image.gz
>>>
>>> and put it somewhere for download? The image will contain only fs 
>>> metadata,
>>> not data so it should be relatively small and we won't have access 
>>> to your
>>> secrets ;). With the image we'd be able to see how the free space looks
>>> like and whether it perhaps does not trigger some pathological 
>>> behavior.
>> i've problems with this. If i try store uncompressed the metadata of 
>> the second SD card partition (/dev/sdb2 = rootfs) the generated image 
>> file is nearly big as the whole partition. In compressed state it's 
>> 25 MB. Is this expected?
>
> This performance regression is also reproducible with 5.19 kernel 
> (arm64, defconfig) and 64-bit Raspberry Pi OS. Unfortunately the 
> problem with metadata generation is the same, the generated 
> uncompressed file is 15 GB.
>
recently i upgraded my build machine (Intel Core i7-1260P) which now 
runs Ubuntu 22.04 including a recent 5.15 kernel. On my build machine if 
i try to install my build kernel modules on the mentioned Industrial 
Kingston SD card 16 GB (SDCIT) and call "sync" immediately, the process 
will takes very long with recent LTS kernel (~ 5 minutes) and trigger a 
hung task warning:

[ 1692.880208] INFO: task sync:22272 blocked for more than 120 seconds.
[ 1692.880222]       Not tainted 5.15.0-46-generic #49-Ubuntu
[ 1692.880225] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" 
disables this message.
[ 1692.880228] task:sync            state:D stack:    0 pid:22272 ppid:  
5238 flags:0x00004002
[ 1692.880237] Call Trace:
[ 1692.880240]  <TASK>
[ 1692.880246]  __schedule+0x23d/0x590
[ 1692.880257]  schedule+0x4e/0xc0
[ 1692.880261]  wb_wait_for_completion+0x59/0x90
[ 1692.880269]  ? wait_woken+0x70/0x70
[ 1692.880275]  sync_inodes_sb+0xbe/0x100
[ 1692.880282]  sync_inodes_one_sb+0x19/0x20
[ 1692.880288]  iterate_supers+0xab/0x110
[ 1692.880294]  ? __x64_sys_tee+0xe0/0xe0
[ 1692.880300]  ksys_sync+0x42/0xa0
[ 1692.880304]  __do_sys_sync+0xe/0x20
[ 1692.880307]  do_syscall_64+0x59/0xc0
[ 1692.880312]  ? do_user_addr_fault+0x1e7/0x670
[ 1692.880319]  ? syscall_exit_to_user_mode+0x27/0x50
[ 1692.880324]  ? exit_to_user_mode_prepare+0x37/0xb0
[ 1692.880331]  ? irqentry_exit_to_user_mode+0x9/0x20
[ 1692.880336]  ? irqentry_exit+0x1d/0x30
[ 1692.880340]  ? exc_page_fault+0x89/0x170
[ 1692.880345]  entry_SYSCALL_64_after_hwframe+0x61/0xcb
[ 1692.880353] RIP: 0033:0x7fcbda436abb
[ 1692.880358] RSP: 002b:00007ffc94923968 EFLAGS: 00000246 ORIG_RAX: 
00000000000000a2
[ 1692.880363] RAX: ffffffffffffffda RBX: 00007ffc94923b48 RCX: 
00007fcbda436abb
[ 1692.880366] RDX: 00007fcbda53c101 RSI: 00007ffc94923b48 RDI: 
00007fcbda4f4e29
[ 1692.880369] RBP: 0000000000000001 R08: 0000000000000001 R09: 
0000000000000000
[ 1692.880371] R10: 000055ca76fb4340 R11: 0000000000000246 R12: 
000055ca752c3bc0
[ 1692.880373] R13: 000055ca752c119f R14: 00007fcbda53442c R15: 
000055ca752c1034
[ 1692.880379]  </TASK>

Interestingly if i switch to the older ubuntu kernel version 5.15.25 
(which shouldn't have "ext4: make mb_optimize_scan performance mount 
option work with extents" applied) the write process is much faster (~ 1 
minute) and i never saw the hung task.

Btw i setup a repo [1] to collect information about this issue. The 
first file adds a kernel log in regression case. The kernel was 5.19-rc6 
with multi_v7_defconfig and ARM_LPAE & EXT4_DEBUG enabled.

rpi-update was started before (backup & clean). The actual download 
started at 11:11:29 and is aborted at 11:14:18.

HTH

[1] - https://github.com/lategoodbye/mb_optimize_scan_regress
[2] - 
https://github.com/lategoodbye/mb_optimize_scan_regress/commit/6ff14dd4026d8607290b2727f5a2c3522567fb21