linux-ext4 - Fwd: ext: hang in jbd2_journal_commit_transaction/wait_transaction

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [day] [month] [year] [list]
Message-ID: <CAGOdRhMOrqfqN+Yz2mWWRfQinBif7uW3AxOC5ipVkgnTcRoeiQ@mail.gmail.com>
Date:   Wed, 29 Jun 2022 10:01:19 -0700
From:   Dmitry <ilyevsky@...il.com>
To:     linux-ext4@...r.kernel.org
Subject: Fwd: ext: hang in jbd2_journal_commit_transaction/wait_transaction_locked

Hi All,

I'm having deadlock issues with ext4 after upgrading 5.14.14 ->
5.16.13. Here's the excerpt of blocked threads dump (the are roughly
200 D threads with a Z parent + jbd2 D thread):

Jun 28 17:43:32 ip-10-66-2-23 kernel: sysrq: Show Blocked State
Jun 28 17:43:32 ip-10-66-2-23 kernel: task:jbd2/nvme3n1-8  state:D
stack:    0 pid:11163 ppid:     2 flags:0x00004000
Jun 28 17:43:32 ip-10-66-2-23 kernel: Call Trace:
Jun 28 17:43:32 ip-10-66-2-23 kernel:  <TASK>
Jun 28 17:43:32 ip-10-66-2-23 kernel:  __schedule+0x2d7/0xfa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? _raw_spin_unlock_irqrestore+0x25/0x40
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? _raw_spin_lock_irqsave+0x26/0x50
Jun 28 17:43:32 ip-10-66-2-23 kernel:  schedule+0x4e/0xc0
Jun 28 17:43:32 ip-10-66-2-23 kernel:
jbd2_journal_commit_transaction+0x314/0x1bd0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? cpuacct_charge+0x2e/0x50
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? _raw_spin_unlock+0x16/0x30
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? do_wait_intr_irq+0xa0/0xa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? preempt_count_add+0x68/0xa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  kjournald2+0x9f/0x260
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? do_wait_intr_irq+0xa0/0xa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ?
jbd2_journal_release_jbd_inode+0x110/0x110
Jun 28 17:43:32 ip-10-66-2-23 kernel:  kthread+0x16b/0x190
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? set_kthread_struct+0x40/0x40
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ret_from_fork+0x22/0x30
Jun 28 17:43:32 ip-10-66-2-23 kernel:  </TASK>
Jun 28 17:43:32 ip-10-66-2-23 kernel: task:BackgrProcPool  state:D
stack:    0 pid:11757 ppid: 11488 flags:0x00000004
Jun 28 17:43:32 ip-10-66-2-23 kernel: Call Trace:
Jun 28 17:43:32 ip-10-66-2-23 kernel:  <TASK>
Jun 28 17:43:32 ip-10-66-2-23 kernel:  __schedule+0x2d7/0xfa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? ext4_match.part.0+0xbf/0x100
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? _raw_spin_lock_irqsave+0x26/0x50
Jun 28 17:43:32 ip-10-66-2-23 kernel:  schedule+0x4e/0xc0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  wait_transaction_locked+0x7a/0xa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? do_wait_intr_irq+0xa0/0xa0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  add_transaction_credits+0x10e/0x2a0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  start_this_handle+0xf1/0x4f0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? kmem_cache_alloc+0x16c/0x2d0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  jbd2__journal_start+0xf7/0x1f0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  __ext4_journal_start_sb+0xfe/0x110
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ext4_rename+0x617/0xb20
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? security_inode_permission+0x30/0x50
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? avc_has_perm_noaudit+0x7f/0xe0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  vfs_rename+0x9ca/0xd20
Jun 28 17:43:32 ip-10-66-2-23 kernel:  ? do_renameat2+0x4be/0x4f0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  do_renameat2+0x4be/0x4f0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  __x64_sys_rename+0x40/0x50
Jun 28 17:43:32 ip-10-66-2-23 kernel:  do_syscall_64+0x3b/0x90
Jun 28 17:43:32 ip-10-66-2-23 kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Jun 28 17:43:32 ip-10-66-2-23 kernel: RIP: 0033:0x7f6507ffb00b
Jun 28 17:43:32 ip-10-66-2-23 kernel: RSP: 002b:00007f64ec9f9968
EFLAGS: 00000202 ORIG_RAX: 0000000000000052
Jun 28 17:43:32 ip-10-66-2-23 kernel: RAX: ffffffffffffffda RBX:
00007f64ec9f99a0 RCX: 00007f6507ffb00b
Jun 28 17:43:32 ip-10-66-2-23 kernel: RDX: 0000000000000031 RSI:
00007f64d98698b0 RDI: 00007f64edc154a0
Jun 28 17:43:32 ip-10-66-2-23 kernel: RBP: 00007f64eca28080 R08:
00007f64ec9ff700 R09: 0000000000000070
Jun 28 17:43:32 ip-10-66-2-23 kernel: R10: 00007f64edcfb190 R11:
0000000000000202 R12: 00007f64ec9f99a1
Jun 28 17:43:32 ip-10-66-2-23 kernel: R13: 0000000000000000 R14:
00007f64ec9f99b8 R15: 00007f64ec9f99c0
Jun 28 17:43:32 ip-10-66-2-23 kernel:  </TASK>

...

Jun 28 17:43:34 ip-10-66-2-23 kernel: task:SystemLogFlush  state:D
stack:    0 pid:11775 ppid: 11488 flags:0x00000004
Jun 28 17:43:34 ip-10-66-2-23 kernel: Call Trace:
Jun 28 17:43:34 ip-10-66-2-23 kernel:  <TASK>
Jun 28 17:43:34 ip-10-66-2-23 kernel:  __schedule+0x2d7/0xfa0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? avc_has_perm_noaudit+0x7f/0xe0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? avc_has_perm_noaudit+0x7f/0xe0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  schedule+0x4e/0xc0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  rwsem_down_read_slowpath+0x310/0x350
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? lookup_fast+0xce/0x130
Jun 28 17:43:35 ip-10-66-2-23 kernel:  walk_component+0x10c/0x190
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? path_init+0x2c1/0x3f0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  path_lookupat+0x6e/0x1b0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  filename_lookup+0xbc/0x1a0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? __check_object_size+0x136/0x150
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? strncpy_from_user+0x3f/0x130
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? _raw_spin_unlock_irqrestore+0x25/0x40
Jun 28 17:43:35 ip-10-66-2-23 kernel:  user_path_at_empty+0x3a/0x50
Jun 28 17:43:35 ip-10-66-2-23 kernel:  vfs_statx+0x64/0x100
Jun 28 17:43:35 ip-10-66-2-23 kernel:  __do_sys_newstat+0x26/0x40
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ? __do_sys_statfs+0x27/0x30
Jun 28 17:43:35 ip-10-66-2-23 kernel:  ?
syscall_trace_enter.constprop.0+0x13d/0x1d0
Jun 28 17:43:35 ip-10-66-2-23 kernel:  do_syscall_64+0x3b/0x90
Jun 28 17:43:35 ip-10-66-2-23 kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Jun 28 17:43:35 ip-10-66-2-23 kernel: RIP: 0033:0x7f65080a562a
Jun 28 17:43:35 ip-10-66-2-23 kernel: RSP: 002b:00007f64e29f5e48
EFLAGS: 00000246 ORIG_RAX: 0000000000000004
Jun 28 17:43:35 ip-10-66-2-23 kernel: RAX: ffffffffffffffda RBX:
00007f64e29f5e78 RCX: 00007f65080a562a
Jun 28 17:43:35 ip-10-66-2-23 kernel: RDX: 00007f64e29f5e90 RSI:
00007f64e29f5e90 RDI: 00007f64edcabb50
Jun 28 17:43:35 ip-10-66-2-23 kernel: RBP: 0000000000000000 R08:
0000000000000001 R09: 0000000000000070
Jun 28 17:43:35 ip-10-66-2-23 kernel: R10: 00007f64ede45d00 R11:
0000000000000246 R12: 00007f64e29f6300
Jun 28 17:43:35 ip-10-66-2-23 kernel: R13: 00007f6507a34700 R14:
00007f6507a34bc8 R15: 00007f64ec11ea18
Jun 28 17:43:35 ip-10-66-2-23 kernel:  </TASK>

...

Jun 28 17:43:36 ip-10-66-2-23 kernel: task:HTTPHandler     state:D
stack:    0 pid:11809 ppid: 11488 flags:0x00000004
Jun 28 17:43:36 ip-10-66-2-23 kernel: Call Trace:
Jun 28 17:43:36 ip-10-66-2-23 kernel:  <TASK>
Jun 28 17:43:36 ip-10-66-2-23 kernel:  __schedule+0x2d7/0xfa0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? avc_has_perm_noaudit+0x7f/0xe0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? avc_has_perm_noaudit+0x7f/0xe0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  schedule+0x4e/0xc0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  rwsem_down_read_slowpath+0x310/0x350
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? lookup_fast+0xce/0x130
Jun 28 17:43:36 ip-10-66-2-23 kernel:  walk_component+0x10c/0x190
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? path_init+0x2c1/0x3f0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  path_lookupat+0x6e/0x1b0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  filename_lookup+0xbc/0x1a0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? __check_object_size+0x136/0x150
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? strncpy_from_user+0x3f/0x130
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? _raw_spin_unlock_irqrestore+0x25/0x40
Jun 28 17:43:36 ip-10-66-2-23 kernel:  user_path_at_empty+0x3a/0x50
Jun 28 17:43:36 ip-10-66-2-23 kernel:  vfs_statx+0x64/0x100
Jun 28 17:43:36 ip-10-66-2-23 kernel:  __do_sys_newstat+0x26/0x40
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ? __do_sys_statfs+0x27/0x30
Jun 28 17:43:36 ip-10-66-2-23 kernel:  ?
syscall_trace_enter.constprop.0+0x13d/0x1d0
Jun 28 17:43:36 ip-10-66-2-23 kernel:  do_syscall_64+0x3b/0x90
Jun 28 17:43:36 ip-10-66-2-23 kernel:  entry_SYSCALL_64_after_hwframe+0x44/0xae
Jun 28 17:43:36 ip-10-66-2-23 kernel: RIP: 0033:0x7f65080a562a
Jun 28 17:43:36 ip-10-66-2-23 kernel: RSP: 002b:00007f64cf7d2f78
EFLAGS: 00000246 ORIG_RAX: 0000000000000004
Jun 28 17:43:36 ip-10-66-2-23 kernel: RAX: ffffffffffffffda RBX:
00007f64cf7d2fa8 RCX: 00007f65080a562a
Jun 28 17:43:36 ip-10-66-2-23 kernel: RDX: 00007f64cf7d2fc0 RSI:
00007f64cf7d2fc0 RDI: 00007f64e909b5b0
Jun 28 17:43:36 ip-10-66-2-23 kernel: RBP: 0000000000000000 R08:
0000000000000001 R09: 0000000000000070
Jun 28 17:43:36 ip-10-66-2-23 kernel: R10: 000000000000002b R11:
0000000000000246 R12: 00007f64cf7d34f0
Jun 28 17:43:36 ip-10-66-2-23 kernel: R13: 00007f65072ffc00 R14:
00007f6507300130 R15: 00007f64cb671218
Jun 28 17:43:36 ip-10-66-2-23 kernel:  </TASK>

The issue seems to pop up after a few hours consistently and after
downgrade back to 5.14 it is gone. I've looked through 'ext:' commits
for v5.14..v5.16 but don't see a smoking gun (not an expert though).
Any suggestions to debug this further (perhaps an issue in nvme/block
subsystems) or any other pointers would be much appreciated!

Thanks,
-Dmitry