Hi,
As previously reported in https://lore.kernel.org/all/[email protected]/
I found some hangs below ext4_fallocate(), in 6.6-rc*. As it looks like my
issue was unrelated to the thread I had responded to, I was asked to start
this new thread.
I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
it took ~55min of high load (io_uring using branch of postgres, running a
write heavy transactional workload concurrently with concurrent bulk data
load) to trigger the issue.
For now I have left the system running, in case there's something you would
like me to check while the system is hung.
The first hanging task that I observed:
cat /proc/57606/stack
[<0>] inode_dio_wait+0xd5/0x100
[<0>] ext4_fallocate+0x12f/0x1040
[<0>] vfs_fallocate+0x135/0x360
[<0>] __x64_sys_fallocate+0x42/0x70
[<0>] do_syscall_64+0x38/0x80
[<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[ 3194.579039] INFO: task postgres:57606 blocked for more than 122 seconds.
[ 3194.579057] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
[ 3194.579064] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3194.579069] task:postgres state:D stack:0 pid:57606 ppid:52606 flags:0x00020002
[ 3194.579083] Call Trace:
[ 3194.579089] <TASK>
[ 3194.579098] __schedule+0x388/0x13e0
[ 3194.579121] schedule+0x5f/0xe0
[ 3194.579133] inode_dio_wait+0xd5/0x100
[ 3194.579148] ? membarrier_register_private_expedited+0xa0/0xa0
[ 3194.579160] ext4_fallocate+0x12f/0x1040
[ 3194.579171] ? timerqueue_add+0x90/0xb0
[ 3194.579183] ? rcu_accelerate_cbs+0x1d/0x70
[ 3194.579194] vfs_fallocate+0x135/0x360
[ 3194.579204] __x64_sys_fallocate+0x42/0x70
[ 3194.579212] do_syscall_64+0x38/0x80
[ 3194.579224] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[ 3194.579236] RIP: 0033:0x7fb8db658f82
[ 3194.579245] RSP: 002b:00007fff86eda9c8 EFLAGS: 00000246 ORIG_RAX: 000000000000011d
[ 3194.579255] RAX: ffffffffffffffda RBX: 0000000000200000 RCX: 00007fb8db658f82
[ 3194.579263] RDX: 000000003fd9e000 RSI: 0000000000000000 RDI: 0000000000000072
[ 3194.579269] RBP: 000000003fd9e000 R08: 000000003fd9e000 R09: 0000559d2f22b530
[ 3194.579275] R10: 0000000000200000 R11: 0000000000000246 R12: 0000000000001538
[ 3194.579281] R13: 000000000a000013 R14: 0000000000000061 R15: 0000559d2dced070
[ 3194.579291] </TASK>
In contrast to earlier iterations, I also got "task blocked" errors for
io_uring workers:
[ 3194.579297] INFO: task iou-wrk-58004:58874 blocked for more than 122 seconds.
[ 3194.579304] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
[ 3194.579310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3194.579314] task:iou-wrk-58004 state:D stack:0 pid:58874 ppid:52606 flags:0x00004000
[ 3194.579325] Call Trace:
[ 3194.579329] <TASK>
[ 3194.579334] __schedule+0x388/0x13e0
[ 3194.579349] schedule+0x5f/0xe0
[ 3194.579361] schedule_preempt_disabled+0x15/0x20
[ 3194.579374] rwsem_down_read_slowpath+0x26e/0x4c0
[ 3194.579385] down_read+0x44/0xa0
[ 3194.579393] ext4_file_write_iter+0x432/0xa80
[ 3194.579407] io_write+0x129/0x420
[ 3194.579421] ? set_next_entity+0xc8/0x180
[ 3194.579433] ? __switch_to_asm+0x3a/0x60
[ 3194.579443] ? finish_task_switch.isra.0+0x87/0x2a0
[ 3194.579457] ? __schedule+0x390/0x13e0
[ 3194.579469] io_issue_sqe+0x60/0x3c0
[ 3194.579482] io_wq_submit_work+0x88/0x2c0
[ 3194.579494] io_worker_handle_work+0x156/0x560
[ 3194.579509] io_wq_worker+0xf5/0x360
[ 3194.579522] ? finish_task_switch.isra.0+0x87/0x2a0
[ 3194.579534] ? io_worker_handle_work+0x560/0x560
[ 3194.579546] ret_from_fork+0x2d/0x50
[ 3194.579557] ? io_worker_handle_work+0x560/0x560
[ 3194.579569] ret_from_fork_asm+0x11/0x20
[ 3194.579581] </TASK>
This is repeated for several other identical workers with ppid 52606 with identical
stacks.
pid:58874 is a io uring worker thread for pid 58004, which has the following
kernel stack:
sudo cat /proc/58004/stack
[<0>] __do_sys_io_uring_enter+0x7bd/0xbf0
[<0>] do_syscall_64+0x38/0x80
[<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
As before, there are no busy IOs according to /sys/kernel/debug/block/nvme1n1/hctx*/busy
nor are there IO errors or such in the kernel log.
Once I hear that you don't want me to test something out on the running
system, I think a sensible next step could be to compile with lockdep and see
if that finds a problem?
Greetings,
Andres Freund
On Mon, Oct 16, 2023 at 08:37:25PM -0700, Andres Freund wrote:
> I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
> it took ~55min of high load (io_uring using branch of postgres, running a
> write heavy transactional workload concurrently with concurrent bulk data
> load) to trigger the issue.
>
> For now I have left the system running, in case there's something you would
> like me to check while the system is hung.
>
> The first hanging task that I observed:
>
> cat /proc/57606/stack
> [<0>] inode_dio_wait+0xd5/0x100
> [<0>] ext4_fallocate+0x12f/0x1040
> [<0>] vfs_fallocate+0x135/0x360
> [<0>] __x64_sys_fallocate+0x42/0x70
> [<0>] do_syscall_64+0x38/0x80
> [<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
This stack trace is from some process (presumably postgres) trying to
do a fallocate() system call:
/* Wait all existing dio workers, newcomers will block on i_rwsem */
inode_dio_wait(inode);
The reason for this is that we can't manipulate the extent tree until
any data block I/Os comlplete. This will block until
iomap_dio_complete() in fs/iomap/direct-io.c calls inode_dio_end().
> [ 3194.579297] INFO: task iou-wrk-58004:58874 blocked for more than 122 seconds.
> [ 3194.579304] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
> [ 3194.579310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 3194.579314] task:iou-wrk-58004 state:D stack:0 pid:58874 ppid:52606 flags:0x00004000
> [ 3194.579325] Call Trace:
> [ 3194.579329] <TASK>
> [ 3194.579334] __schedule+0x388/0x13e0
> [ 3194.579349] schedule+0x5f/0xe0
> [ 3194.579361] schedule_preempt_disabled+0x15/0x20
> [ 3194.579374] rwsem_down_read_slowpath+0x26e/0x4c0
> [ 3194.579385] down_read+0x44/0xa0
> [ 3194.579393] ext4_file_write_iter+0x432/0xa80
> [ 3194.579407] io_write+0x129/0x420
This could potentially be a interesting stack trace; but this is where
we really need to map the stack address to line numbers. Is that
something you could do?
> Once I hear that you don't want me to test something out on the running
> system, I think a sensible next step could be to compile with lockdep and see
> if that finds a problem?
That's certainly a possibiity. But also please make sure that you can
compile with with debugging information enabled so that we can get
reliable line numbers. I use:
CONFIG_DEBUG_INFO=y
CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y
CONFIG_DEBUG_INFO_REDUCED=y
Cheers,
- Ted
Hi,
On 2023-10-17 20:43:35 -0400, Theodore Ts'o wrote:
> On Mon, Oct 16, 2023 at 08:37:25PM -0700, Andres Freund wrote:
> > I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
> > it took ~55min of high load (io_uring using branch of postgres, running a
> > write heavy transactional workload concurrently with concurrent bulk data
> > load) to trigger the issue.
> >
> > For now I have left the system running, in case there's something you would
> > like me to check while the system is hung.
> >
> > The first hanging task that I observed:
> >
> > cat /proc/57606/stack
> > [<0>] inode_dio_wait+0xd5/0x100
> > [<0>] ext4_fallocate+0x12f/0x1040
> > [<0>] vfs_fallocate+0x135/0x360
> > [<0>] __x64_sys_fallocate+0x42/0x70
> > [<0>] do_syscall_64+0x38/0x80
> > [<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
>
> This stack trace is from some process (presumably postgres) trying to
> do a fallocate() system call:
Yes, it's indeed postgres.
> > [ 3194.579297] INFO: task iou-wrk-58004:58874 blocked for more than 122 seconds.
> > [ 3194.579304] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
> > [ 3194.579310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > [ 3194.579314] task:iou-wrk-58004 state:D stack:0 pid:58874 ppid:52606 flags:0x00004000
> > [ 3194.579325] Call Trace:
> > [ 3194.579329] <TASK>
> > [ 3194.579334] __schedule+0x388/0x13e0
> > [ 3194.579349] schedule+0x5f/0xe0
> > [ 3194.579361] schedule_preempt_disabled+0x15/0x20
> > [ 3194.579374] rwsem_down_read_slowpath+0x26e/0x4c0
> > [ 3194.579385] down_read+0x44/0xa0
> > [ 3194.579393] ext4_file_write_iter+0x432/0xa80
> > [ 3194.579407] io_write+0x129/0x420
>
> This could potentially be a interesting stack trace; but this is where
> we really need to map the stack address to line numbers. Is that
> something you could do?
Converting the above with scripts/decode_stacktrace.sh yields:
__schedule (kernel/sched/core.c:5382 kernel/sched/core.c:6695)
schedule (./arch/x86/include/asm/preempt.h:85 (discriminator 13) kernel/sched/core.c:6772 (discriminator 13))
schedule_preempt_disabled (./arch/x86/include/asm/preempt.h:80 (discriminator 10) kernel/sched/core.c:6831 (discriminator 10))
rwsem_down_read_slowpath (kernel/locking/rwsem.c:1073 (discriminator 4))
down_read (./arch/x86/include/asm/preempt.h:95 kernel/locking/rwsem.c:1257 kernel/locking/rwsem.c:1263 kernel/locking/rwsem.c:1522)
ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
But I'm not sure that that stacktrace is quite right (e.g. what's
./include/linux/fs.h:1073 doing in this stacktrace?). But with an optimized
build it's a bit hard to tell what's an optimization artifact and what's an
off stack trace...
I had the idea to look at the stacks (via /proc/$pid/stack) for all postgres
processes and the associated io-uring threads, and then to deduplicate them.
22x:
ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
io_issue_sqe (io_uring/io_uring.c:1878)
io_wq_submit_work (io_uring/io_uring.c:1960)
io_worker_handle_work (io_uring/io-wq.c:596)
io_wq_worker (io_uring/io-wq.c:258 io_uring/io-wq.c:648)
ret_from_fork (arch/x86/kernel/process.c:147)
ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
8x:
__do_sys_io_uring_enter (io_uring/io_uring.c:2553 (discriminator 1) io_uring/io_uring.c:2622 (discriminator 1) io_uring/io_uring.c:3706 (discriminator 1))
do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
2x:
io_wq_worker (./arch/x86/include/asm/current.h:41 (discriminator 5) io_uring/io-wq.c:668 (discriminator 5))
ret_from_fork (arch/x86/kernel/process.c:147)
ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
2x:
futex_wait_queue (./arch/x86/include/asm/current.h:41 (discriminator 5) kernel/futex/waitwake.c:357 (discriminator 5))
futex_wait (kernel/futex/waitwake.c:660)
do_futex (kernel/futex/syscalls.c:106 (discriminator 1))
__x64_sys_futex (kernel/futex/syscalls.c:183 kernel/futex/syscalls.c:164 kernel/futex/syscalls.c:164)
do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
1x:
do_epoll_wait (fs/eventpoll.c:1921 (discriminator 1) fs/eventpoll.c:2318 (discriminator 1))
__x64_sys_epoll_wait (fs/eventpoll.c:2325)
do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
1x:
inode_dio_wait (./arch/x86/include/asm/atomic.h:23 ./include/linux/atomic/atomic-arch-fallback.h:444 ./include/linux/atomic/atomic-instrumented.h:33 fs/inode.c:2429 fs/inode.c:2446)
ext4_fallocate (fs/ext4/extents.c:4752)
vfs_fallocate (fs/open.c:324)
__x64_sys_fallocate (./include/linux/file.h:45 fs/open.c:348 fs/open.c:355 fs/open.c:353 fs/open.c:353)
do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
> > Once I hear that you don't want me to test something out on the running
> > system, I think a sensible next step could be to compile with lockdep and see
> > if that finds a problem?
>
> That's certainly a possibiity. But also please make sure that you can
> compile with with debugging information enabled so that we can get
> reliable line numbers. I use:
>
> CONFIG_DEBUG_INFO=y
> CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y
> CONFIG_DEBUG_INFO_REDUCED=y
The kernel from above had debug info enabled, albeit forced to dwarf4 (IIRC I
ran into issues with pahole not understanding all of dwarf5):
$ zgrep DEBUG_INFO /proc/config.gz
CONFIG_DEBUG_INFO=y
# CONFIG_DEBUG_INFO_NONE is not set
# CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT is not set
CONFIG_DEBUG_INFO_DWARF4=y
# CONFIG_DEBUG_INFO_DWARF5 is not set
# CONFIG_DEBUG_INFO_REDUCED is not set
CONFIG_DEBUG_INFO_COMPRESSED_NONE=y
# CONFIG_DEBUG_INFO_COMPRESSED_ZLIB is not set
# CONFIG_DEBUG_INFO_COMPRESSED_ZSTD is not set
# CONFIG_DEBUG_INFO_SPLIT is not set
CONFIG_DEBUG_INFO_BTF=y
CONFIG_DEBUG_INFO_BTF_MODULES=y
I switched it to CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y and am rebuilding
with lockdep enabled. Curious to see how long it'll take to trigger the
problem with it enabled...
Greetings,
Andres Freund
HI,
On 2023-10-17 19:50:09 -0700, Andres Freund wrote:
> I switched it to CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y and am rebuilding
> with lockdep enabled. Curious to see how long it'll take to trigger the
> problem with it enabled...
After booting into the lockdep enabled kernel I was immediately greeted with a
lockdep splat - in nouveau. Not realizing that would prevent subsequent
lockdep reports, I continued trying to reproduce the issue. Took 2-3h.
The next boot quickly triggered another unrelated lockdep report, possibly
triggered by a usb hub disconnecting.
Luckily the boot after that the problem very quickly reproduced. Lockdep did
not report a bug, but the list of held locks after the "hung task" warning
seems interesting:
[ 367.987710] INFO: task iou-wrk-3385:3753 blocked for more than 122 seconds.
[ 367.987882] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #79
[ 367.987896] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 367.987907] task:iou-wrk-3385 state:D stack:0 pid:3753 ppid:3320 flags:0x00004000
[ 367.987931] Call Trace:
[ 367.987942] <TASK>
[ 367.987964] __schedule+0x4c3/0x17f0
[ 367.988000] ? schedule+0xa6/0xe0
[ 367.988030] schedule+0x5f/0xe0
[ 367.988049] schedule_preempt_disabled+0x15/0x20
[ 367.988068] rwsem_down_read_slowpath+0x2b9/0x590
[ 367.988110] down_read+0x64/0x150
[ 367.988128] ext4_file_write_iter+0x435/0xa90
[ 367.988150] ? find_held_lock+0x2b/0x80
[ 367.988170] ? io_write+0x366/0x4d0
[ 367.988184] ? lock_release+0xba/0x260
[ 367.988199] ? lock_is_held_type+0x84/0xf0
[ 367.988225] io_write+0x12b/0x4d0
[ 367.988264] ? lock_acquire+0xb3/0x2a0
[ 367.988280] ? io_worker_handle_work+0x10c/0x560
[ 367.988303] io_issue_sqe+0x5a/0x340
[ 367.988323] io_wq_submit_work+0x86/0x240
[ 367.988342] io_worker_handle_work+0x156/0x560
[ 367.988371] io_wq_worker+0xf6/0x370
[ 367.988392] ? find_held_lock+0x2b/0x80
[ 367.988409] ? ret_from_fork+0x17/0x50
[ 367.988427] ? lock_release+0xba/0x260
[ 367.988441] ? io_worker_handle_work+0x560/0x560
[ 367.988459] ? io_worker_handle_work+0x560/0x560
[ 367.988477] ret_from_fork+0x2d/0x50
[ 367.988493] ? io_worker_handle_work+0x560/0x560
[ 367.988509] ret_from_fork_asm+0x11/0x20
[ 367.988551] </TASK>
[ 367.988562] INFO: task iou-wrk-3385:3855 blocked for more than 122 seconds.
[ 367.988575] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #79
[ 367.988586] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 367.988596] task:iou-wrk-3385 state:D stack:0 pid:3855 ppid:3320 flags:0x00004000
[ 367.988615] Call Trace:
[ 367.988625] <TASK>
[ 367.988641] __schedule+0x4c3/0x17f0
[ 367.988670] ? schedule+0xa6/0xe0
[ 367.988699] schedule+0x5f/0xe0
[ 367.988718] schedule_preempt_disabled+0x15/0x20
[ 367.988736] rwsem_down_read_slowpath+0x2b9/0x590
[ 367.988777] down_read+0x64/0x150
[ 367.988795] ext4_file_write_iter+0x435/0xa90
[ 367.988813] ? find_held_lock+0x2b/0x80
[ 367.988831] ? io_write+0x366/0x4d0
[ 367.988844] ? lock_release+0xba/0x260
[ 367.988858] ? lock_is_held_type+0x84/0xf0
[ 367.988883] io_write+0x12b/0x4d0
[ 367.988922] ? lock_acquire+0xb3/0x2a0
[ 367.988937] ? io_worker_handle_work+0x10c/0x560
[ 367.988959] io_issue_sqe+0x5a/0x340
[ 367.988978] io_wq_submit_work+0x86/0x240
[ 367.988998] io_worker_handle_work+0x156/0x560
[ 367.989026] io_wq_worker+0xf6/0x370
[ 367.989047] ? find_held_lock+0x2b/0x80
[ 367.989064] ? ret_from_fork+0x17/0x50
[ 367.989080] ? lock_release+0xba/0x260
[ 367.989094] ? io_worker_handle_work+0x560/0x560
[ 367.989112] ? io_worker_handle_work+0x560/0x560
[ 367.989130] ret_from_fork+0x2d/0x50
[ 367.989146] ? io_worker_handle_work+0x560/0x560
[ 367.989162] ret_from_fork_asm+0x11/0x20
[ 367.989202] </TASK>
[ 367.989251] INFO: task postgres:3409 blocked for more than 122 seconds.
[ 367.989263] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #79
[ 367.989273] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 367.989283] task:postgres state:D stack:0 pid:3409 ppid:3320 flags:0x00020002
[ 367.989301] Call Trace:
[ 367.989310] <TASK>
[ 367.989327] __schedule+0x4c3/0x17f0
[ 367.989345] ? prepare_to_wait+0x19/0x90
[ 367.989383] schedule+0x5f/0xe0
[ 367.989403] inode_dio_wait+0xd5/0x100
[ 367.989424] ? sugov_start+0x120/0x120
[ 367.989445] ext4_fallocate+0x149/0x1140
[ 367.989461] ? lock_acquire+0xb3/0x2a0
[ 367.989476] ? __x64_sys_fallocate+0x42/0x70
[ 367.989513] vfs_fallocate+0x135/0x450
[ 367.989534] __x64_sys_fallocate+0x42/0x70
[ 367.989554] do_syscall_64+0x38/0x80
[ 367.989573] entry_SYSCALL_64_after_hwframe+0x46/0xb0
[ 367.989589] RIP: 0033:0x7f9bbc458f82
[ 367.989605] RSP: 002b:00007fff59b4b6a8 EFLAGS: 00000246 ORIG_RAX: 000000000000011d
[ 367.989624] RAX: ffffffffffffffda RBX: 00000000000d0000 RCX: 00007f9bbc458f82
[ 367.989637] RDX: 00000000139ec000 RSI: 0000000000000000 RDI: 0000000000000046
[ 367.989649] RBP: 00000000139ec000 R08: 00000000139ec000 R09: 0000558ea7726ed0
[ 367.989661] R10: 00000000000d0000 R11: 0000000000000246 R12: 0000000000000b98
[ 367.989672] R13: 000000000a000013 R14: 0000000000000035 R15: 0000558ea719c070
[ 367.989710] </TASK>
[ 367.989723]
Showing all locks held in the system:
[ 367.989749] 1 lock held by khungtaskd/130:
[ 367.989762] #0: ffffffff8412d020 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1b0
[ 367.989864] 1 lock held by iou-wrk-3322/3768:
[ 367.989875] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.989918] 1 lock held by iou-wrk-3322/4142:
[ 367.989929] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.989968] 1 lock held by iou-wrk-3322/4143:
[ 367.989978] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990015] 1 lock held by iou-wrk-3322/4144:
[ 367.990025] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990062] 1 lock held by iou-wrk-3322/4145:
[ 367.990072] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990109] 1 lock held by iou-wrk-3322/4146:
[ 367.990119] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990157] 1 lock held by iou-wrk-3322/4147:
[ 367.990167] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990204] 1 lock held by iou-wrk-3322/4148:
[ 367.990214] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990252] 1 lock held by iou-wrk-3385/3753:
[ 367.990263] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990300] 1 lock held by iou-wrk-3385/3855:
[ 367.990310] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990347] 1 lock held by iou-wrk-3386/3953:
[ 367.990357] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990394] 1 lock held by iou-wrk-3386/4016:
[ 367.990404] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990478] 1 lock held by iou-wrk-3386/4018:
[ 367.990489] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990527] 1 lock held by iou-wrk-3386/4026:
[ 367.990537] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990574] 1 lock held by iou-wrk-3386/4027:
[ 367.990584] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990622] 1 lock held by iou-wrk-3386/4030:
[ 367.990632] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990669] 1 lock held by iou-wrk-3386/4031:
[ 367.990679] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990716] 1 lock held by iou-wrk-3386/4034:
[ 367.990726] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990763] 1 lock held by iou-wrk-3386/4036:
[ 367.990773] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990810] 1 lock held by iou-wrk-3386/4037:
[ 367.990820] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990857] 1 lock held by iou-wrk-3386/4039:
[ 367.990868] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990905] 1 lock held by iou-wrk-3386/4041:
[ 367.990915] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990952] 1 lock held by iou-wrk-3386/4043:
[ 367.990962] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.990999] 1 lock held by iou-wrk-3386/4045:
[ 367.991009] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991046] 1 lock held by iou-wrk-3386/4047:
[ 367.991056] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991094] 1 lock held by iou-wrk-3386/4049:
[ 367.991104] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991141] 1 lock held by iou-wrk-3386/4052:
[ 367.991151] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991188] 1 lock held by iou-wrk-3386/4054:
[ 367.991198] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991235] 1 lock held by iou-wrk-3386/4056:
[ 367.991245] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991283] 1 lock held by iou-wrk-3386/4058:
[ 367.991293] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991330] 1 lock held by iou-wrk-3386/4060:
[ 367.991340] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991377] 1 lock held by iou-wrk-3386/4061:
[ 367.991387] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991424] 1 lock held by iou-wrk-3386/4063:
[ 367.991434] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991471] 1 lock held by iou-wrk-3386/4066:
[ 367.991481] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991518] 1 lock held by iou-wrk-3386/4069:
[ 367.991528] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991566] 1 lock held by iou-wrk-3386/4071:
[ 367.991576] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991613] 1 lock held by iou-wrk-3386/4073:
[ 367.991623] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991660] 1 lock held by iou-wrk-3386/4075:
[ 367.991670] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991707] 1 lock held by iou-wrk-3386/4076:
[ 367.991717] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991754] 1 lock held by iou-wrk-3386/4077:
[ 367.991764] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991801] 1 lock held by iou-wrk-3386/4078:
[ 367.991811] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991848] 1 lock held by iou-wrk-3386/4079:
[ 367.991859] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991896] 1 lock held by iou-wrk-3387/3990:
[ 367.991906] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991943] 1 lock held by iou-wrk-3387/3998:
[ 367.991953] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.991990] 1 lock held by iou-wrk-3387/4083:
[ 367.992001] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992038] 1 lock held by iou-wrk-3387/4085:
[ 367.992048] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992085] 1 lock held by iou-wrk-3387/4087:
[ 367.992095] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992132] 1 lock held by iou-wrk-3387/4089:
[ 367.992142] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992179] 1 lock held by iou-wrk-3387/4091:
[ 367.992189] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992226] 1 lock held by iou-wrk-3387/4093:
[ 367.992236] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992273] 1 lock held by iou-wrk-3387/4095:
[ 367.992283] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992321] 1 lock held by iou-wrk-3387/4097:
[ 367.992331] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992368] 1 lock held by iou-wrk-3387/4099:
[ 367.992378] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992415] 1 lock held by iou-wrk-3387/4101:
[ 367.992425] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992462] 1 lock held by iou-wrk-3387/4103:
[ 367.992472] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992509] 1 lock held by iou-wrk-3387/4105:
[ 367.992519] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992556] 1 lock held by iou-wrk-3387/4107:
[ 367.992566] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992603] 1 lock held by iou-wrk-3387/4109:
[ 367.992613] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992650] 1 lock held by iou-wrk-3387/4111:
[ 367.992660] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992697] 1 lock held by iou-wrk-3387/4113:
[ 367.992707] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992745] 1 lock held by iou-wrk-3387/4115:
[ 367.992755] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992792] 1 lock held by iou-wrk-3387/4117:
[ 367.992817] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992823] 1 lock held by iou-wrk-3387/4119:
[ 367.992825] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992832] 1 lock held by iou-wrk-3387/4122:
[ 367.992834] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992840] 1 lock held by iou-wrk-3387/4124:
[ 367.992842] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992849] 1 lock held by iou-wrk-3387/4126:
[ 367.992851] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992858] 1 lock held by iou-wrk-3387/4128:
[ 367.992859] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992866] 1 lock held by iou-wrk-3387/4130:
[ 367.992868] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992875] 1 lock held by iou-wrk-3387/4132:
[ 367.992876] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992883] 1 lock held by iou-wrk-3387/4134:
[ 367.992885] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992892] 1 lock held by iou-wrk-3387/4136:
[ 367.992893] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992900] 1 lock held by iou-wrk-3387/4138:
[ 367.992902] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992909] 1 lock held by iou-wrk-3387/4139:
[ 367.992910] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992917] 1 lock held by iou-wrk-3387/4141:
[ 367.992919] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992926] 1 lock held by iou-wrk-3388/3968:
[ 367.992927] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992934] 1 lock held by iou-wrk-3388/4013:
[ 367.992936] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992943] 1 lock held by iou-wrk-3388/4015:
[ 367.992944] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992951] 1 lock held by iou-wrk-3388/4021:
[ 367.992953] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992960] 1 lock held by iou-wrk-3388/4150:
[ 367.992962] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992968] 1 lock held by iou-wrk-3388/4151:
[ 367.992970] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992977] 1 lock held by iou-wrk-3388/4152:
[ 367.992979] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992985] 1 lock held by iou-wrk-3388/4153:
[ 367.992987] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.992994] 1 lock held by iou-wrk-3388/4154:
[ 367.992996] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993002] 1 lock held by iou-wrk-3388/4155:
[ 367.993004] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993011] 1 lock held by iou-wrk-3388/4156:
[ 367.993013] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993019] 1 lock held by iou-wrk-3388/4157:
[ 367.993021] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993028] 1 lock held by iou-wrk-3388/4158:
[ 367.993030] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993036] 1 lock held by iou-wrk-3388/4159:
[ 367.993038] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993045] 1 lock held by iou-wrk-3388/4160:
[ 367.993047] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993054] 1 lock held by iou-wrk-3388/4161:
[ 367.993055] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993062] 1 lock held by iou-wrk-3388/4162:
[ 367.993064] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993071] 1 lock held by iou-wrk-3388/4163:
[ 367.993073] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993079] 1 lock held by iou-wrk-3388/4164:
[ 367.993081] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993088] 1 lock held by iou-wrk-3389/3965:
[ 367.993089] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993096] 1 lock held by iou-wrk-3389/4005:
[ 367.993098] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993105] 1 lock held by iou-wrk-3389/4023:
[ 367.993106] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993113] 1 lock held by iou-wrk-3389/4024:
[ 367.993115] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993122] 1 lock held by iou-wrk-3389/4025:
[ 367.993124] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993130] 1 lock held by iou-wrk-3389/4028:
[ 367.993132] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993139] 1 lock held by iou-wrk-3389/4029:
[ 367.993140] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993147] 1 lock held by iou-wrk-3389/4032:
[ 367.993149] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993156] 1 lock held by iou-wrk-3389/4033:
[ 367.993157] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993164] 1 lock held by iou-wrk-3389/4035:
[ 367.993166] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993172] 1 lock held by iou-wrk-3389/4038:
[ 367.993174] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993181] 1 lock held by iou-wrk-3389/4040:
[ 367.993183] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993189] 1 lock held by iou-wrk-3389/4042:
[ 367.993191] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993198] 1 lock held by iou-wrk-3389/4044:
[ 367.993200] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993206] 1 lock held by iou-wrk-3389/4046:
[ 367.993208] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993215] 1 lock held by iou-wrk-3389/4048:
[ 367.993217] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993223] 1 lock held by iou-wrk-3389/4050:
[ 367.993225] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993232] 1 lock held by iou-wrk-3389/4051:
[ 367.993234] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993240] 1 lock held by iou-wrk-3389/4053:
[ 367.993242] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993249] 1 lock held by iou-wrk-3389/4055:
[ 367.993251] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993257] 1 lock held by iou-wrk-3389/4057:
[ 367.993259] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993266] 1 lock held by iou-wrk-3389/4059:
[ 367.993268] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993274] 1 lock held by iou-wrk-3389/4062:
[ 367.993276] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993283] 1 lock held by iou-wrk-3389/4064:
[ 367.993284] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993291] 1 lock held by iou-wrk-3389/4065:
[ 367.993293] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993300] 1 lock held by iou-wrk-3389/4067:
[ 367.993301] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993308] 1 lock held by iou-wrk-3389/4068:
[ 367.993310] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993317] 1 lock held by iou-wrk-3389/4070:
[ 367.993318] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993325] 1 lock held by iou-wrk-3389/4072:
[ 367.993327] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993334] 1 lock held by iou-wrk-3389/4074:
[ 367.993335] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993342] 1 lock held by iou-wrk-3389/4080:
[ 367.993344] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993351] 1 lock held by iou-wrk-3389/4081:
[ 367.993352] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993359] 1 lock held by iou-wrk-3390/3856:
[ 367.993361] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993368] 1 lock held by iou-wrk-3390/4014:
[ 367.993370] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993376] 1 lock held by iou-wrk-3390/4017:
[ 367.993378] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993385] 1 lock held by iou-wrk-3390/4165:
[ 367.993387] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993393] 1 lock held by iou-wrk-3390/4166:
[ 367.993395] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993402] 1 lock held by iou-wrk-3390/4167:
[ 367.993404] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993410] 1 lock held by iou-wrk-3390/4168:
[ 367.993412] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993419] 1 lock held by iou-wrk-3390/4169:
[ 367.993420] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993427] 1 lock held by iou-wrk-3390/4170:
[ 367.993429] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993436] 1 lock held by iou-wrk-3390/4171:
[ 367.993437] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993444] 1 lock held by iou-wrk-3390/4172:
[ 367.993446] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993453] 1 lock held by iou-wrk-3390/4173:
[ 367.993454] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993461] 1 lock held by iou-wrk-3390/4174:
[ 367.993463] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993470] 1 lock held by iou-wrk-3390/4175:
[ 367.993471] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993478] 1 lock held by iou-wrk-3390/4176:
[ 367.993480] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993486] 1 lock held by iou-wrk-3390/4177:
[ 367.993488] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993495] 1 lock held by iou-wrk-3390/4178:
[ 367.993497] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993504] 1 lock held by iou-wrk-3392/4000:
[ 367.993506] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993512] 1 lock held by iou-wrk-3392/4019:
[ 367.993514] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993521] 1 lock held by iou-wrk-3392/4082:
[ 367.993523] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993529] 1 lock held by iou-wrk-3392/4084:
[ 367.993531] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993538] 1 lock held by iou-wrk-3392/4086:
[ 367.993540] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993546] 1 lock held by iou-wrk-3392/4088:
[ 367.993548] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993555] 1 lock held by iou-wrk-3392/4090:
[ 367.993557] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993563] 1 lock held by iou-wrk-3392/4092:
[ 367.993565] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993572] 1 lock held by iou-wrk-3392/4094:
[ 367.993574] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993580] 1 lock held by iou-wrk-3392/4096:
[ 367.993582] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993589] 1 lock held by iou-wrk-3392/4098:
[ 367.993591] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993597] 1 lock held by iou-wrk-3392/4100:
[ 367.993599] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993606] 1 lock held by iou-wrk-3392/4102:
[ 367.993608] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993614] 1 lock held by iou-wrk-3392/4104:
[ 367.993616] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993623] 1 lock held by iou-wrk-3392/4106:
[ 367.993625] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993631] 1 lock held by iou-wrk-3392/4108:
[ 367.993633] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993640] 1 lock held by iou-wrk-3392/4110:
[ 367.993642] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993648] 1 lock held by iou-wrk-3392/4112:
[ 367.993650] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993657] 1 lock held by iou-wrk-3392/4114:
[ 367.993659] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993665] 1 lock held by iou-wrk-3392/4116:
[ 367.993667] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993674] 1 lock held by iou-wrk-3392/4118:
[ 367.993676] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993682] 1 lock held by iou-wrk-3392/4120:
[ 367.993684] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993691] 1 lock held by iou-wrk-3392/4121:
[ 367.993693] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993699] 1 lock held by iou-wrk-3392/4123:
[ 367.993701] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993708] 1 lock held by iou-wrk-3392/4125:
[ 367.993710] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993716] 1 lock held by iou-wrk-3392/4127:
[ 367.993718] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993725] 1 lock held by iou-wrk-3392/4129:
[ 367.993727] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993733] 1 lock held by iou-wrk-3392/4131:
[ 367.993735] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993742] 1 lock held by iou-wrk-3392/4133:
[ 367.993743] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993750] 1 lock held by iou-wrk-3392/4135:
[ 367.993752] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993759] 1 lock held by iou-wrk-3392/4137:
[ 367.993760] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993767] 1 lock held by iou-wrk-3392/4140:
[ 367.993769] #0: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_file_write_iter+0x435/0xa90
[ 367.993780] 2 locks held by postgres/3409:
[ 367.993801] #0: ffff888144c3e3f8 (sb_writers#7){.+.+}-{0:0}, at: __x64_sys_fallocate+0x42/0x70
[ 367.993809] #1: ffff888466a00d70 (&sb->s_type->i_mutex_key#13){++++}-{3:3}, at: ext4_fallocate+0x110/0x1140
[ 367.993818] 2 locks held by less/3875:
[ 367.993820] #0: ffff888142f518a0 (&tty->ldisc_sem){++++}-{0:0}, at: tty_ldisc_ref_wait+0x24/0x50
[ 367.993828] #1: ffffc900022ea2f0 (&ldata->atomic_read_lock){+.+.}-{3:3}, at: n_tty_read+0x51b/0x650
[ 367.993838] =============================================
Translating the various lock acquisition locations:
addr2line -p -i -e /home/andres/src/kernel/vmlinux ext4_file_write_iter+0x435/0xa90
/home/andres/src/kernel/./include/linux/fs.h:1073
(inlined by) /home/andres/src/kernel/fs/ext4/file.c:57
(inlined by) /home/andres/src/kernel/fs/ext4/file.c:564
(inlined by) /home/andres/src/kernel/fs/ext4/file.c:715
addr2line -p -i -e /home/andres/src/kernel/vmlinux __x64_sys_fallocate+0x42/0x70
/home/andres/src/kernel/./include/linux/file.h:45
(inlined by) /home/andres/src/kernel/fs/open.c:348
(inlined by) /home/andres/src/kernel/fs/open.c:355
(inlined by) /home/andres/src/kernel/fs/open.c:353
(inlined by) /home/andres/src/kernel/fs/open.c:353
addr2line -p -i -e /home/andres/src/kernel/vmlinux ext4_fallocate+0x110/0x1140
/home/andres/src/kernel/./arch/x86/include/asm/bitops.h:207
(inlined by) /home/andres/src/kernel/./arch/x86/include/asm/bitops.h:239
(inlined by) /home/andres/src/kernel/./include/asm-generic/bitops/instrumented-non-atomic.h:142
(inlined by) /home/andres/src/kernel/fs/ext4/ext4.h:1922
(inlined by) /home/andres/src/kernel/fs/ext4/extents.c:4735
I think the addresses that lockdep computes must be off a bit - it sure looks
like instead of the address that ext4_fallocate+0x110 maps to, the acquisition
instead was the preceding line, i.e. the inode_lock().
fs/ext4/extents.c:
4727 max_blocks = EXT4_MAX_BLOCKS(len, offset, blkbits);
0xffffffff815d9de0 <ext4_fallocate+256>: and %rdx,%rax
0xffffffff815d9de3 <ext4_fallocate+259>: sar %cl,%rax
0xffffffff815d9de6 <ext4_fallocate+262>: sub %esi,%eax
0xffffffff815d9de8 <ext4_fallocate+264>: mov %eax,-0x60(%rbp)
./include/linux/fs.h:
802 down_write(&inode->i_rwsem);
0xffffffff815d9deb <ext4_fallocate+267>: call 0xffffffff8276c0c0 <down_write>
./arch/x86/include/asm/bitops.h:
206 return ((1UL << (nr & (BITS_PER_LONG-1))) &
0xffffffff815d9df0 <ext4_fallocate+272>: mov -0x260(%rbx),%rax
fs/ext4/extents.c:
4735 if (!(ext4_test_inode_flag(inode, EXT4_INODE_EXTENTS))) {
Looking at the code, I assume the reason lockdep doesn't fire is that it
doesn't understand wait edges via __inode_dio_wait().
Greetings,
Andres Freund
[TLDR: I'm adding this report to the list of tracked Linux kernel
regressions; the text you find below is based on a few templates
paragraphs you might have encountered already in similar form.
See link in footer if these mails annoy you.]
On 17.10.23 05:37, Andres Freund wrote:
>
> As previously reported in https://lore.kernel.org/all/[email protected]/
> I found some hangs below ext4_fallocate(), in 6.6-rc*. As it looks like my
> issue was unrelated to the thread I had responded to, I was asked to start
> this new thread.
>
> I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
> it took ~55min of high load (io_uring using branch of postgres, running a
> write heavy transactional workload concurrently with concurrent bulk data
> load) to trigger the issue.
>
> For now I have left the system running, in case there's something you would
> like me to check while the system is hung.
> [...]
Thanks for the report. To be sure the issue doesn't fall through the
cracks unnoticed, I'm adding it to regzbot, the Linux kernel regression
tracking bot:
#regzbot ^introduced v6.5..v6.6-rc6
#regzbot title ext4: task hung in ext4_fallocate
#regzbot ignore-activity
This isn't a regression? This issue or a fix for it are already
discussed somewhere else? It was fixed already? You want to clarify when
the regression started to happen? Or point out I got the title or
something else totally wrong? Then just reply and tell me -- ideally
while also telling regzbot about it, as explained by the page listed in
the footer of this mail.
Developers: When fixing the issue, remember to add 'Link:' tags pointing
to the report (the parent of this mail). See page linked in footer for
details.
Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
--
Everything you wanna know about Linux kernel regression tracking:
https://linux-regtracking.leemhuis.info/about/#tldr
That page also explains what to do if mails like this annoy you.
[cc Jens, io-uring]
On Tue, Oct 17, 2023 at 07:50:09PM -0700, Andres Freund wrote:
> Hi,
>
> On 2023-10-17 20:43:35 -0400, Theodore Ts'o wrote:
> > On Mon, Oct 16, 2023 at 08:37:25PM -0700, Andres Freund wrote:
> > > I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
> > > it took ~55min of high load (io_uring using branch of postgres, running a
> > > write heavy transactional workload concurrently with concurrent bulk data
> > > load) to trigger the issue.
> > >
> > > For now I have left the system running, in case there's something you would
> > > like me to check while the system is hung.
> > >
> > > The first hanging task that I observed:
> > >
> > > cat /proc/57606/stack
> > > [<0>] inode_dio_wait+0xd5/0x100
> > > [<0>] ext4_fallocate+0x12f/0x1040
> > > [<0>] vfs_fallocate+0x135/0x360
> > > [<0>] __x64_sys_fallocate+0x42/0x70
> > > [<0>] do_syscall_64+0x38/0x80
> > > [<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
> >
> > This stack trace is from some process (presumably postgres) trying to
> > do a fallocate() system call:
>
> Yes, it's indeed postgres.
>
>
> > > [ 3194.579297] INFO: task iou-wrk-58004:58874 blocked for more than 122 seconds.
> > > [ 3194.579304] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
> > > [ 3194.579310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > > [ 3194.579314] task:iou-wrk-58004 state:D stack:0 pid:58874 ppid:52606 flags:0x00004000
> > > [ 3194.579325] Call Trace:
> > > [ 3194.579329] <TASK>
> > > [ 3194.579334] __schedule+0x388/0x13e0
> > > [ 3194.579349] schedule+0x5f/0xe0
> > > [ 3194.579361] schedule_preempt_disabled+0x15/0x20
> > > [ 3194.579374] rwsem_down_read_slowpath+0x26e/0x4c0
> > > [ 3194.579385] down_read+0x44/0xa0
> > > [ 3194.579393] ext4_file_write_iter+0x432/0xa80
> > > [ 3194.579407] io_write+0x129/0x420
> >
> > This could potentially be a interesting stack trace; but this is where
> > we really need to map the stack address to line numbers. Is that
> > something you could do?
>
> Converting the above with scripts/decode_stacktrace.sh yields:
>
> __schedule (kernel/sched/core.c:5382 kernel/sched/core.c:6695)
> schedule (./arch/x86/include/asm/preempt.h:85 (discriminator 13) kernel/sched/core.c:6772 (discriminator 13))
> schedule_preempt_disabled (./arch/x86/include/asm/preempt.h:80 (discriminator 10) kernel/sched/core.c:6831 (discriminator 10))
> rwsem_down_read_slowpath (kernel/locking/rwsem.c:1073 (discriminator 4))
> down_read (./arch/x86/include/asm/preempt.h:95 kernel/locking/rwsem.c:1257 kernel/locking/rwsem.c:1263 kernel/locking/rwsem.c:1522)
> ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
> io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
>
> But I'm not sure that that stacktrace is quite right (e.g. what's
> ./include/linux/fs.h:1073 doing in this stacktrace?). But with an optimized
> build it's a bit hard to tell what's an optimization artifact and what's an
> off stack trace...
>
>
> I had the idea to look at the stacks (via /proc/$pid/stack) for all postgres
> processes and the associated io-uring threads, and then to deduplicate them.
>
> 22x:
> ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
> io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
> io_issue_sqe (io_uring/io_uring.c:1878)
> io_wq_submit_work (io_uring/io_uring.c:1960)
> io_worker_handle_work (io_uring/io-wq.c:596)
> io_wq_worker (io_uring/io-wq.c:258 io_uring/io-wq.c:648)
> ret_from_fork (arch/x86/kernel/process.c:147)
> ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
io_uring does some interesting stuff with IO completion and iomap
now - IIRC IOCB_DIO_CALLER_COMP is new 6.6-rc1 functionality. This
flag is set by io_write() to tell the iomap IO completion handler
that the caller will the IO completion, avoiding a context switch
to run the completion in a kworker thread.
It's not until the caller runs iocb->dio_complete() that
inode_dio_end() is called to drop the i_dio_count. This happens when
io_uring gets completion notification from iomap via
iocb->ki_complete(iocb, 0);
It then requires the io_uring layer to process the completion
and call iocb->dio_complete() before the inode->i_dio_count is
dropped and inode_dio_wait() will complete.
So what I suspect here is that we have a situation where the worker
that would run the completion is blocked on the inode rwsem because
this isn't a IOCB_NOWAIT IO and the fallocate call holds the rwsem
exclusive and is waiting on inode_dio_wait() to return.
Cc Jens, because I'm not sure this is actually an ext4 problem - I
can't see why XFS won't have the same issue w.r.t.
truncate/fallocate and IOCB_DIO_CALLER_COMP delaying the
inode_dio_end() until whenever the io_uring code can get around to
processing the delayed completion....
-Dave.
>
> 8x:
> __do_sys_io_uring_enter (io_uring/io_uring.c:2553 (discriminator 1) io_uring/io_uring.c:2622 (discriminator 1) io_uring/io_uring.c:3706 (discriminator 1))
> do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
>
> 2x:
> io_wq_worker (./arch/x86/include/asm/current.h:41 (discriminator 5) io_uring/io-wq.c:668 (discriminator 5))
> ret_from_fork (arch/x86/kernel/process.c:147)
> ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
>
> 2x:
> futex_wait_queue (./arch/x86/include/asm/current.h:41 (discriminator 5) kernel/futex/waitwake.c:357 (discriminator 5))
> futex_wait (kernel/futex/waitwake.c:660)
> do_futex (kernel/futex/syscalls.c:106 (discriminator 1))
> __x64_sys_futex (kernel/futex/syscalls.c:183 kernel/futex/syscalls.c:164 kernel/futex/syscalls.c:164)
> do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
>
> 1x:
> do_epoll_wait (fs/eventpoll.c:1921 (discriminator 1) fs/eventpoll.c:2318 (discriminator 1))
> __x64_sys_epoll_wait (fs/eventpoll.c:2325)
> do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
>
> 1x:
> inode_dio_wait (./arch/x86/include/asm/atomic.h:23 ./include/linux/atomic/atomic-arch-fallback.h:444 ./include/linux/atomic/atomic-instrumented.h:33 fs/inode.c:2429 fs/inode.c:2446)
> ext4_fallocate (fs/ext4/extents.c:4752)
> vfs_fallocate (fs/open.c:324)
> __x64_sys_fallocate (./include/linux/file.h:45 fs/open.c:348 fs/open.c:355 fs/open.c:353 fs/open.c:353)
> do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
>
>
>
>
> > > Once I hear that you don't want me to test something out on the running
> > > system, I think a sensible next step could be to compile with lockdep and see
> > > if that finds a problem?
> >
> > That's certainly a possibiity. But also please make sure that you can
> > compile with with debugging information enabled so that we can get
> > reliable line numbers. I use:
> >
> > CONFIG_DEBUG_INFO=y
> > CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y
> > CONFIG_DEBUG_INFO_REDUCED=y
>
> The kernel from above had debug info enabled, albeit forced to dwarf4 (IIRC I
> ran into issues with pahole not understanding all of dwarf5):
>
> $ zgrep DEBUG_INFO /proc/config.gz
> CONFIG_DEBUG_INFO=y
> # CONFIG_DEBUG_INFO_NONE is not set
> # CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT is not set
> CONFIG_DEBUG_INFO_DWARF4=y
> # CONFIG_DEBUG_INFO_DWARF5 is not set
> # CONFIG_DEBUG_INFO_REDUCED is not set
> CONFIG_DEBUG_INFO_COMPRESSED_NONE=y
> # CONFIG_DEBUG_INFO_COMPRESSED_ZLIB is not set
> # CONFIG_DEBUG_INFO_COMPRESSED_ZSTD is not set
> # CONFIG_DEBUG_INFO_SPLIT is not set
> CONFIG_DEBUG_INFO_BTF=y
> CONFIG_DEBUG_INFO_BTF_MODULES=y
>
> I switched it to CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y and am rebuilding
> with lockdep enabled. Curious to see how long it'll take to trigger the
> problem with it enabled...
>
> Greetings,
>
> Andres Freund
>
--
Dave Chinner
[email protected]
Hi,
On 2023-10-24 12:12:23 +1100, Dave Chinner wrote:
> [cc Jens, io-uring]
Yes, good call, had been meaning to do that but forgot.
> On Tue, Oct 17, 2023 at 07:50:09PM -0700, Andres Freund wrote:
> > I had the idea to look at the stacks (via /proc/$pid/stack) for all postgres
> > processes and the associated io-uring threads, and then to deduplicate them.
> >
> > 22x:
> > ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
> > io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
> > io_issue_sqe (io_uring/io_uring.c:1878)
> > io_wq_submit_work (io_uring/io_uring.c:1960)
> > io_worker_handle_work (io_uring/io-wq.c:596)
> > io_wq_worker (io_uring/io-wq.c:258 io_uring/io-wq.c:648)
> > ret_from_fork (arch/x86/kernel/process.c:147)
> > ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
>
> io_uring does some interesting stuff with IO completion and iomap
> now - IIRC IOCB_DIO_CALLER_COMP is new 6.6-rc1 functionality. This
> flag is set by io_write() to tell the iomap IO completion handler
> that the caller will the IO completion, avoiding a context switch
> to run the completion in a kworker thread.
>
> It's not until the caller runs iocb->dio_complete() that
> inode_dio_end() is called to drop the i_dio_count. This happens when
> io_uring gets completion notification from iomap via
> iocb->ki_complete(iocb, 0);
>
> It then requires the io_uring layer to process the completion
> and call iocb->dio_complete() before the inode->i_dio_count is
> dropped and inode_dio_wait() will complete.
>
> So what I suspect here is that we have a situation where the worker
> that would run the completion is blocked on the inode rwsem because
> this isn't a IOCB_NOWAIT IO and the fallocate call holds the rwsem
> exclusive and is waiting on inode_dio_wait() to return.
>
> Cc Jens, because I'm not sure this is actually an ext4 problem - I
> can't see why XFS won't have the same issue w.r.t.
> truncate/fallocate and IOCB_DIO_CALLER_COMP delaying the
> inode_dio_end() until whenever the io_uring code can get around to
> processing the delayed completion....
The absence of a reproducer obviously is not proof of an absence of
problems. With that said, I have run the workload on xfs for far longer on
both bigger and smaller machines, without triggering the same symptoms.
Greetings,
Andres Freund
On 10/23/23 7:12 PM, Dave Chinner wrote:
> [cc Jens, io-uring]
Thanks!
> On Tue, Oct 17, 2023 at 07:50:09PM -0700, Andres Freund wrote:
>> Hi,
>>
>> On 2023-10-17 20:43:35 -0400, Theodore Ts'o wrote:
>>> On Mon, Oct 16, 2023 at 08:37:25PM -0700, Andres Freund wrote:
>>>> I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
>>>> it took ~55min of high load (io_uring using branch of postgres, running a
>>>> write heavy transactional workload concurrently with concurrent bulk data
>>>> load) to trigger the issue.
>>>>
>>>> For now I have left the system running, in case there's something you would
>>>> like me to check while the system is hung.
>>>>
>>>> The first hanging task that I observed:
>>>>
>>>> cat /proc/57606/stack
>>>> [<0>] inode_dio_wait+0xd5/0x100
>>>> [<0>] ext4_fallocate+0x12f/0x1040
>>>> [<0>] vfs_fallocate+0x135/0x360
>>>> [<0>] __x64_sys_fallocate+0x42/0x70
>>>> [<0>] do_syscall_64+0x38/0x80
>>>> [<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0
>>>
>>> This stack trace is from some process (presumably postgres) trying to
>>> do a fallocate() system call:
>>
>> Yes, it's indeed postgres.
>>
>>
>>>> [ 3194.579297] INFO: task iou-wrk-58004:58874 blocked for more than 122 seconds.
>>>> [ 3194.579304] Not tainted 6.6.0-rc6-andres-00001-g01edcfe38260 #77
>>>> [ 3194.579310] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>>>> [ 3194.579314] task:iou-wrk-58004 state:D stack:0 pid:58874 ppid:52606 flags:0x00004000
>>>> [ 3194.579325] Call Trace:
>>>> [ 3194.579329] <TASK>
>>>> [ 3194.579334] __schedule+0x388/0x13e0
>>>> [ 3194.579349] schedule+0x5f/0xe0
>>>> [ 3194.579361] schedule_preempt_disabled+0x15/0x20
>>>> [ 3194.579374] rwsem_down_read_slowpath+0x26e/0x4c0
>>>> [ 3194.579385] down_read+0x44/0xa0
>>>> [ 3194.579393] ext4_file_write_iter+0x432/0xa80
>>>> [ 3194.579407] io_write+0x129/0x420
>>>
>>> This could potentially be a interesting stack trace; but this is where
>>> we really need to map the stack address to line numbers. Is that
>>> something you could do?
>>
>> Converting the above with scripts/decode_stacktrace.sh yields:
>>
>> __schedule (kernel/sched/core.c:5382 kernel/sched/core.c:6695)
>> schedule (./arch/x86/include/asm/preempt.h:85 (discriminator 13) kernel/sched/core.c:6772 (discriminator 13))
>> schedule_preempt_disabled (./arch/x86/include/asm/preempt.h:80 (discriminator 10) kernel/sched/core.c:6831 (discriminator 10))
>> rwsem_down_read_slowpath (kernel/locking/rwsem.c:1073 (discriminator 4))
>> down_read (./arch/x86/include/asm/preempt.h:95 kernel/locking/rwsem.c:1257 kernel/locking/rwsem.c:1263 kernel/locking/rwsem.c:1522)
>> ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
>> io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
>>
>> But I'm not sure that that stacktrace is quite right (e.g. what's
>> ./include/linux/fs.h:1073 doing in this stacktrace?). But with an optimized
>> build it's a bit hard to tell what's an optimization artifact and what's an
>> off stack trace...
>>
>>
>> I had the idea to look at the stacks (via /proc/$pid/stack) for all postgres
>> processes and the associated io-uring threads, and then to deduplicate them.
>>
>> 22x:
>> ext4_file_write_iter (./include/linux/fs.h:1073 fs/ext4/file.c:57 fs/ext4/file.c:564 fs/ext4/file.c:715)
>> io_write (./include/linux/fs.h:1956 io_uring/rw.c:926)
>> io_issue_sqe (io_uring/io_uring.c:1878)
>> io_wq_submit_work (io_uring/io_uring.c:1960)
>> io_worker_handle_work (io_uring/io-wq.c:596)
>> io_wq_worker (io_uring/io-wq.c:258 io_uring/io-wq.c:648)
>> ret_from_fork (arch/x86/kernel/process.c:147)
>> ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
>
> io_uring does some interesting stuff with IO completion and iomap
> now - IIRC IOCB_DIO_CALLER_COMP is new 6.6-rc1 functionality. This
> flag is set by io_write() to tell the iomap IO completion handler
> that the caller will the IO completion, avoiding a context switch
> to run the completion in a kworker thread.
>
> It's not until the caller runs iocb->dio_complete() that
> inode_dio_end() is called to drop the i_dio_count. This happens when
> io_uring gets completion notification from iomap via
> iocb->ki_complete(iocb, 0);
>
> It then requires the io_uring layer to process the completion
> and call iocb->dio_complete() before the inode->i_dio_count is
> dropped and inode_dio_wait() will complete.
>
> So what I suspect here is that we have a situation where the worker
> that would run the completion is blocked on the inode rwsem because
> this isn't a IOCB_NOWAIT IO and the fallocate call holds the rwsem
> exclusive and is waiting on inode_dio_wait() to return.
>
> Cc Jens, because I'm not sure this is actually an ext4 problem - I
> can't see why XFS won't have the same issue w.r.t.
> truncate/fallocate and IOCB_DIO_CALLER_COMP delaying the
> inode_dio_end() until whenever the io_uring code can get around to
> processing the delayed completion....
I don't think this is related to the io-wq workers doing non-blocking
IO. The callback is eventually executed by the task that originally
submitted the IO, which is the owner and not the async workers. But...
If that original task is blocked in eg fallocate, then I can see how
that would potentially be an issue.
I'll take a closer look.
--
Jens Axboe
On 10/24/23 8:30 AM, Jens Axboe wrote:
> I don't think this is related to the io-wq workers doing non-blocking
> IO. The callback is eventually executed by the task that originally
> submitted the IO, which is the owner and not the async workers. But...
> If that original task is blocked in eg fallocate, then I can see how
> that would potentially be an issue.
>
> I'll take a closer look.
I think the best way to fix this is likely to have inode_dio_wait() be
interruptible, and return -ERESTARTSYS if it should be restarted. Now
the below is obviously not a full patch, but I suspect it'll make ext4
and xfs tick, because they should both be affected.
Andres, any chance you can throw this into the testing mix?
diff --git a/fs/ext4/extents.c b/fs/ext4/extents.c
index 202c76996b62..0d946b6d36fe 100644
--- a/fs/ext4/extents.c
+++ b/fs/ext4/extents.c
@@ -4747,7 +4747,9 @@ long ext4_fallocate(struct file *file, int mode, loff_t offset, loff_t len)
}
/* Wait all existing dio workers, newcomers will block on i_rwsem */
- inode_dio_wait(inode);
+ ret = inode_dio_wait(inode);
+ if (ret)
+ goto out;
ret = file_modified(file);
if (ret)
diff --git a/fs/inode.c b/fs/inode.c
index 84bc3c76e5cc..c4eca812b16b 100644
--- a/fs/inode.c
+++ b/fs/inode.c
@@ -2417,17 +2417,24 @@ EXPORT_SYMBOL(inode_owner_or_capable);
/*
* Direct i/o helper functions
*/
-static void __inode_dio_wait(struct inode *inode)
+static int __inode_dio_wait(struct inode *inode)
{
wait_queue_head_t *wq = bit_waitqueue(&inode->i_state, __I_DIO_WAKEUP);
DEFINE_WAIT_BIT(q, &inode->i_state, __I_DIO_WAKEUP);
+ int ret = 0;
do {
- prepare_to_wait(wq, &q.wq_entry, TASK_UNINTERRUPTIBLE);
- if (atomic_read(&inode->i_dio_count))
- schedule();
+ prepare_to_wait(wq, &q.wq_entry, TASK_INTERRUPTIBLE);
+ if (!atomic_read(&inode->i_dio_count))
+ break;
+ schedule();
+ if (signal_pending(current)) {
+ ret = -ERESTARTSYS;
+ break;
+ }
} while (atomic_read(&inode->i_dio_count));
finish_wait(wq, &q.wq_entry);
+ return ret;
}
/**
@@ -2440,10 +2447,11 @@ static void __inode_dio_wait(struct inode *inode)
* Must be called under a lock that serializes taking new references
* to i_dio_count, usually by inode->i_mutex.
*/
-void inode_dio_wait(struct inode *inode)
+int inode_dio_wait(struct inode *inode)
{
if (atomic_read(&inode->i_dio_count))
- __inode_dio_wait(inode);
+ return __inode_dio_wait(inode);
+ return 0;
}
EXPORT_SYMBOL(inode_dio_wait);
diff --git a/fs/xfs/xfs_file.c b/fs/xfs/xfs_file.c
index 203700278ddb..8ea0c414b173 100644
--- a/fs/xfs/xfs_file.c
+++ b/fs/xfs/xfs_file.c
@@ -936,7 +936,9 @@ xfs_file_fallocate(
* the on disk and in memory inode sizes, and the operations that follow
* require the in-memory size to be fully up-to-date.
*/
- inode_dio_wait(inode);
+ error = inode_dio_wait(inode);
+ if (error)
+ goto out_unlock;
/*
* Now AIO and DIO has drained we flush and (if necessary) invalidate
diff --git a/include/linux/fs.h b/include/linux/fs.h
index 4a40823c3c67..7dff3167cb0c 100644
--- a/include/linux/fs.h
+++ b/include/linux/fs.h
@@ -2971,7 +2971,7 @@ static inline ssize_t blockdev_direct_IO(struct kiocb *iocb,
}
#endif
-void inode_dio_wait(struct inode *inode);
+int inode_dio_wait(struct inode *inode);
/**
* inode_dio_begin - signal start of a direct I/O requests
--
Jens Axboe
On Tue, Oct 24, 2023 at 12:35:26PM -0600, Jens Axboe wrote:
> On 10/24/23 8:30 AM, Jens Axboe wrote:
> > I don't think this is related to the io-wq workers doing non-blocking
> > IO.
The io-wq worker that has deadlocked _must_ be doing blocking IO. If
it was doing non-blocking IO (i.e. IOCB_NOWAIT) then it would have
done a trylock and returned -EAGAIN to the worker for it to try
again later. I'm not sure that would avoid the issue, however - it
seems to me like it might just turn it into a livelock rather than a
deadlock....
> > The callback is eventually executed by the task that originally
> > submitted the IO, which is the owner and not the async workers. But...
> > If that original task is blocked in eg fallocate, then I can see how
> > that would potentially be an issue.
> >
> > I'll take a closer look.
>
> I think the best way to fix this is likely to have inode_dio_wait() be
> interruptible, and return -ERESTARTSYS if it should be restarted. Now
> the below is obviously not a full patch, but I suspect it'll make ext4
> and xfs tick, because they should both be affected.
How does that solve the problem? Nothing will issue a signal to the
process that is waiting in inode_dio_wait() except userspace, so I
can't see how this does anything to solve the problem at hand...
I'm also very leary of adding new error handling complexity to paths
like truncate, extent cloning, fallocate, etc which expect to block
on locks until they can perform the operation safely.
On further thinking, this could be a self deadlock with
just async direct IO submission - submit an async DIO with
IOCB_CALLER_COMP, then run an unaligned async DIO that attempts to
drain in-flight DIO before continuing. Then the thread waits in
inode_dio_wait() because it can't run the completion that will drop
the i_dio_count to zero.
Hence it appears to me that we've missed some critical constraints
around nesting IO submission and completion when using
IOCB_CALLER_COMP. Further, it really isn't clear to me how deep the
scope of this problem is yet, let alone what the solution might be.
With all this in mind, and how late this is in the 6.6 cycle, can we
just revert the IOCB_CALLER_COMP changes for now?
-Dave.
--
Dave Chinner
[email protected]
On 10/24/23 6:06 PM, Dave Chinner wrote:
> On Tue, Oct 24, 2023 at 12:35:26PM -0600, Jens Axboe wrote:
>> On 10/24/23 8:30 AM, Jens Axboe wrote:
>>> I don't think this is related to the io-wq workers doing non-blocking
>>> IO.
>
> The io-wq worker that has deadlocked _must_ be doing blocking IO. If
> it was doing non-blocking IO (i.e. IOCB_NOWAIT) then it would have
> done a trylock and returned -EAGAIN to the worker for it to try
> again later. I'm not sure that would avoid the issue, however - it
> seems to me like it might just turn it into a livelock rather than a
> deadlock....
Sorry typo, yes they are doing blocking IO, that's all they ever do. My
point is that it's not related to the issue.
>>> The callback is eventually executed by the task that originally
>>> submitted the IO, which is the owner and not the async workers. But...
>>> If that original task is blocked in eg fallocate, then I can see how
>>> that would potentially be an issue.
>>>
>>> I'll take a closer look.
>>
>> I think the best way to fix this is likely to have inode_dio_wait() be
>> interruptible, and return -ERESTARTSYS if it should be restarted. Now
>> the below is obviously not a full patch, but I suspect it'll make ext4
>> and xfs tick, because they should both be affected.
>
> How does that solve the problem? Nothing will issue a signal to the
> process that is waiting in inode_dio_wait() except userspace, so I
> can't see how this does anything to solve the problem at hand...
Except task_work, which when it completes, will increment the i_dio
count again. This is the whole point of the half assed patch I sent out.
> I'm also very leary of adding new error handling complexity to paths
> like truncate, extent cloning, fallocate, etc which expect to block
> on locks until they can perform the operation safely.
I actually looked at all of them, ext4 and xfs specifically. It really
doesn't seem to bad.
> On further thinking, this could be a self deadlock with
> just async direct IO submission - submit an async DIO with
> IOCB_CALLER_COMP, then run an unaligned async DIO that attempts to
> drain in-flight DIO before continuing. Then the thread waits in
> inode_dio_wait() because it can't run the completion that will drop
> the i_dio_count to zero.
No, because those will be non-blocking. Any blocking IO will go via
io-wq, and that won't then hit the deadlock. If you're doing
inode_dio_wait() from the task itself for a non-blocking issue, then
that would surely be an issue. But we should not be doing that, and we
are checking for it.
> Hence it appears to me that we've missed some critical constraints
> around nesting IO submission and completion when using
> IOCB_CALLER_COMP. Further, it really isn't clear to me how deep the
> scope of this problem is yet, let alone what the solution might be.
I think you're missing exactly what the deadlock is.
> With all this in mind, and how late this is in the 6.6 cycle, can we
> just revert the IOCB_CALLER_COMP changes for now?
Yeah I'm going to do a revert of the io_uring side, which effectively
disables it. Then a revised series can be done, and when done, we could
bring it back.
--
Jens Axboe
Hi,
On 2023-10-24 18:34:05 -0600, Jens Axboe wrote:
> Yeah I'm going to do a revert of the io_uring side, which effectively
> disables it. Then a revised series can be done, and when done, we could
> bring it back.
I'm queueing a test to confirm that the revert actually fixes things. Is there
still benefit in testing your other patch in addition upstream?
Greetings,
Andres Freund
On 10/25/23 9:31 AM, Andres Freund wrote:
> Hi,
>
> On 2023-10-24 18:34:05 -0600, Jens Axboe wrote:
>> Yeah I'm going to do a revert of the io_uring side, which effectively
>> disables it. Then a revised series can be done, and when done, we could
>> bring it back.
>
> I'm queueing a test to confirm that the revert actually fixes things.
> Is there still benefit in testing your other patch in addition
> upstream?
Don't think there's much point to testing the quick hack, I believe it
should work. So testing the most recent revert is useful, though I also
fully expect that to work. And then we can test the re-enable once that
is sent out, I did prepare a series. But timing is obviously unfortunate
for that, as it'll miss 6.6 and now also 6.7 due to the report timing.
FWIW, I wrote a small test case which does seem to trigger it very fast,
as expected:
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <fcntl.h>
#include <string.h>
#include <liburing.h>
#define BS 4096
#define FSIZE (128 * 1024 * 1024UL)
static int set_file_size(int fd, off_t file_size)
{
off_t this_size;
char buf[BS];
int ret;
memset(buf, 0, BS);
this_size = 0;
while (this_size < file_size) {
ret = write(fd, buf, BS);
if (ret != BS) {
fprintf(stderr, "write ret %d\n", ret);
return 1;
}
this_size += BS;
}
fsync(fd);
posix_fadvise(fd, 0, file_size, POSIX_FADV_DONTNEED);
return 0;
}
int main(int argc, char *argv[])
{
struct io_uring_sqe *sqe;
struct io_uring_cqe *cqe;
struct io_uring ring;
off_t off, foff;
int fd, i, ret;
void *buf;
if (argc < 2) {
fprintf(stderr, "%s <file>\n", argv[0]);
return 1;
}
fd = open(argv[1], O_RDWR | O_CREAT | O_TRUNC | O_DIRECT, 0644);
if (fd < 0) {
perror("open");
return 1;
}
if (set_file_size(fd, FSIZE))
return 1;
if (posix_memalign(&buf, 4096, BS))
return 1;
io_uring_queue_init(8, &ring, 0);
i = 0;
off = 0;
foff = FSIZE + BS;
do {
sqe = io_uring_get_sqe(&ring);
io_uring_prep_write(sqe, fd, buf, BS, off);
off += BS;
if (off == FSIZE)
off = 0;
io_uring_submit(&ring);
ret = posix_fallocate(fd, 0, foff);
if (ret < 0) {
perror("fallocate");
return 1;
}
foff += BS;
ret = io_uring_wait_cqe(&ring, &cqe);
if (ret) {
fprintf(stderr, "wait cqe %d\n", ret);
return 1;
}
io_uring_cqe_seen(&ring, cqe);
i++;
if (!(i & 1023))
fprintf(stdout, "Loop iteration %d\n", i);
} while (1);
return 0;
}
--
Jens Axboe
Hi,
On 2023-10-25 09:36:01 -0600, Jens Axboe wrote:
> On 10/25/23 9:31 AM, Andres Freund wrote:
> > Hi,
> >
> > On 2023-10-24 18:34:05 -0600, Jens Axboe wrote:
> >> Yeah I'm going to do a revert of the io_uring side, which effectively
> >> disables it. Then a revised series can be done, and when done, we could
> >> bring it back.
> >
> > I'm queueing a test to confirm that the revert actually fixes things.
> > Is there still benefit in testing your other patch in addition
> > upstream?
>
> Don't think there's much point to testing the quick hack, I believe it
> should work. So testing the most recent revert is useful, though I also
> fully expect that to work.
I'll leave it running for a few hours, just to be sure.
> And then we can test the re-enable once that is sent out, I did prepare a
> series. But timing is obviously unfortunate for that, as it'll miss 6.6 and
> now also 6.7 due to the report timing.
Yea, it's too bad. I'm somewhat lucky to have hit it at all, it was just due
to having procrastinated on talk preparation and having to test things on my
laptop instead of my workstation (where the same workload never triggered the
problem), while travelling.
> FWIW, I wrote a small test case which does seem to trigger it very fast,
> as expected:
Ah, nice.
It's too bad stuff like this can't be discovered by lockdep et al..
Greetings,
Andres Freund
On Wed, Oct 25, 2023 at 09:36:01AM -0600, Jens Axboe wrote:
>
> FWIW, I wrote a small test case which does seem to trigger it very fast,
> as expected:
Great! I was about to ask if we had an easy reproducer. Any chance
you can package this up as an test in xfstests? Or would you like
some help with that?
Thanks,
- Ted
On Tue, Oct 24, 2023 at 06:34:05PM -0600, Jens Axboe wrote:
> On 10/24/23 6:06 PM, Dave Chinner wrote:
> > On Tue, Oct 24, 2023 at 12:35:26PM -0600, Jens Axboe wrote:
> >> On 10/24/23 8:30 AM, Jens Axboe wrote:
> >>> I don't think this is related to the io-wq workers doing non-blocking
> >>> IO.
> >
> > The io-wq worker that has deadlocked _must_ be doing blocking IO. If
> > it was doing non-blocking IO (i.e. IOCB_NOWAIT) then it would have
> > done a trylock and returned -EAGAIN to the worker for it to try
> > again later. I'm not sure that would avoid the issue, however - it
> > seems to me like it might just turn it into a livelock rather than a
> > deadlock....
>
> Sorry typo, yes they are doing blocking IO, that's all they ever do. My
> point is that it's not related to the issue.
>
> >>> The callback is eventually executed by the task that originally
> >>> submitted the IO, which is the owner and not the async workers. But...
> >>> If that original task is blocked in eg fallocate, then I can see how
> >>> that would potentially be an issue.
> >>>
> >>> I'll take a closer look.
> >>
> >> I think the best way to fix this is likely to have inode_dio_wait() be
> >> interruptible, and return -ERESTARTSYS if it should be restarted. Now
> >> the below is obviously not a full patch, but I suspect it'll make ext4
> >> and xfs tick, because they should both be affected.
> >
> > How does that solve the problem? Nothing will issue a signal to the
> > process that is waiting in inode_dio_wait() except userspace, so I
> > can't see how this does anything to solve the problem at hand...
>
> Except task_work, which when it completes, will increment the i_dio
> count again. This is the whole point of the half assed patch I sent out.
What task_work is that? When does that actually run?
Please don't assume that everyone is intimately familiar with the
subtle complexities of io_uring infrastructure - if the fix relies
on a signal from -somewhere- then you need to explain where
that signal comes from and why we should be able to rely on that...
>
> > I'm also very leary of adding new error handling complexity to paths
> > like truncate, extent cloning, fallocate, etc which expect to block
> > on locks until they can perform the operation safely.
>
> I actually looked at all of them, ext4 and xfs specifically. It really
> doesn't seem to bad.
>
> > On further thinking, this could be a self deadlock with
> > just async direct IO submission - submit an async DIO with
> > IOCB_CALLER_COMP, then run an unaligned async DIO that attempts to
> > drain in-flight DIO before continuing. Then the thread waits in
> > inode_dio_wait() because it can't run the completion that will drop
> > the i_dio_count to zero.
>
> No, because those will be non-blocking. Any blocking IO will go via
> io-wq, and that won't then hit the deadlock. If you're doing
> inode_dio_wait() from the task itself for a non-blocking issue, then
> that would surely be an issue. But we should not be doing that, and we
> are checking for it.
There's no documentation that says IO submission inside a
IOCB_DIO_CALLER_COMP context must be IOCB_NOWAIT.
I don't recall it being mentioned during patch submission or review,
and if it was ithe implications certainly didn't register with me -
I would not have given a rvb without such a landmine either being
removed or very well documented.
I don't see anywhere that is checked and I don't see how it can be,
because the filesystem IO submission path itself has no idea if the
caller is already has a IOCB_DIO_CALLER_COMP IO in flight and
pending completion.
> > Hence it appears to me that we've missed some critical constraints
> > around nesting IO submission and completion when using
> > IOCB_CALLER_COMP. Further, it really isn't clear to me how deep the
> > scope of this problem is yet, let alone what the solution might be.
>
> I think you're missing exactly what the deadlock is.
Then you need to explain exactly what it is, not send undocumented
hacks that appear to do absolutely nothing to fix the problem.
> > With all this in mind, and how late this is in the 6.6 cycle, can we
> > just revert the IOCB_CALLER_COMP changes for now?
>
> Yeah I'm going to do a revert of the io_uring side, which effectively
> disables it. Then a revised series can be done, and when done, we could
> bring it back.
Please revert the whole lot, I'm now unconvinced that this is
functionality we can sanely support at the filesystem level without
a whole lot more thought.
-Dave.
--
Dave Chinner
[email protected]
Hi,
On 2023-10-25 09:14:05 -0700, Andres Freund wrote:
> On 2023-10-25 09:36:01 -0600, Jens Axboe wrote:
> > On 10/25/23 9:31 AM, Andres Freund wrote:
> > > Hi,
> > >
> > > On 2023-10-24 18:34:05 -0600, Jens Axboe wrote:
> > >> Yeah I'm going to do a revert of the io_uring side, which effectively
> > >> disables it. Then a revised series can be done, and when done, we could
> > >> bring it back.
> > >
> > > I'm queueing a test to confirm that the revert actually fixes things.
> > > Is there still benefit in testing your other patch in addition
> > > upstream?
> >
> > Don't think there's much point to testing the quick hack, I believe it
> > should work. So testing the most recent revert is useful, though I also
> > fully expect that to work.
>
> I'll leave it running for a few hours, just to be sure.
Quite a few hours and > 15TBW written later, no hang....
Greetings,
Andres Freund
On 10/25/23 1:55 PM, Theodore Ts'o wrote:
> On Wed, Oct 25, 2023 at 09:36:01AM -0600, Jens Axboe wrote:
>>
>> FWIW, I wrote a small test case which does seem to trigger it very fast,
>> as expected:
>
> Great! I was about to ask if we had an easy reproducer. Any chance
> you can package this up as an test in xfstests? Or would you like
> some help with that?
I think it's good to convert to a test case as-is, would just need to
loop X iterations or something rather than go forever. If you want to
run with it, please do!
--
Jens Axboe
On 10/25/23 4:28 PM, Dave Chinner wrote:
> On Tue, Oct 24, 2023 at 06:34:05PM -0600, Jens Axboe wrote:
>> On 10/24/23 6:06 PM, Dave Chinner wrote:
>>> On Tue, Oct 24, 2023 at 12:35:26PM -0600, Jens Axboe wrote:
>>>> On 10/24/23 8:30 AM, Jens Axboe wrote:
>>>>> I don't think this is related to the io-wq workers doing non-blocking
>>>>> IO.
>>>
>>> The io-wq worker that has deadlocked _must_ be doing blocking IO. If
>>> it was doing non-blocking IO (i.e. IOCB_NOWAIT) then it would have
>>> done a trylock and returned -EAGAIN to the worker for it to try
>>> again later. I'm not sure that would avoid the issue, however - it
>>> seems to me like it might just turn it into a livelock rather than a
>>> deadlock....
>>
>> Sorry typo, yes they are doing blocking IO, that's all they ever do. My
>> point is that it's not related to the issue.
>>
>>>>> The callback is eventually executed by the task that originally
>>>>> submitted the IO, which is the owner and not the async workers. But...
>>>>> If that original task is blocked in eg fallocate, then I can see how
>>>>> that would potentially be an issue.
>>>>>
>>>>> I'll take a closer look.
>>>>
>>>> I think the best way to fix this is likely to have inode_dio_wait() be
>>>> interruptible, and return -ERESTARTSYS if it should be restarted. Now
>>>> the below is obviously not a full patch, but I suspect it'll make ext4
>>>> and xfs tick, because they should both be affected.
>>>
>>> How does that solve the problem? Nothing will issue a signal to the
>>> process that is waiting in inode_dio_wait() except userspace, so I
>>> can't see how this does anything to solve the problem at hand...
>>
>> Except task_work, which when it completes, will increment the i_dio
>> count again. This is the whole point of the half assed patch I sent out.
>
> What task_work is that? When does that actually run?
>
> Please don't assume that everyone is intimately familiar with the
> subtle complexities of io_uring infrastructure - if the fix relies
> on a signal from -somewhere- then you need to explain where
> that signal comes from and why we should be able to rely on that...
Sorry yes, I should explain that more clearly.
For buffered reads/writes, we get the completion on the IRQ side, as you
know. io_uring posts the completion from task context, for which it uses
task_work to do so. task_work is run by the task itself, when it exits
to userspace from the kernel. TIF_NOTIFY_SIGNAL is used for this, which
is like per-thread signals, not shared across thread groups. But they do
break waiting, so we can exit and process them.
With the iomap workqueue punt, we get the block layer callback and then
queue processing to the workqueue. Once that is run, we'll queue up the
task_work and post the completion. With DIO_CALLER_COMP, we move more of
this context to the task_work, most notably the inode_dio_end(). And
this is where our problem is coming from. Now we need the task to
actually run this task_work, and when the task does inode_dio_wait() and
blocks in there, we have a deadlock where we are waiting on task_work
being run to run inode_dio_end(), yet preventing it from actually
running.
>>> I'm also very leary of adding new error handling complexity to paths
>>> like truncate, extent cloning, fallocate, etc which expect to block
>>> on locks until they can perform the operation safely.
>>
>> I actually looked at all of them, ext4 and xfs specifically. It really
>> doesn't seem to bad.
>>
>>> On further thinking, this could be a self deadlock with
>>> just async direct IO submission - submit an async DIO with
>>> IOCB_CALLER_COMP, then run an unaligned async DIO that attempts to
>>> drain in-flight DIO before continuing. Then the thread waits in
>>> inode_dio_wait() because it can't run the completion that will drop
>>> the i_dio_count to zero.
>>
>> No, because those will be non-blocking. Any blocking IO will go via
>> io-wq, and that won't then hit the deadlock. If you're doing
>> inode_dio_wait() from the task itself for a non-blocking issue, then
>> that would surely be an issue. But we should not be doing that, and we
>> are checking for it.
>
> There's no documentation that says IO submission inside a
> IOCB_DIO_CALLER_COMP context must be IOCB_NOWAIT.
>
> I don't recall it being mentioned during patch submission or review,
> and if it was ithe implications certainly didn't register with me -
> I would not have given a rvb without such a landmine either being
> removed or very well documented.
>
> I don't see anywhere that is checked and I don't see how it can be,
> because the filesystem IO submission path itself has no idea if the
> caller is already has a IOCB_DIO_CALLER_COMP IO in flight and
> pending completion.
The io-wq threads can do IOCB_DIO_CALLER_COMP with blocking writes just
fine, as they are not the ones that will ultimately run the task_work
that does inode_dio_end(). Hence there's no deadlock from that
perspective.
The task that runs the task_work that does inode_dio_end() must not be
calling inode_dio_wait() blocking, that would run into this deadlock
we're currently seeing with fallocate. See end-of-email for a lockdep
addition for this.
>>> Hence it appears to me that we've missed some critical constraints
>>> around nesting IO submission and completion when using
>>> IOCB_CALLER_COMP. Further, it really isn't clear to me how deep the
>>> scope of this problem is yet, let alone what the solution might be.
>>
>> I think you're missing exactly what the deadlock is.
>
> Then you need to explain exactly what it is, not send undocumented
> hacks that appear to do absolutely nothing to fix the problem.
For the io-wq case, when a write completes, it's queued with the
_original_ task for processing, and the original task is the one that
will run the task_work and hence inode_dio_done(). This is why it's
totally fine for io-wq to do blocking writes, even hitting
inode_dio_wait() as well.
>>> With all this in mind, and how late this is in the 6.6 cycle, can we
>>> just revert the IOCB_CALLER_COMP changes for now?
>>
>> Yeah I'm going to do a revert of the io_uring side, which effectively
>> disables it. Then a revised series can be done, and when done, we could
>> bring it back.
>
> Please revert the whole lot, I'm now unconvinced that this is
> functionality we can sanely support at the filesystem level without
> a whole lot more thought.
I'd prefer just eliminating the caller for now. I already have a full
series that does the inode_dio_wait(), so let's please give that a go
first. The only other potential user of CALLER_COMP would be aio, and
that would need some substantial changes to enable it as-is. So we
should not really be at risk here, and I'd rather avoid doing another
round of merge conflicts with the whole thing.
I'll be posting that soon, for a 6.8 target. It's obviously too late for
6.7 at this point.
I did also look into adding lockdep support for this, so we can detect
the dependency, and it seems to be working for me. Here's the test case
on current -git with lockdep enabled. This shows that we have a
dependency with someone having done inode_dio_begin() and then
inode_dio_wait() on the same inode. With that in place, we should be
able to catch any violations of this. Trace:
[ 17.897351] ============================================
[ 17.897677] WARNING: possible recursive locking detected
[ 17.897999] 6.6.0-rc7-00123-g3a568e3a961b-dirty #4300 Not tainted
[ 17.898413] --------------------------------------------
[ 17.898783] falloc-dio/502 is trying to acquire lock:
[ 17.899135] ffff000205318648 (inode){++++}-{3:3}, at: xfs_file_fallocate+0x74/0x40
[ 17.899681]
[ 17.899681] but task is already holding lock:
[ 17.900085] ffff000205318648 (inode){++++}-{3:3}, at: __iomap_dio_rw+0x164/0x87c
[ 17.900606]
[ 17.900606] other info that might help us debug this:
[ 17.901058] Possible unsafe locking scenario:
[ 17.901058]
[ 17.901472] CPU0
[ 17.901645] ----
[ 17.901820] lock(inode);
[ 17.902014] lock(inode);
[ 17.902209]
[ 17.902209] *** DEADLOCK ***
[ 17.902209]
[ 17.902619] May be due to missing lock nesting notation
[ 17.902619]
[ 17.903089] 4 locks held by falloc-dio/502:
[ 17.903383] #0: ffff000205318648 (inode){++++}-{3:3}, at: __iomap_dio_rw+0x164/0c
[ 17.903926] #1: ffff0000c3e9d3e8 (sb_writers#12){.+.+}-{0:0}, at: vfs_fallocate+0
[ 17.904512] #2: ffff000205318338 (&sb->s_type->i_mutex_key#17){++++}-{3:3}, at: 4
[ 17.905158] #3: ffff0002053184c8 (mapping.invalidate_lock#3){+.+.}-{3:3}, at: xf4
[ 17.905808]
[ 17.905808] stack backtrace:
[ 17.906124] CPU: 0 PID: 502 Comm: falloc-dio Not tainted 6.6.0-rc7-00123-g3a568e30
[ 17.906762] Hardware name: linux,dummy-virt (DT)
[ 17.907094] Call trace:
[ 17.907270] dump_backtrace+0x90/0xe4
[ 17.907537] show_stack+0x14/0x1c
[ 17.907770] dump_stack_lvl+0x5c/0xa0
[ 17.908038] dump_stack+0x14/0x1c
[ 17.908297] print_deadlock_bug+0x24c/0x334
[ 17.908612] __lock_acquire+0xe18/0x20d4
[ 17.908876] lock_acquire+0x1e0/0x30c
[ 17.909137] inode_dio_wait+0xc8/0x114
[ 17.909378] xfs_file_fallocate+0x74/0x440
[ 17.909672] vfs_fallocate+0x1a0/0x2f0
[ 17.909943] ksys_fallocate+0x48/0x90
[ 17.910212] __arm64_sys_fallocate+0x1c/0x28
[ 17.910518] invoke_syscall+0x44/0x104
[ 17.910759] el0_svc_common.constprop.0+0xb4/0xd4
[ 17.911085] do_el0_svc+0x18/0x20
[ 17.911334] el0_svc+0x4c/0xec
[ 17.911549] el0t_64_sync_handler+0x118/0x124
[ 17.911833] el0t_64_sync+0x168/0x16c
--
Jens Axboe
[TLDR: This mail in primarily relevant for Linux regression tracking. A
change or fix related to the regression discussed in this thread was
posted or applied, but it did not use a Closes: tag to point to the
report, as Linus and the documentation call for. Things happen, no
worries -- but now the regression tracking bot needs to be told manually
about the fix. See link in footer if these mails annoy you.]
On 20.10.23 09:01, Linux regression tracking #adding (Thorsten Leemhuis)
wrote:
> On 17.10.23 05:37, Andres Freund wrote:
>>
>> As previously reported in https://lore.kernel.org/all/[email protected]/
>> I found some hangs below ext4_fallocate(), in 6.6-rc*. As it looks like my
>> issue was unrelated to the thread I had responded to, I was asked to start
>> this new thread.
>>
>> I just was able to reproduce the issue, after upgrading to 6.6-rc6 - this time
>> it took ~55min of high load (io_uring using branch of postgres, running a
>> write heavy transactional workload concurrently with concurrent bulk data
>> load) to trigger the issue.
>>
>> For now I have left the system running, in case there's something you would
>> like me to check while the system is hung.
>> [...]
>
> Thanks for the report. To be sure the issue doesn't fall through the
> cracks unnoticed, I'm adding it to regzbot, the Linux kernel regression
> tracking bot:
>
> #regzbot ^introduced v6.5..v6.6-rc6
> #regzbot title ext4: task hung in ext4_fallocate
> #regzbot ignore-activity
#regzbot fix: 838b35bb6a89c36da07ca39520ec071d
#regzbot ignore-activity
Ciao, Thorsten (wearing his 'the Linux kernel's regression tracker' hat)
--
Everything you wanna know about Linux kernel regression tracking:
https://linux-regtracking.leemhuis.info/about/#tldr
That page also explains what to do if mails like this annoy you.