kjournald2提交流程和jbd2_journal_start_reserved异常流程并发，报 kernel BUG at fs/jbd2/commit.c:616

【标题描述】kjournald2提交流程和jbd2_journal_start_reserved异常流程并发，报 kernel BUG at fs/jbd2/commit.c:616
【环境信息】
NA
软件信息：
OLK-5.10
【问题复现步骤】
1.首先在内核中打入以下延时注入补丁。
```
diff --git a/fs/ext4/extents.c b/fs/ext4/extents.c
index 4323186bae78..69b78861d380 100644
--- a/fs/ext4/extents.c
+++ b/fs/ext4/extents.c
@@ -4829,11 +4829,14 @@ int ext4_convert_unwritten_extents(handle_t *handle, struct inode *inode,
 	return ret > 0 ? ret2 : ret;
 }
 
+#include <linux/delay.h>
 int ext4_convert_unwritten_io_end_vec(handle_t *handle, ext4_io_end_t *io_end)
 {
 	int ret = 0, err = 0;
 	struct ext4_io_end_vec *io_end_vec;
 
+	printk("[%s] sleep 15s to wait kjournald2 start\n", __func__);
+	msleep(15 * 1000);
 	/*
 	 * This is somewhat ugly but the idea is clear: When transaction is
 	 * reserved, everything goes into it. Otherwise we rather start several
diff --git a/fs/ext4/inode.c b/fs/ext4/inode.c
index a46b0074ebcc..ebf1e56cb003 100644
--- a/fs/ext4/inode.c
+++ b/fs/ext4/inode.c
@@ -2817,6 +2817,7 @@ static int ext4_writepages(struct address_space *mapping,
 		needed_blocks = ext4_da_writepages_trans_blocks(inode);
 
 		/* start a new transaction */
+		printk("[%s] start rsv %d handle\n", __func__, rsv_blocks);
 		handle = ext4_journal_start_with_reserve(inode,
 				EXT4_HT_WRITE_PAGE, needed_blocks, rsv_blocks);
 		if (IS_ERR(handle)) {
@@ -2905,6 +2906,7 @@ static int ext4_writepages(struct address_space *mapping,
 	trace_ext4_writepages_result(inode, wbc, ret,
 				     nr_to_write - wbc->nr_to_write);
 	percpu_up_read(&sbi->s_writepages_rwsem);
+	printk("[%s] ret=%d\n", __func__, ret);
 	return ret;
 }
 
diff --git a/fs/jbd2/commit.c b/fs/jbd2/commit.c
index b121d7d434c6..5b7da6234600 100644
--- a/fs/jbd2/commit.c
+++ b/fs/jbd2/commit.c
@@ -378,6 +378,7 @@ static void jbd2_block_tag_csum_set(journal_t *j, journal_block_tag_t *tag,
  * The primary function for committing a transaction to the log.  This
  * function is called by the journal thread to begin a complete commit.
  */
+#include <linux/delay.h>
 void jbd2_journal_commit_transaction(journal_t *journal)
 {
 	struct transaction_stats_s stats;
@@ -565,9 +566,22 @@ void jbd2_journal_commit_transaction(journal_t *journal)
 	/*
 	 * Reserved credits cannot be claimed anymore, free them
 	 */
+	printk("[%s] transaction %u j_reserved_credits=%d\n",
+		__func__, commit_transaction->t_tid,
+		atomic_read(&journal->j_reserved_credits));
 	atomic_sub(atomic_read(&journal->j_reserved_credits),
 		   &commit_transaction->t_outstanding_credits);
 
+	if (is_journal_aborted(journal) &&
+	    atomic_read(&journal->j_reserved_credits)) {
+		printk("[%s] transaction %u, t_nr_buffers %d sub %d to outstanding %d\n",
+			__func__, commit_transaction->t_tid,
+			commit_transaction->t_nr_buffers,
+			atomic_read(&journal->j_reserved_credits),
+			atomic_read(&commit_transaction->t_outstanding_credits));
+		msleep(20 * 1000);
+	}
+
 	write_lock(&journal->j_state_lock);
 	trace_jbd2_commit_flushing(journal, commit_transaction);
 	stats.run.rs_flushing = jiffies;
diff --git a/fs/jbd2/journal.c b/fs/jbd2/journal.c
index aae412b0bfae..40fe12f2aea0 100644
--- a/fs/jbd2/journal.c
+++ b/fs/jbd2/journal.c
@@ -2516,8 +2516,11 @@ void jbd2_journal_abort(journal_t *journal, int errno)
 	journal->j_flags |= JBD2_ABORT;
 	journal->j_errno = errno;
 	transaction = journal->j_running_transaction;
-	if (transaction)
+	if (transaction) {
+		printk("[%s] start to submit transaction %d\n",
+			__func__, transaction->t_tid);
 		__jbd2_log_start_commit(journal, transaction->t_tid);
+	}
 	write_unlock(&journal->j_state_lock);
 
 	/*
diff --git a/fs/jbd2/transaction.c b/fs/jbd2/transaction.c
index 8804e126805f..c1f8a38fdf26 100644
--- a/fs/jbd2/transaction.c
+++ b/fs/jbd2/transaction.c
@@ -554,8 +554,12 @@ static void __jbd2_journal_unreserve_handle(handle_t *handle, transaction_t *t)
 
 	WARN_ON(!handle->h_reserved);
 	sub_reserved_credits(journal, handle->h_total_credits);
-	if (t)
+	if (t) {
 		atomic_sub(handle->h_total_credits, &t->t_outstanding_credits);
+		printk("[%s] sub %d to outstanding %d\n", __func__,
+			handle->h_total_credits,
+			atomic_read(&t->t_outstanding_credits));
+	}
 }
 
 void jbd2_journal_free_reserved(handle_t *handle)
```
2. 执行以下脚本
```
#!/bin/bash
TEST_DEV="/dev/pmem1"

echo 0 > /sys/block/${TEST_DEV##*/}/make-it-fail
echo 100 > /sys/kernel/debug/fail_make_request/probability
echo 2 > /sys/kernel/debug/fail_make_request/verbose
echo 1 > /sys/kernel/debug/fail_make_request/times
echo 500 > /proc/sys/vm/dirty_writeback_centisecs

mkfs.ext4 -F -b 4K -E lazy_itable_init=0,lazy_journal_init=0 $TEST_DEV 500M
mount -o dioread_lock $TEST_DEV /mnt
xfs_io -fc "pwrite 1 1" /mnt/foo
umount /mnt
mount -o errors=remount-ro $TEST_DEV /mnt
sleep 1
touch /mnt/bar
sleep 0.1
xfs_io -c "fsync" /mnt/bar  #sync jbd2 and wait backgroud writeback
sleep 0.1
xfs_io -c "pwrite 1 4096" /mnt/foo  #start a new transaction with reserved cred
sleep 0.1
xfs_io -c "fdatasync" /mnt/foo &
sleep 0.1
echo 1 > /sys/block/${TEST_DEV##*/}/make-it-fail
sleep 0.1
echo 400 > /proc/sys/vm/dirty_writeback_centisecs  #trigger writeback
sleep 0.5
touch /mnt/bar
```
出现概率(是否必现，概率性错误)大概率
【预期结果】
jbd2报BUGON
【实际结果】
```
[   47.752577] [jbd2_journal_commit_transaction] transaction 6 j_reserved_credits=9
[   47.753871] [jbd2_journal_commit_transaction] transaction 6, t_nr_buffers 3 sub 9 to outstanding 9
[   62.394077] [ext4_convert_unwritten_io_end_vec] sleep 15s done
[   62.395211] [__ext4_journal_start_reserved]
[   62.396029] [__jbd2_journal_unreserve_handle] sub 9 to outstanding 0
[   62.397503] [ext4_writepages] ret=0
[   68.026013] ------------[ cut here ]------------
[   68.027494] kernel BUG at fs/jbd2/commit.c:630!
[   68.029098] invalid opcode: 0000 [#1] SMP
[   68.030599] CPU: 22 PID: 971 Comm: jbd2/pmem1-8 Not tainted 5.10.0-16635-gee53a654b61c-dirty #137
[   68.032759] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31 04/01/2014
[   68.035245] RIP: 0010:jbd2_journal_commit_transaction+0x2001/0x3110
[   68.036421] Code: 48 83 05 81 3f 9f 0b 01 0f 0b 48 83 05 87 3f 9f 0b 01 48 83 05 87 3f 9f 0b 01 48 83 05 87 3f 9f 0b 01 48 83 05 1f 3c 9f 0b 01 <0f> 0b 48 83 05 1d 3c 9f 0b 01 48 83 05 1d 3c 9f 0b 01 48 83 0d
[   68.039829] RSP: 0018:ffffc90000a93cf0 EFLAGS: 00010202
[   68.040789] RAX: 0000000000000000 RBX: ffff88811685e800 RCX: 0000000000000264
[   68.042089] RDX: 00000000fffc7400 RSI: ffffffffb0bed3e6 RDI: ffff88811685e84c
[   68.043344] RBP: ffffc90000a93e80 R08: ffffffffb0bed43c R09: 0000000000000000
[   68.044367] R10: 0000000000000252 R11: 0000000fcda72e00 R12: 0000000000000000
[   68.045405] R13: ffff88811975a040 R14: ffff8881257fce80 R15: ffff88811975a000
[   68.046447] FS:  0000000000000000(0000) GS:ffff888825b80000(0000) knlGS:0000000000000000
[   68.047559] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   68.048368] CR2: 000055e98e65f8a0 CR3: 0000000125732000 CR4: 00000000000006e0
[   68.049357] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   68.050358] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   68.051356] Call Trace:
[   68.051727]  ? newidle_balance+0x2bf/0x5a0
[   68.052306]  ? kjournald2+0x12e/0x510
[   68.052826]  kjournald2+0x12e/0x510
[   68.053326]  ? woken_wake_function+0x30/0x30
[   68.053935]  ? commit_timeout+0x20/0x20
[   68.054469]  kthread+0x153/0x1b0
[   68.054941]  ? kthread_flush_work+0x170/0x170
[   68.055551]  ret_from_fork+0x1f/0x30
[   68.056074] Modules linked in:
[   68.056570] ---[ end trace 2de5a4ecb108f782 ]---
```
【附件信息】
比如系统message日志/组件日志、dump信息、图片等

GVP openEuler/kernel

内容风险标识

评论 (1)

GVPopenEuler/kernel

内容风险标识