linux-ext4.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Jan Kara <jack@suse.cz>
To: Thilo Fromm <t-lo@linux.microsoft.com>
Cc: jack@suse.com, tytso@mit.edu, Ye Bin <yebin10@huawei.com>,
	linux-ext4@vger.kernel.org
Subject: Re: [syzbot] possible deadlock in jbd2_journal_lock_updates
Date: Thu, 29 Sep 2022 10:27:16 +0200	[thread overview]
Message-ID: <20220929082716.5urzcfk4hnapd3cr@quack3> (raw)
In-Reply-To: <c77bf00f-4618-7149-56f1-b8d1664b9d07@linux.microsoft.com>

Hello!

On Wed 28-09-22 09:30:25, Thilo Fromm wrote:
> > So this seems like a real issue. Essentially, the problem is that
> > ext4_bmap() acquires inode->i_rwsem while its caller
> > jbd2_journal_flush() is holding journal->j_checkpoint_mutex. This
> > looks like a real deadlock possibility.
> 
> Flatcar Container Linux users have reported a kernel issue which might be
> caused by commit 51ae846cff5. The issue is triggered under I/O load in
> certain conditions and leads to a complete system hang. I've pasted a
> typical kernel log below; please refer to
> https://github.com/flatcar/Flatcar/issues/847 for more details.
> 
> The issue can be triggered on Flatcar release 3227.2.2 / kernel version
> 5.15.63 (we ship LTS kernels) but not on release 3227.2.1 / kernel 5.15.58.
> 51ae846cff5 was introduced to 5.15 in 5.15.61.

Well, so far your stacktraces do not really show anything pointing to that
particular commit. So we need to understand that hang some more.

> ( Kernel log of a crash follows; more info here:
> https://github.com/flatcar/Flatcar/issues/847 )
> 
> [1282119.153912] INFO: task jbd2/sda9-8:544 blocked for more than 122
> seconds.
> [1282119.157088]       Not tainted 5.15.63-flatcar #1
> [1282119.159281] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [1282119.162723] task:jbd2/sda9-8     state:D stack:    0 pid:  544 ppid:
> 2 flags:0x00004000
> [1282119.166441] Call Trace:
> [1282119.167640]  <TASK>
> [1282119.168675]  __schedule+0x2eb/0x8d0
> [1282119.170341]  schedule+0x5b/0xd0
> [1282119.171806]  jbd2_journal_commit_transaction+0x301/0x2850 [jbd2]
> [1282119.175448]  ? wait_woken+0x70/0x70
> [1282119.177174]  ? lock_timer_base+0x61/0x80
> [1282119.179015]  jbd2_journal_check_available_features+0x1ab/0x3f0 [jbd2]
> [1282119.181922]  ? wait_woken+0x70/0x70
> [1282119.183533]  ? jbd2_journal_check_available_features+0x100/0x3f0 [jbd2]
> [1282119.186566]  kthread+0x127/0x150
> [1282119.188087]  ? set_kthread_struct+0x50/0x50
> [1282119.190346]  ret_from_fork+0x22/0x30

Hrm, so your backtraces seem to be strange. For example in this stacktrace
we should have kjournald2() somewhere instead of
jbd2_journal_check_available_features() which can hardly be there. So
somehow stack unwinding or symbol resolution is strangely confused with
this kernel. Compiling with any unusual config or compiler?

> [1282119.193081] INFO: task systemd-journal:748 blocked for more than 122
> seconds.
> [1282119.196255]       Not tainted 5.15.63-flatcar #1
> [1282119.198321] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [1282119.201776] task:systemd-journal state:D stack:    0 pid:  748 ppid:
> 1 flags:0x00000004
> [1282119.205604] Call Trace:
> [1282119.206773]  <TASK>
> [1282119.207794]  __schedule+0x2eb/0x8d0
> [1282119.209410]  schedule+0x5b/0xd0
> [1282119.210887]  jbd2_journal_free_reserved+0xca/0x9d0 [jbd2]
> [1282119.213342]  ? wait_woken+0x70/0x70
> [1282119.214946]  jbd2_journal_free_reserved+0x2d9/0x9d0 [jbd2]
> [1282119.217482]  ? call_rcu+0xa2/0x330
> [1282119.219070]  jbd2_journal_free_reserved+0x5ab/0x9d0 [jbd2]
> [1282119.221672]  ? step_into+0x47c/0x7b0
> [1282119.223372]  ? __cond_resched+0x16/0x50
> [1282119.225175]  jbd2__journal_start+0xfb/0x1e0 [jbd2]
> [1282119.227342]  __ext4_journal_start_sb+0xf8/0x110 [ext4]
> [1282119.229688]  ext4_dirty_inode+0x35/0x80 [ext4]
> [1282119.231735]  __mark_inode_dirty+0x147/0x320
> [1282119.233712]  touch_atime+0x13c/0x150
> [1282119.235429]  filemap_read+0x308/0x320
> [1282119.238370]  ? may_delete+0x2a0/0x2f0
> [1282119.240286]  ? do_filp_open+0xa9/0x150
> [1282119.242071]  new_sync_read+0x119/0x1b0
> [1282119.244052]  ? 0xffffffffad000000
> [1282119.245736]  vfs_read+0xf6/0x190
> [1282119.247362]  __x64_sys_pread64+0x91/0xc0
> [1282119.249365]  do_syscall_64+0x3b/0x90
> [1282119.251173]  entry_SYSCALL_64_after_hwframe+0x61/0xcb

Similarly here the stacktrace inside jbd2 looks confused.
jbd2__journal_start() looks correct but jbd2_journal_free_reserved()
entries are certainly wrong. Likely there should be start_this_handle()
somewhere on the stack and then maybe some other function before we get to
schedule(). It seems as if the symbol table for jbd2 got somehow messed up.

Looking into stacktraces below it seems to be the case there as well and
even some stacktraces inside ext4 look bogus. Like this one:

> [1282119.800485] task:kworker/u8:2    state:D stack:    0 pid:874634 ppid:
> 2 flags:0x00004000
> [1282119.804354] Workqueue: writeback wb_workfn (flush-8:0)
> [1282119.806726] Call Trace:
> [1282119.807936]  <TASK>
> [1282119.809026]  __schedule+0x2eb/0x8d0
> [1282119.810692]  schedule+0x5b/0xd0
> [1282119.812181]  jbd2_journal_free_reserved+0xca/0x9d0 [jbd2]
> [1282119.814641]  ? wait_woken+0x70/0x70
> [1282119.816909]  jbd2_journal_free_reserved+0x2d9/0x9d0 [jbd2]
> [1282119.819409]  ? find_get_pages_range+0x197/0x200
> [1282119.821507]  jbd2_journal_free_reserved+0x5ab/0x9d0 [jbd2]
> [1282119.823988]  ? ext4_convert_inline_data+0xb07/0x2020 [ext4]
> [1282119.826555]  ? __cond_resched+0x16/0x50
> [1282119.828352]  jbd2__journal_start+0xfb/0x1e0 [jbd2]
> [1282119.830542]  __ext4_journal_start_sb+0xf8/0x110 [ext4]
> [1282119.833049]  __ext4_mark_inode_dirty+0x502/0x1880 [ext4]
> [1282119.835474]  ? __cond_resched+0x16/0x50
> [1282119.837281]  ? __getblk_gfp+0x27/0x60
> [1282119.838986]  ? __ext4_handle_dirty_metadata+0x56/0x19b0 [ext4]
> [1282119.841629]  ? ext4_mark_iloc_dirty+0x56a/0xaf0 [ext4]

^^ We should have ext4_writepages() around here. Also notice how the
offsets within __ext4_mark_inode_dirty() are strange. That function almost
certainly does not have 0x1880 bytes when compiled.

> [1282119.843979]  do_writepages+0xd1/0x200
> [1282119.845682]  __writeback_single_inode+0x39/0x290
> [1282119.847884]  writeback_sb_inodes+0x20d/0x490
> [1282119.849861]  __writeback_inodes_wb+0x4c/0xe0
> [1282119.851844]  wb_writeback+0x1c0/0x280
> [1282119.853561]  wb_workfn+0x29f/0x4d0
> [1282119.855195]  ? psi_task_switch+0x1e0/0x200
> [1282119.857128]  process_one_work+0x226/0x3c0
> [1282119.859031]  worker_thread+0x50/0x410
> [1282119.860747]  ? process_one_work+0x3c0/0x3c0
> [1282119.862674]  kthread+0x127/0x150
> [1282119.864307]  ? set_kthread_struct+0x50/0x50
> [1282119.867863]  ret_from_fork+0x22/0x30
> [1282119.869538]  </TASK>

So far it seems that most tasks are waiting for transaction to commit, jbd2
thread committing the transaction waits for someone to drop its transaction
reference which never happens. It is unclear who holds the transaction
reference. But with stacktraces corrupted like this it is difficult to be
certain.

So probably first try find out why stacktraces are not working right on
your kernel and fix them. And then, if the hang happens, please trigger
sysrq-w (or do echo w >/proc/sysrq-trigger if you can still get to the
machine) and send here the output. It will dump all blocked tasks and from
that we should be able to better understand what is happening.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

  reply	other threads:[~2022-09-29  8:28 UTC|newest]

Thread overview: 33+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2022-08-08  7:34 [syzbot] possible deadlock in jbd2_journal_lock_updates syzbot
2022-08-08 16:38 ` syzbot
2022-08-24 10:06   ` Jan Kara
2022-09-28  7:30     ` Thilo Fromm
2022-09-29  8:27       ` Jan Kara [this message]
2022-09-29 13:18         ` Thilo Fromm
2022-10-04  6:38           ` Jeremi Piotrowski
2022-10-04  9:10             ` Jan Kara
2022-10-04 14:21               ` Thilo Fromm
2022-10-05 15:10                 ` Jan Kara
2022-10-10 14:24                   ` Jeremi Piotrowski
2022-10-14  6:42                     ` Thilo Fromm
2022-10-14 13:25                       ` Jan Kara
2022-10-21 10:23                         ` Thilo Fromm
2022-10-24 10:46                           ` Jan Kara
2022-10-24 16:32                             ` Thilo Fromm
2022-10-26 10:18                               ` Jan Kara
2022-11-10 12:57                                 ` Jeremi Piotrowski
2022-11-10 15:26                                   ` Jan Kara
2022-11-10 19:27                                     ` Jeremi Piotrowski
2022-11-11 14:24                                       ` Jan Kara
2022-11-11 15:10                                         ` Jeremi Piotrowski
2022-11-11 15:52                                           ` Jeremi Piotrowski
2022-11-21 13:35                                             ` Jan Kara
2022-11-21 15:00                                               ` Jan Kara
2022-11-21 15:18                                                 ` Thorsten Leemhuis
2022-11-21 15:40                                                   ` Jan Kara
2022-11-21 18:15                                                 ` Jeremi Piotrowski
2022-11-22 11:57                                                   ` Jan Kara
2022-11-22 17:48                                                     ` Jeremi Piotrowski
2022-11-23 19:41                                                       ` Jan Kara
2022-09-30 12:16       ` [syzbot] possible deadlock in jbd2_journal_lock_updates #forregzbot Thorsten Leemhuis
2022-11-23  9:56         ` Thorsten Leemhuis

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20220929082716.5urzcfk4hnapd3cr@quack3 \
    --to=jack@suse.cz \
    --cc=jack@suse.com \
    --cc=linux-ext4@vger.kernel.org \
    --cc=t-lo@linux.microsoft.com \
    --cc=tytso@mit.edu \
    --cc=yebin10@huawei.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).