Hello,
kernel test robot noticed "INFO:task_blocked_for_more_than#seconds" on:
commit: 96cfeb0389530ae32ade8a48ae3ae1ac3b6c009d ("f2fs: fix to wait dio completion")
https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git fs-next
[test failed on linux-next/master 1ca4237ad9ce29b0c66fe87862f1da54ac56a1e8]
in testcase: ltp
version: ltp-x86_64-14c1f76-1_20240824
with following parameters:
disk: 1HDD
fs: f2fs
test: ltp-aiodio.part4-01
compiler: gcc-12
test machine: 36 threads 1 sockets Intel(R) Core(TM) i9-10980XE CPU @ 3.00GHz (Cascade Lake) with 128G memory
(please refer to attached dmesg/kmsg for entire log/backtrace)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202408271015.5b4de2c5-oliver.sang@xxxxxxxxx
kern :err : [ 1975.160382] INFO: task dio_truncate:7499 blocked for more than 491 seconds.
kern :err : [ 1975.162291] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 1975.163937] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 1975.165896] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 1975.168012] Call Trace:
kern :info : [ 1975.169513] <TASK>
kern :info : [ 1975.170940] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 1975.172569] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 1975.174128] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 1975.175713] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 1975.177213] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 1975.178732] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 1975.180360] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 1975.181888] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 1975.183478] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 1975.185017] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 1975.186637] notify_change (fs/attr.c:495)
kern :info : [ 1975.188160] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 1975.189645] ? do_truncate (fs/open.c:66)
kern :info : [ 1975.191087] do_truncate (fs/open.c:66)
kern :info : [ 1975.192582] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 1975.194037] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 1975.195518] vfs_truncate (fs/open.c:111)
kern :info : [ 1975.196955] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 1975.198393] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 1975.199920] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 1975.201350] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 1975.202723] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 1975.204281] RIP: 0033:0x7fb415adaf17
kern :info : [ 1975.205651] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 1975.207385] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 1975.209091] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 1975.210765] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 1975.212511] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 1975.214171] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 1975.215872] </TASK>
kern :err : [ 2466.680277] INFO: task dio_truncate:7499 blocked for more than 983 seconds.
kern :err : [ 2466.682130] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 2466.683485] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 2466.685152] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 2466.686743] Call Trace:
kern :info : [ 2466.687916] <TASK>
kern :info : [ 2466.689140] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 2466.690254] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 2466.691533] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 2466.692815] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 2466.694022] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 2466.695258] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 2466.696491] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 2466.697829] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 2466.699156] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 2466.700333] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 2466.701756] notify_change (fs/attr.c:495)
kern :info : [ 2466.702975] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 2466.704241] ? do_truncate (fs/open.c:66)
kern :info : [ 2466.705436] do_truncate (fs/open.c:66)
kern :info : [ 2466.706641] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 2466.707775] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 2466.709133] vfs_truncate (fs/open.c:111)
kern :info : [ 2466.710229] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 2466.711485] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 2466.712728] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 2466.714005] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 2466.715220] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 2466.716486] RIP: 0033:0x7fb415adaf17
kern :info : [ 2466.717758] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 2466.719330] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 2466.720811] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 2466.722359] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 2466.723766] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 2466.725408] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 2466.726816] </TASK>
kern :err : [ 2958.200311] INFO: task dio_truncate:7499 blocked for more than 1474 seconds.
kern :err : [ 2958.202114] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 2958.203466] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 2958.205053] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 2958.206833] Call Trace:
kern :info : [ 2958.207970] <TASK>
kern :info : [ 2958.209063] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 2958.210370] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 2958.211614] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 2958.212856] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 2958.214029] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 2958.215341] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 2958.216584] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 2958.217788] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 2958.219114] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 2958.220297] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 2958.221567] notify_change (fs/attr.c:495)
kern :info : [ 2958.222775] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 2958.223964] ? do_truncate (fs/open.c:66)
kern :info : [ 2958.225108] do_truncate (fs/open.c:66)
kern :info : [ 2958.226262] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 2958.227498] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 2958.228670] vfs_truncate (fs/open.c:111)
kern :info : [ 2958.229803] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 2958.231062] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 2958.232296] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 2958.233460] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 2958.234650] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 2958.235930] RIP: 0033:0x7fb415adaf17
kern :info : [ 2958.237063] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 2958.238601] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 2958.240081] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 2958.241545] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 2958.243099] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 2958.244574] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 2958.246040] </TASK>
kern :err : [ 3449.721200] INFO: task dio_truncate:7499 blocked for more than 1966 seconds.
kern :err : [ 3449.722637] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 3449.724151] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 3449.725677] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 3449.727394] Call Trace:
kern :info : [ 3449.728500] <TASK>
kern :info : [ 3449.729661] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 3449.730915] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 3449.732183] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 3449.733409] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 3449.734677] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 3449.735922] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 3449.737184] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 3449.738465] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 3449.739717] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 3449.740912] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 3449.742231] notify_change (fs/attr.c:495)
kern :info : [ 3449.743426] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 3449.744606] ? do_truncate (fs/open.c:66)
kern :info : [ 3449.745832] do_truncate (fs/open.c:66)
kern :info : [ 3449.747038] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 3449.748280] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 3449.749532] vfs_truncate (fs/open.c:111)
kern :info : [ 3449.750754] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 3449.751994] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 3449.753303] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 3449.754537] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 3449.755749] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 3449.757070] RIP: 0033:0x7fb415adaf17
kern :info : [ 3449.758277] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 3449.759822] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 3449.761364] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 3449.762868] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 3449.764421] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 3449.765958] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 3449.767521] </TASK>
kern :err : [ 3941.240221] INFO: task dio_truncate:7499 blocked for more than 2457 seconds.
kern :err : [ 3941.241971] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 3941.243381] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 3941.244968] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 3941.246768] Call Trace:
kern :info : [ 3941.247927] <TASK>
kern :info : [ 3941.249017] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 3941.250267] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 3941.251521] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 3941.252708] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 3941.253986] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 3941.255231] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 3941.256422] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 3941.257705] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 3941.258954] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 3941.260125] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 3941.261391] notify_change (fs/attr.c:495)
kern :info : [ 3941.262601] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 3941.263779] ? do_truncate (fs/open.c:66)
kern :info : [ 3941.264917] do_truncate (fs/open.c:66)
kern :info : [ 3941.266044] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 3941.267257] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 3941.268451] vfs_truncate (fs/open.c:111)
kern :info : [ 3941.269581] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 3941.270861] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 3941.272111] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 3941.273240] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 3941.274502] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 3941.275872] RIP: 0033:0x7fb415adaf17
kern :info : [ 3941.277068] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 3941.278608] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 3941.280150] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 3941.281582] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 3941.283213] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 3941.284655] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 3941.286229] </TASK>
kern :err : [ 4432.760118] INFO: task dio_truncate:7499 blocked for more than 2949 seconds.
kern :err : [ 4432.761567] Not tainted 6.11.0-rc2-00012-g96cfeb038953 #1
kern :err : [ 4432.763073] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kern :info : [ 4432.764652] task:dio_truncate state:D stack:0 pid:7499 tgid:7499 ppid:7498 flags:0x00000002
kern :info : [ 4432.766420] Call Trace:
kern :info : [ 4432.767606] <TASK>
kern :info : [ 4432.768695] __schedule (kernel/sched/core.c:5188 kernel/sched/core.c:6529)
kern :info : [ 4432.769905] ? __pfx___schedule (kernel/sched/core.c:6399)
kern :info : [ 4432.771267] ? stack_trace_save (kernel/stacktrace.c:123)
kern :info : [ 4432.772514] schedule (arch/x86/include/asm/preempt.h:84 kernel/sched/core.c:6607 kernel/sched/core.c:6621)
kern :info : [ 4432.773699] inode_dio_wait (fs/inode.c:2478 fs/inode.c:2496)
kern :info : [ 4432.774910] ? __pfx_inode_dio_wait (fs/inode.c:2494)
kern :info : [ 4432.776269] ? kasan_save_track (arch/x86/include/asm/current.h:49 mm/kasan/common.c:60 mm/kasan/common.c:69)
kern :info : [ 4432.777469] ? __pfx_wake_bit_function (kernel/sched/wait_bit.c:22)
kern :info : [ 4432.778706] ? setattr_prepare (fs/attr.c:173)
kern :info : [ 4432.779958] f2fs_setattr (fs/f2fs/file.c:1063) f2fs
kern :info : [ 4432.781241] notify_change (fs/attr.c:495)
kern :info : [ 4432.782379] ? __pfx_down_write (kernel/locking/rwsem.c:1577)
kern :info : [ 4432.783604] ? do_truncate (fs/open.c:66)
kern :info : [ 4432.784772] do_truncate (fs/open.c:66)
kern :info : [ 4432.785973] ? __pfx_do_truncate (fs/open.c:41)
kern :info : [ 4432.787198] ? inode_permission (fs/namei.c:536 fs/namei.c:510)
kern :info : [ 4432.788514] vfs_truncate (fs/open.c:111)
kern :info : [ 4432.789655] __x64_sys_truncate (fs/open.c:135 fs/open.c:146 fs/open.c:144 fs/open.c:144)
kern :info : [ 4432.790909] ? __pfx___x64_sys_truncate (fs/open.c:144)
kern :info : [ 4432.792413] ? kmem_cache_free (mm/slub.c:4474 mm/slub.c:4548)
kern :info : [ 4432.793602] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
kern :info : [ 4432.794814] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:130)
kern :info : [ 4432.796255] RIP: 0033:0x7fb415adaf17
kern :info : [ 4432.797402] RSP: 002b:00007fff6e0f8e28 EFLAGS: 00000206 ORIG_RAX: 000000000000004c
kern :info : [ 4432.798963] RAX: ffffffffffffffda RBX: 000055bd20741074 RCX: 00007fb415adaf17
kern :info : [ 4432.800493] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000055bd2074103d
kern :info : [ 4432.802033] RBP: 000055bd4dc17000 R08: 0000000000000001 R09: 0000000000010000
kern :info : [ 4432.803557] R10: 00007fb4159ea390 R11: 0000000000000206 R12: 0000000000000004
kern :info : [ 4432.805121] R13: 0000000000000064 R14: 0000000000010000 R15: 0000000000000064
kern :info : [ 4432.806589] </TASK>
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240827/202408271015.5b4de2c5-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
