On Sun, Dec 19, 2021 at 7:16 PM Xin Yin <yinxin.x@xxxxxxxxxxxxx> wrote:
>
> Thanks for Eric's report. After looking at these stacks, I think there
> is one scenario that may cause this issue.
> 1. Task A call ext4_fc_start_update().
> 2. Task B starts a fast commit and waits for inode update complete.
> 3. Task A call ext4_should_retry_alloc() wake up jbd2 and wait for a
> full commit complete.
> 4. jbd2 waits for a fast commit complete.
>
> so, I think maybe we should make
> ext4_fc_start_update()/ext4_fc_stop_update() more fine grained now, as
> listed in the TODOs
..and I just sent out a patch series to do that :)
- Harshad
> * TODOs
> * -----
> * 1) Make fast commit atomic updates more fine grained. Today, a fast commit
> * eligible update must be protected within ext4_fc_start_update() and
> * ext4_fc_stop_update(). These routines are called at much higher
> * routines. This can be made more fine grained by combining with
> * ext4_journal_start().
>
> Thanks,
> Xin Yin
>
>
>
> On Sat, Dec 18, 2021 at 7:50 AM harshad shirwadkar
> <harshadshirwadkar@xxxxxxxxx> wrote:
> >
> > The problem seems to be during "ext4_should_retry_alloc()" which can
> > call journal commit in certain cases. There are multiple callers to
> > this function and all need to ensure that fast_commit transactions
> > have been stopped before calling this function.
> >
> > Thinking more generally about this, these problems are occurring
> > because we have a different "transaction start" APIs for full commits
> > and fast commits. For full commits, we use
> > "jbd2__handle_start()/stop()" while for fast commits we have
> > "ext4_fc_start_update()" and "ext4_fc_stop_update()". Maintaining
> > these two different APIs is bound to cause problems in the long run.
> > Jan had pointed it out during the initial review and I think it's
> > better to fix it sooner rather than later. So what I'm considering in
> > terms of API blending is to maintain an ext4 global counter for
> > currently open handles and block fast commits if that counter is non
> > zero. This change would make ext4_journal_start block if a fast commit
> > is ongoing. IIUC, it does get blocked if a full commit is ongoing
> > already right?
> >
> > On Fri, Dec 17, 2021 at 12:10 PM harshad shirwadkar
> > <harshadshirwadkar@xxxxxxxxx> wrote:
> > >
> > > Thanks Eric for testing with Xin's patch. I also observed that the
> > > patch didn't fix it.
> > >
> > > I have found one root cause after which the probability of failure
> > > reduces drastically (it takes over 200-300 runs to reproduce the
> > > issue). I'm looking for other places where something might be wrong.
> > > But one definite issue is that in ext4_buffered_write_iter() we start
> > > a fast commit transaction and if for some reason the write fails, we
> > > try to perform a commit (hoping that after the commit write would
> > > succeed). However, that commit waits for the opened fast commit
> > > transaction to finish, causing the thread to hang. I should be
> > > stopping the transaction before starting the commit. I'll send out the
> > > patch once I find other issues too.
> > >
> > > Thanks,
> > > Harshad
> > >
> > > On Thu, Dec 16, 2021 at 1:36 PM Eric Whitney <enwlinux@xxxxxxxxx> wrote:
> > > >
> > > > * Eric Whitney <enwlinux@xxxxxxxxx>:
> > > > > I'm observing kernel hangs when running generic/083 using the latest version
> > > > > of the xfstests-bld test appliance on 5.16-rc5 with the adv test case. The
> > > > > hangs typically occur once in 16 or 17 trials. This is not a regression in
> > > > > 5.16, as it's reproducible in 5.15. Modifying the adv test case to exclude
> > > > > the inline_data feature and then all features results in 100 passed tests
> > > > > out of 100 trials in each case. Modifying adv to include only the fast_commit
> > > > > feature leads to hangs at the same rate as described above. Output from a hung
> > > > > test run follows below.
> > > > >
> > > > > Thanks,
> > > > > Eric
> > > > >
> > > > > generic/083 5s ... [16:09:08][ 24.909037] run fstests generic/083 at 2028
> > > > > [ 25.266112] EXT4-fs (vdc): mounted filesystem with ordered data mode. Opts: .
> > > > > [ 245.414394] INFO: task jbd2/vdc-8:4436 blocked for more than 122 seconds.
> > > > > [ 245.418977] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.421909] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.425207] task:jbd2/vdc-8 state:D stack: 0 pid: 4436 ppid: 2 f0
> > > > > [ 245.426372] Call Trace:
> > > > > [ 245.426777] <TASK>
> > > > > [ 245.427130] __schedule+0x309/0xab0
> > > > > [ 245.427722] ? lock_release+0x132/0x2a0
> > > > > [ 245.428338] ? wait_woken+0x60/0x60
> > > > > [ 245.428899] schedule+0x44/0xc0
> > > > > [ 245.429407] jbd2_journal_commit_transaction+0x174/0x1e40
> > > > > [ 245.430276] ? find_held_lock+0x2d/0x90
> > > > > [ 245.430920] ? try_to_del_timer_sync+0x4d/0x80
> > > > > [ 245.431622] ? wait_woken+0x60/0x60
> > > > > [ 245.432189] ? _raw_spin_unlock_irqrestore+0x3b/0x50
> > > > > [ 245.432982] ? try_to_del_timer_sync+0x4d/0x80
> > > > > [ 245.433692] kjournald2+0xcc/0x2a0
> > > > > [ 245.434263] ? wait_woken+0x60/0x60
> > > > > [ 245.434820] ? commit_timeout+0x10/0x10
> > > > > [ 245.435435] kthread+0x164/0x190
> > > > > [ 245.435957] ? set_kthread_struct+0x40/0x40
> > > > > [ 245.436630] ret_from_fork+0x22/0x30
> > > > > [ 245.437218] </TASK>
> > > > > [ 245.437602] INFO: task fsstress:4440 blocked for more than 122 seconds.
> > > > > [ 245.438643] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.439306] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.440513] task:fsstress state:D stack: 0 pid: 4440 ppid: 4439 f0
> > > > > [ 245.441857] Call Trace:
> > > > > [ 245.442240] <TASK>
> > > > > [ 245.442530] __schedule+0x309/0xab0
> > > > > [ 245.442903] schedule+0x44/0xc0
> > > > > [ 245.443237] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.444011] ? wait_woken+0x60/0x60
> > > > > [ 245.444616] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.445374] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.446181] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.446882] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.447572] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.448258] ? generic_update_time+0xa0/0xc0
> > > > > [ 245.448935] ? file_update_time+0xd4/0x110
> > > > > [ 245.449582] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.450314] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.451011] ? lock_is_held_type+0xd8/0x130
> > > > > [ 245.451662] ? find_held_lock+0x2d/0x90
> > > > > [ 245.452275] do_iter_readv_writev+0x169/0x1d0
> > > > > [ 245.452972] do_iter_write+0x83/0x1c0
> > > > > [ 245.453554] iter_file_splice_write+0x265/0x390
> > > > > [ 245.454298] direct_splice_actor+0x31/0x40
> > > > > [ 245.454934] splice_direct_to_actor+0xfb/0x220
> > > > > [ 245.455640] ? pipe_to_sendpage+0xa0/0xa0
> > > > > [ 245.456279] do_splice_direct+0xa0/0xd0
> > > > > [ 245.456895] vfs_copy_file_range+0x1b6/0x5b0
> > > > > [ 245.457590] __x64_sys_copy_file_range+0xdd/0x200
> > > > > [ 245.458325] do_syscall_64+0x3a/0x80
> > > > > [ 245.458891] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.459682] RIP: 0033:0x7f9419fb5f59
> > > > > [ 245.460247] RSP: 002b:00007ffdf52d2428 EFLAGS: 00000246 ORIG_RAX: 00000000006
> > > > > [ 245.461444] RAX: ffffffffffffffda RBX: 00007ffdf52d2478 RCX: 00007f9419fb5f59
> > > > > [ 245.462537] RDX: 0000000000000004 RSI: 00007ffdf52d2470 RDI: 0000000000000003
> > > > > [ 245.463640] RBP: 0000000000019f46 R08: 0000000000019f46 R09: 0000000000000000
> > > > > [ 245.464770] R10: 00007ffdf52d2478 R11: 0000000000000246 R12: 0000000000000004
> > > > > [ 245.465876] R13: 00007ffdf52d2470 R14: 0000000000000003 R15: 000000000009858f
> > > > > [ 245.466989] </TASK>
> > > > > [ 245.467343] INFO: task fsstress:4441 blocked for more than 122 seconds.
> > > > > [ 245.468383] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.469031] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.470238] task:fsstress state:D stack: 0 pid: 4441 ppid: 4439 f0
> > > > > [ 245.471436] Call Trace:
> > > > > [ 245.471681] <TASK>
> > > > > [ 245.471924] __schedule+0x309/0xab0
> > > > > [ 245.472683] schedule+0x44/0xc0
> > > > > [ 245.473181] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.473869] ? wait_woken+0x60/0x60
> > > > > [ 245.474448] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.475197] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.476004] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.476709] ext4_write_begin+0x168/0x520
> > > > > [ 245.477352] __page_symlink+0xbe/0x110
> > > > > [ 245.477977] ext4_symlink+0x1db/0x3d0
> > > > > [ 245.478561] vfs_symlink+0x109/0x1b0
> > > > > [ 245.479124] do_symlinkat+0xde/0xf0
> > > > > [ 245.479685] __x64_sys_symlink+0x37/0x40
> > > > > [ 245.480306] do_syscall_64+0x3a/0x80
> > > > > [ 245.480903] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.481677] RIP: 0033:0x7f9419fadf07
> > > > > [ 245.482266] RSP: 002b:00007ffdf52d2c58 EFLAGS: 00000206 ORIG_RAX: 00000000008
> > > > > [ 245.483436] RAX: ffffffffffffffda RBX: 000000000000023d RCX: 00007f9419fadf07
> > > > > [ 245.484573] RDX: 0000000000000064 RSI: 00005595aed07d60 RDI: 00005595aed0bd00
> > > > > [ 245.485680] RBP: 00005595aed0bd00 R08: 0000000000000004 R09: 00005595aecf3980
> > > > > [ 245.486774] R10: 0000000000000006 R11: 0000000000000206 R12: 00005595aed07d60
> > > > > [ 245.487901] R13: 00007ffdf52d2dc0 R14: 00005595aed0bd00 R15: 00005595ad3dd450
> > > > > [ 245.489012] </TASK>
> > > > > [ 245.489358] INFO: task fsstress:4442 blocked for more than 122 seconds.
> > > > > [ 245.490390] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.491059] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.492255] task:fsstress state:D stack: 0 pid: 4442 ppid: 4439 f0
> > > > > [ 245.493541] Call Trace:
> > > > > [ 245.493933] <TASK>
> > > > > [ 245.494298] __schedule+0x309/0xab0
> > > > > [ 245.494851] schedule+0x44/0xc0
> > > > > [ 245.495355] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.496038] ? wait_woken+0x60/0x60
> > > > > [ 245.496604] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.497358] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.498175] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.498865] ext4_iomap_begin+0x193/0x2b0
> > > > > [ 245.499499] iomap_iter+0x184/0x4a0
> > > > > [ 245.500053] __iomap_dio_rw+0x249/0x7b0
> > > > > [ 245.500686] iomap_dio_rw+0xa/0x30
> > > > > [ 245.501203] ext4_file_write_iter+0x421/0x8a0
> > > > > [ 245.501840] new_sync_write+0x125/0x1c0
> > > > > [ 245.502355] vfs_write+0x20f/0x370
> > > > > [ 245.502757] ksys_write+0x5f/0xe0
> > > > > [ 245.503120] do_syscall_64+0x3a/0x80
> > > > > [ 245.503472] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.503956] RIP: 0033:0x7f941a094471
> > > > > [ 245.504328] RSP: 002b:00007ffdf52d2908 EFLAGS: 00000246 ORIG_RAX: 00000000001
> > > > > [ 245.505399] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f941a094471
> > > > > [ 245.506509] RDX: 000000000000c000 RSI: 00005595aed08000 RDI: 0000000000000003
> > > > > [ 245.507663] RBP: 000000000018f000 R08: 0000000000000b4f R09: 00007f941a07e0d0
> > > > > [ 245.508776] R10: 00005595aecf2010 R11: 0000000000000246 R12: 00000000000003c7
> > > > > [ 245.509888] R13: 000000000000c000 R14: 00005595aed08000 R15: 0000000000000000
> > > > > [ 245.511041] </TASK>
> > > > > [ 245.511398] INFO: task fsstress:4443 blocked for more than 122 seconds.
> > > > > [ 245.512430] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.513103] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.514354] task:fsstress state:D stack: 0 pid: 4443 ppid: 4439 f0
> > > > > [ 245.515652] Call Trace:
> > > > > [ 245.516054] <TASK>
> > > > > [ 245.516408] __schedule+0x309/0xab0
> > > > > [ 245.516976] schedule+0x44/0xc0
> > > > > [ 245.517483] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.518199] ? wait_woken+0x60/0x60
> > > > > [ 245.518758] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.519520] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.520330] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.521065] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.521736] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.522425] ? generic_update_time+0xa0/0xc0
> > > > > [ 245.523102] ? file_update_time+0xd4/0x110
> > > > > [ 245.523759] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.524521] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.525197] ? lock_is_held_type+0xd8/0x130
> > > > > [ 245.525875] do_iter_readv_writev+0x169/0x1d0
> > > > > [ 245.526568] do_iter_write+0x83/0x1c0
> > > > > [ 245.527155] vfs_writev+0x9c/0x280
> > > > > [ 245.527725] ? lock_is_held_type+0xd8/0x130
> > > > > [ 245.528388] ? find_held_lock+0x2d/0x90
> > > > > [ 245.528911] ? do_writev+0x6b/0x110
> > > > > [ 245.529443] ? syscall_enter_from_user_mode+0x20/0x70
> > > > > [ 245.530182] do_writev+0x6b/0x110
> > > > > [ 245.530674] do_syscall_64+0x3a/0x80
> > > > > [ 245.531219] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.531978] RIP: 0033:0x7f9419fb2504
> > > > > [ 245.532498] RSP: 002b:00007ffdf52d28f8 EFLAGS: 00000246 ORIG_RAX: 00000000004
> > > > > [ 245.533817] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f9419fb2504
> > > > > [ 245.534870] RDX: 00000000000000d9 RSI: 00005595aed072f0 RDI: 0000000000000003
> > > > > [ 245.535915] RBP: 000000000000040a R08: 00005595aed7cf55 R09: 00007f941a07e3a0
> > > > > [ 245.536957] R10: 00005595aecf2010 R11: 0000000000000246 R12: 00005595aed072f0
> > > > > [ 245.538003] R13: 00005595aed61250 R14: 00000000000000d9 R15: 000000000000020d
> > > > > [ 245.539051] </TASK>
> > > > > [ 245.539382] INFO: task fsstress:4444 blocked for more than 123 seconds.
> > > > > [ 245.540346] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.541007] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.542237] task:fsstress state:D stack: 0 pid: 4444 ppid: 4439 f0
> > > > > [ 245.543252] Call Trace:
> > > > > [ 245.543555] <TASK>
> > > > > [ 245.543821] __schedule+0x309/0xab0
> > > > > [ 245.544294] schedule+0x44/0xc0
> > > > > [ 245.544779] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.545203] ? wait_woken+0x60/0x60
> > > > > [ 245.545546] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.546009] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.546501] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.546929] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.547337] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.547797] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.548398] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.548998] new_sync_write+0x125/0x1c0
> > > > > [ 245.549568] vfs_write+0x20f/0x370
> > > > > [ 245.550070] ksys_write+0x5f/0xe0
> > > > > [ 245.550560] do_syscall_64+0x3a/0x80
> > > > > [ 245.551109] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.551857] RIP: 0033:0x7f941a094471
> > > > > [ 245.552384] RSP: 002b:00007ffdf52d2908 EFLAGS: 00000246 ORIG_RAX: 00000000001
> > > > > [ 245.553480] RAX: ffffffffffffffda RBX: 00000000000184da RCX: 00007f941a094471
> > > > > [ 245.554527] RDX: 00000000000184da RSI: 00005595aedc43c0 RDI: 0000000000000003
> > > > > [ 245.555564] RBP: 0000000000000311 R08: 0000000000000000 R09: 00007f941a07dcd0
> > > > > [ 245.556601] R10: 00005595aecf2010 R11: 0000000000000246 R12: 0000000000000003
> > > > > [ 245.557648] R13: 00000000001d8893 R14: 00005595aedc43c0 R15: 0000000000000000
> > > > > [ 245.558694] </TASK>
> > > > > [ 245.559021] INFO: task fsstress:4445 blocked for more than 123 seconds.
> > > > > [ 245.559977] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.560591] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.561733] task:fsstress state:D stack: 0 pid: 4445 ppid: 4439 f0
> > > > > [ 245.562945] Call Trace:
> > > > > [ 245.563491] <TASK>
> > > > > [ 245.563887] __schedule+0x309/0xab0
> > > > > [ 245.564427] schedule+0x44/0xc0
> > > > > [ 245.564905] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.565542] ? wait_woken+0x60/0x60
> > > > > [ 245.566056] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.566750] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.567494] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.568156] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.568788] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.569429] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.570102] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.570730] new_sync_write+0x125/0x1c0
> > > > > [ 245.571313] vfs_write+0x20f/0x370
> > > > > [ 245.571821] ksys_write+0x5f/0xe0
> > > > > [ 245.572311] do_syscall_64+0x3a/0x80
> > > > > [ 245.572842] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.573573] RIP: 0033:0x7f941a094471
> > > > > [ 245.574097] RSP: 002b:00007ffdf52d2908 EFLAGS: 00000246 ORIG_RAX: 00000000001
> > > > > [ 245.575199] RAX: ffffffffffffffda RBX: 0000000000019da9 RCX: 00007f941a094471
> > > > > [ 245.576239] RDX: 0000000000019da9 RSI: 00005595aedc23f0 RDI: 0000000000000003
> > > > > [ 245.577271] RBP: 0000000000000359 R08: 0000000000000003 R09: 00007f941a07dd60
> > > > > [ 245.578319] R10: 00005595aecf2010 R11: 0000000000000246 R12: 0000000000000003
> > > > > [ 245.579357] R13: 0000000000147e54 R14: 00005595aedc23f0 R15: 0000000000000000
> > > > > [ 245.580395] </TASK>
> > > > > [ 245.580729] INFO: task fsstress:4446 blocked for more than 123 seconds.
> > > > > [ 245.581693] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.582344] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.583552] task:fsstress state:D stack: 0 pid: 4446 ppid: 4439 f0
> > > > > [ 245.584844] Call Trace:
> > > > > [ 245.585145] <TASK>
> > > > > [ 245.585491] __schedule+0x309/0xab0
> > > > > [ 245.586040] ? lock_release+0x132/0x2a0
> > > > > [ 245.586560] schedule+0x44/0xc0
> > > > > [ 245.586866] ext4_fc_commit+0x447/0xa90
> > > > > [ 245.587231] ? jbd2_trans_will_send_data_barrier+0x7f/0xa0
> > > > > [ 245.587765] ? wait_woken+0x60/0x60
> > > > > [ 245.588103] ext4_sync_file+0x3fc/0x470
> > > > > [ 245.588466] do_fsync+0x38/0x70
> > > > > [ 245.588917] __x64_sys_fdatasync+0x13/0x20
> > > > > [ 245.589517] do_syscall_64+0x3a/0x80
> > > > > [ 245.590042] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.590774] RIP: 0033:0x7f9419fb32c4
> > > > > [ 245.591317] RSP: 002b:00007ffdf52d2db8 EFLAGS: 00000246 ORIG_RAX: 0000000000b
> > > > > [ 245.592439] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f9419fb32c4
> > > > > [ 245.593465] RDX: 00007ffdf52d2d20 RSI: 00007ffdf52d2d20 RDI: 0000000000000003
> > > > > [ 245.594762] RBP: 00000000000003df R08: 00007f941a07dc40 R09: 00007ffdf52d2a06
> > > > > [ 245.595861] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000000002ee
> > > > > [ 245.596968] R13: 0000000051eb851f R14: 00007ffdf52d2e60 R15: 00005595ad3d85f0
> > > > > [ 245.598100] </TASK>
> > > > > [ 245.598364] INFO: task fsstress:4447 blocked for more than 123 seconds.
> > > > > [ 245.599382] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.600039] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.601273] task:fsstress state:D stack: 0 pid: 4447 ppid: 4439 f0
> > > > > [ 245.602406] Call Trace:
> > > > > [ 245.602829] <TASK>
> > > > > [ 245.603191] __schedule+0x309/0xab0
> > > > > [ 245.603788] schedule+0x44/0xc0
> > > > > [ 245.604324] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.604897] ? wait_woken+0x60/0x60
> > > > > [ 245.605493] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.606290] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.607136] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.607885] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.608423] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.609148] ? generic_update_time+0xa0/0xc0
> > > > > [ 245.609861] ? file_update_time+0xd4/0x110
> > > > > [ 245.610527] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.611296] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.611840] ? lock_is_held_type+0xd8/0x130
> > > > > [ 245.612470] ? find_held_lock+0x2d/0x90
> > > > > [ 245.613055] do_iter_readv_writev+0x169/0x1d0
> > > > > [ 245.613709] do_iter_write+0x83/0x1c0
> > > > > [ 245.614272] iter_file_splice_write+0x265/0x390
> > > > > [ 245.615015] direct_splice_actor+0x31/0x40
> > > > > [ 245.615676] splice_direct_to_actor+0xfb/0x220
> > > > > [ 245.616390] ? pipe_to_sendpage+0xa0/0xa0
> > > > > [ 245.617038] do_splice_direct+0xa0/0xd0
> > > > > [ 245.617684] vfs_copy_file_range+0x1b6/0x5b0
> > > > > [ 245.618338] __x64_sys_copy_file_range+0xdd/0x200
> > > > > [ 245.619026] do_syscall_64+0x3a/0x80
> > > > > [ 245.619552] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.620283] RIP: 0033:0x7f9419fb5f59
> > > > > [ 245.620811] RSP: 002b:00007ffdf52d2428 EFLAGS: 00000246 ORIG_RAX: 00000000006
> > > > > [ 245.621907] RAX: ffffffffffffffda RBX: 00007ffdf52d2478 RCX: 00007f9419fb5f59
> > > > > [ 245.622986] RDX: 0000000000000004 RSI: 00007ffdf52d2470 RDI: 0000000000000003
> > > > > [ 245.623983] RBP: 000000000001ddb5 R08: 000000000001ddb5 R09: 0000000000000000
> > > > > [ 245.625033] R10: 00007ffdf52d2478 R11: 0000000000000246 R12: 0000000000000004
> > > > > [ 245.626162] R13: 00007ffdf52d2470 R14: 0000000000000003 R15: 000000000030e49f
> > > > > [ 245.627282] </TASK>
> > > > > [ 245.627654] INFO: task fsstress:4448 blocked for more than 123 seconds.
> > > > > [ 245.628601] Not tainted 5.16.0-rc5 #1
> > > > > [ 245.629266] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this.
> > > > > [ 245.630484] task:fsstress state:D stack: 0 pid: 4448 ppid: 4439 f0
> > > > > [ 245.631788] Call Trace:
> > > > > [ 245.632162] <TASK>
> > > > > [ 245.632495] __schedule+0x309/0xab0
> > > > > [ 245.632991] schedule+0x44/0xc0
> > > > > [ 245.633395] jbd2_log_wait_commit+0x119/0x190
> > > > > [ 245.633958] ? wait_woken+0x60/0x60
> > > > > [ 245.634465] __jbd2_journal_force_commit+0x5d/0xb0
> > > > > [ 245.635224] jbd2_journal_force_commit_nested+0xa/0x20
> > > > > [ 245.635889] ext4_should_retry_alloc+0x5c/0xb0
> > > > > [ 245.636464] ext4_da_write_begin+0xf2/0x310
> > > > > [ 245.637042] generic_perform_write+0xf0/0x1d0
> > > > > [ 245.637631] ext4_buffered_write_iter+0x88/0x120
> > > > > [ 245.638294] ext4_file_write_iter+0x5f/0x8a0
> > > > > [ 245.638847] new_sync_write+0x125/0x1c0
> > > > > [ 245.639349] vfs_write+0x20f/0x370
> > > > > [ 245.639787] ksys_write+0x5f/0xe0
> > > > > [ 245.640220] do_syscall_64+0x3a/0x80
> > > > > [ 245.640685] entry_SYSCALL_64_after_hwframe+0x44/0xae
> > > > > [ 245.641351] RIP: 0033:0x7f941a094471
> > > > > [ 245.641910] RSP: 002b:00007ffdf52d2908 EFLAGS: 00000246 ORIG_RAX: 00000000001
> > > > > [ 245.642861] RAX: ffffffffffffffda RBX: 00000000000094f2 RCX: 00007f941a094471
> > > > > [ 245.643751] RDX: 00000000000094f2 RSI: 00005595aecf55c0 RDI: 0000000000000003
> > > > > [ 245.644686] RBP: 000000000000040e R08: 00005595aed4d330 R09: 00007f941a07dcc0
> > > > > [ 245.645630] R10: 00005595aecf2010 R11: 0000000000000246 R12: 0000000000000003
> > > > > [ 245.646501] R13: 00000000000dd6d8 R14: 00005595aecf55c0 R15: 0000000000000000
> > > > > [ 245.647380] </TASK>
> > > > > [ 245.647684]
> > > > > [ 245.647684] Showing all locks held in the system:
> > > > > [ 245.648492] 1 lock held by khungtaskd/25:
> > > > > [ 245.648992] #0: ffffffff82762e40 (rcu_read_lock){....}-{1:2}, at: debug_shoa
> > > > > [ 245.650094] 2 locks held by fsstress/4440:
> > > > > [ 245.650600] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: __x64_sys_0
> > > > > [ 245.651761] #1: ffff888013cad850 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.653096] 2 locks held by fsstress/4441:
> > > > > [ 245.653595] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: filename_c0
> > > > > [ 245.654650] #1: ffff88800750f470 (&type->i_mutex_dir_key#3/1){+.+.}-{3:3}, 0
> > > > > [ 245.656111] 2 locks held by fsstress/4442:
> > > > > [ 245.656655] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_write0
> > > > > [ 245.657707] #1: ffff8880076f32d0 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.659084] 2 locks held by fsstress/4443:
> > > > > [ 245.659618] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: do_writev+0
> > > > > [ 245.660632] #1: ffff888007686b10 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.661960] 2 locks held by fsstress/4444:
> > > > > [ 245.662540] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_write0
> > > > > [ 245.663538] #1: ffff8880178c96b0 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.664873] 2 locks held by fsstress/4445:
> > > > > [ 245.665442] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_write0
> > > > > [ 245.666441] #1: ffff88801a8da970 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.667806] 2 locks held by fsstress/4447:
> > > > > [ 245.668389] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: __x64_sys_0
> > > > > [ 245.669588] #1: ffff88800777c590 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.670944] 2 locks held by fsstress/4448:
> > > > > [ 245.671520] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_write0
> > > > > [ 245.672537] #1: ffff888017ac2010 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.673888] 2 locks held by fsstress/4449:
> > > > > [ 245.674455] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_fallo0
> > > > > [ 245.675596] #1: ffff88800747bc30 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.676839] 2 locks held by fsstress/4450:
> > > > > [ 245.677356] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: do_writev+0
> > > > > [ 245.678379] #1: ffff888013caf470 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.679794] 2 locks held by fsstress/4451:
> > > > > [ 245.680329] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: ksys_write0
> > > > > [ 245.681390] #1: ffff888007542010 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.682734] 1 lock held by fsstress/4452:
> > > > > [ 245.683243] #0: ffff88800bb090e0 (&type->s_umount_key#31){++++}-{3:3}, at: 0
> > > > > [ 245.684412] 1 lock held by fsstress/4453:
> > > > > [ 245.684967] #0: ffff88800bb090e0 (&type->s_umount_key#31){++++}-{3:3}, at: 0
> > > > > [ 245.686109] 2 locks held by fsstress/4454:
> > > > > [ 245.686674] #0: ffff88800bb09448 (sb_writers#3){.+.+}-{0:0}, at: do_writev+0
> > > > > [ 245.687718] #1: ffff8880178461b0 (&sb->s_type->i_mutex_key#9){++++}-{3:3}, 0
> > > > > [ 245.689137]
> > > > > [ 245.689346] =============================================
> > > > > [ 245.689346]
> > > > >
> > > >
> > > >
> > > > Hi Harshad:
> > > >
> > > > FWIW, I've applied Xin Yin's hang fix for fallocate when using fast_commit to a
> > > > 5.16-rc5 kernel and I'm still seeing generic/083 hang when running the adv
> > > > test case on the test appliance. If anything, it actually hangs more quickly
> > > > and reliably - generally on the first or second trial in a sequence.
> > > >
> > > > Eric
> > > >
