Skip to contentSkip to conversation

ocfs2: fix trans extend while flush truncate log

PATCH Applied Junxiao Bi 2 participants 5 messages Sep 12, 2016 – Sep 13, 2016 OCFS2

lore
Share & tools
lore

Junxiao Bi

author
#0 lore raw

PATCH 1/2 ocfs2: fix trans extend while flush truncate log

Every time, ocfs2_extend_trans() included a credit for truncate log inode, but as that inode had been managed by jbd2 running transaction first time, it will not consume that credit until jbd2_journal_restart(). Since total credits to extend always included the un-consumed ones, there will be more and more un-consumed credit, at last jbd2_journal_restart() will fail due to credit number over the half of max transction credit.

The following error was caught when unlink a large file with many extents.

[233096.013936] ------------[ cut here ]------------
[233096.018586] WARNING: CPU: 0 PID: 13626 at fs/jbd2/transaction.c:269 start_this_handle+0x4c3/0x510 [jbd2]()
[233096.028335] Modules linked in: ocfs2 nfsd lockd grace nfs_acl auth_rpcgss sunrpc autofs4 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs sd_mod sg ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr ipv6 iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev xen_kbdfront xen_netfront fb_sys_fops sysimgblt sysfillrect syscopyarea parport_pc parport pcspkr i2c_piix4 i2c_core acpi_cpufreq ext4 jbd2 mbcache xen_blkfront floppy pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod
[233096.081751] CPU: 0 PID: 13626 Comm: unlink Tainted: G        W       4.1.12-37.6.3.el6uek.x86_64 #2
[233096.088556] Hardware name: Xen HVM domU, BIOS 4.4.4OVM 02/11/2016
[233096.093125]  000000000000010d ffff88000018b768 ffffffff816bc5bc 000000000000010d
[233096.099082]  0000000000000000 ffff88000018b7a8 ffffffff81081475 ffff88000018b788
[233096.105038]  ffff88007a99a000 ffff88007b573390 00000000000000fb 0000000000000050
[233096.110540] Call Trace:
[233096.111893]  [<ffffffff816bc5bc>] dump_stack+0x48/0x5c
[233096.114637]  [<ffffffff81081475>] warn_slowpath_common+0x95/0xe0
[233096.117797]  [<ffffffff810814da>] warn_slowpath_null+0x1a/0x20
[233096.120984]  [<ffffffffa0080993>] start_this_handle+0x4c3/0x510 [jbd2]
[233096.124505]  [<ffffffffa0088f95>] ? __jbd2_log_start_commit+0xe5/0xf0 [jbd2]
[233096.128115]  [<ffffffff810c4eb3>] ? __wake_up+0x53/0x70
[233096.130924]  [<ffffffffa0080b41>] jbd2__journal_restart+0x161/0x1b0 [jbd2]
[233096.134523]  [<ffffffffa0080ba3>] jbd2_journal_restart+0x13/0x20 [jbd2]
[233096.137986]  [<ffffffffa06d1d94>] ocfs2_extend_trans+0x74/0x220 [ocfs2]
[233096.141407]  [<ffffffffa06d156a>] ? ocfs2_journal_dirty+0x3a/0x90 [ocfs2]
[233096.144921]  [<ffffffffa0692943>] ocfs2_replay_truncate_records+0x93/0x360 [ocfs2]
[233096.148819]  [<ffffffffa0697ace>] __ocfs2_flush_truncate_log+0x13e/0x3a0 [ocfs2]
[233096.152644]  [<ffffffffa0697304>] ? ocfs2_reserve_blocks_for_rec_trunc.clone.0+0x44/0x1f0 [ocfs2]
[233096.157310]  [<ffffffffa069f768>] ocfs2_remove_btree_range+0x458/0x7f0 [ocfs2]
[233096.161099]  [<ffffffffa0696777>] ? __ocfs2_find_path+0x187/0x2d0 [ocfs2]
[233096.164612]  [<ffffffffa06a2673>] ocfs2_commit_truncate+0x1b3/0x6f0 [ocfs2]
[233096.168204]  [<ffffffffa0744ac0>] ? ocfs2_xattr_tree_et_ops+0x60/0xfffffffffffe8c20 [ocfs2]
[233096.172539]  [<ffffffffa06d1a00>] ? ocfs2_journal_access_eb+0x20/0x20 [ocfs2]
[233096.176285]  [<ffffffff81202303>] ? __sb_end_write+0x33/0x70
[233096.179226]  [<ffffffffa06ca61d>] ocfs2_truncate_for_delete+0xbd/0x380 [ocfs2]
[233096.183009]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.186738]  [<ffffffffa06caf76>] ocfs2_wipe_inode+0x136/0x6a0 [ocfs2]
[233096.190165]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.193846]  [<ffffffffa06cb782>] ocfs2_delete_inode+0x2a2/0x3e0 [ocfs2]
[233096.197274]  [<ffffffff812298c9>] ? __inode_wait_for_writeback+0x69/0xc0
[233096.200736]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.205146]  [<ffffffffa06cc298>] ocfs2_evict_inode+0x28/0x60 [ocfs2]
[233096.208462]  [<ffffffff8121b81b>] evict+0xab/0x1a0
[233096.211020]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.215396]  [<ffffffff8121ba06>] iput_final+0xf6/0x190
[233096.218169]  [<ffffffff8121bb68>] iput+0xc8/0xe0
[233096.220586]  [<ffffffff8120f9b7>] do_unlinkat+0x1b7/0x310
[233096.223487]  [<ffffffff8106ae5b>] ? __do_page_fault+0x18b/0x480
[233096.226655]  [<ffffffff81126dbc>] ? __audit_syscall_entry+0xac/0x110
[233096.230009]  [<ffffffff810236cc>] ? do_audit_syscall_entry+0x6c/0x70
[233096.233346]  [<ffffffff81023823>] ? syscall_trace_enter_phase1+0x153/0x180
[233096.237103]  [<ffffffff8120fb26>] SyS_unlink+0x16/0x20
[233096.239800]  [<ffffffff816c122e>] system_call_fastpath+0x12/0x71
[233096.244346] ---[ end trace 28aa7410e69369cf ]---
[233096.247798] JBD2: unlink wants too many credits (251 > 128)
Signed-off-by Junxiao Bi <[email protected]>
---
 fs/ocfs2/alloc.c |   29 ++++++++++-------------------
 1 file changed, 10 insertions(+), 19 deletions(-)
fs/ocfs2/alloc.c +10 -19
index 7dabbc31060e..51128789a661 100644
@@ -5922,7 +5922,6 @@ bail:
 }
 
 static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
-					 handle_t *handle,
 					 struct inode *data_alloc_inode,
 					 struct buffer_head *data_alloc_bh)
 {

@@ -5935,11 +5934,19 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 	struct ocfs2_truncate_log *tl;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;
+	handle_t *handle;
 
 	di = (struct ocfs2_dinode *) tl_bh->b_data;
 	tl = &di->id2.i_dealloc;
 	i = le16_to_cpu(tl->tl_used) - 1;
 	while (i >= 0) {
+		handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
+		if (IS_ERR(handle)) {
+			status = PTR_ERR(handle);
+			mlog_errno(status);
+			goto bail;
+		}
+
 		/* Caller has given us at least enough credits to
 		 * update the truncate log dinode */
 		status = ocfs2_journal_access_di(handle, INODE_CACHE(tl_inode), tl_bh,

@@ -5974,12 +5981,7 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 			}
 		}
 
-		status = ocfs2_extend_trans(handle,
-				OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-		if (status < 0) {
-			mlog_errno(status);
-			goto bail;
-		}
+		ocfs2_commit_trans(osb, handle);
 		i--;
 	}
 

@@ -5994,7 +5996,6 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 {
 	int status;
 	unsigned int num_to_flush;
-	handle_t *handle;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct inode *data_alloc_inode = NULL;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;

@@ -6038,21 +6039,11 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 		goto out_mutex;
 	}
 
-	handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-	if (IS_ERR(handle)) {
-		status = PTR_ERR(handle);
-		mlog_errno(status);
-		goto out_unlock;
-	}
-
-	status = ocfs2_replay_truncate_records(osb, handle, data_alloc_inode,
+	status = ocfs2_replay_truncate_records(osb, data_alloc_inode,
 					       data_alloc_bh);
 	if (status < 0)
 		mlog_errno(status);
 
-	ocfs2_commit_trans(osb, handle);
-
-out_unlock:
 	brelse(data_alloc_bh);
 	ocfs2_inode_unlock(data_alloc_inode, 1);
Signature · 1 line
1.7.9.5
author
#1 lore raw

PATCH 2/2 ocfs2: fix trans extend while free cached blocks

Root cause of this issue is the same with the one fixed by last patch, but this time credits for allocator inode and group descriptor may not be consumed before trans extend.

The following error was caught.

[  685.240276] WARNING: CPU: 0 PID: 2037 at fs/jbd2/transaction.c:269 start_this_handle+0x4c3/0x510 [jbd2]()
[  685.240294] Modules linked in: ocfs2 nfsd lockd grace nfs_acl auth_rpcgss sunrpc autofs4 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs sd_mod sg ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr ipv6 iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev xen_kbdfront fb_sys_fops sysimgblt sysfillrect syscopyarea xen_netfront parport_pc parport pcspkr i2c_piix4 i2c_core acpi_cpufreq ext4 jbd2 mbcache xen_blkfront floppy pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod
[  685.240296] CPU: 0 PID: 2037 Comm: rm Tainted: G        W       4.1.12-37.6.3.el6uek.bug24573128v2.x86_64 #2
[  685.240296] Hardware name: Xen HVM domU, BIOS 4.4.4OVM 02/11/2016
[  685.240298]  000000000000010d ffff88007ac3f808 ffffffff816bc5bc 000000000000010d
[  685.240300]  0000000000000000 ffff88007ac3f848 ffffffff81081475 ffff88007ac3f828
[  685.240301]  ffff880037bbf000 ffff880037688210 0000000000000095 0000000000000050
[  685.240301] Call Trace:
[  685.240305]  [<ffffffff816bc5bc>] dump_stack+0x48/0x5c
[  685.240308]  [<ffffffff81081475>] warn_slowpath_common+0x95/0xe0
[  685.240310]  [<ffffffff810814da>] warn_slowpath_null+0x1a/0x20
[  685.240313]  [<ffffffffa0080993>] start_this_handle+0x4c3/0x510 [jbd2]
[  685.240317]  [<ffffffffa0088f95>] ? __jbd2_log_start_commit+0xe5/0xf0 [jbd2]
[  685.240319]  [<ffffffff810c4eb3>] ? __wake_up+0x53/0x70
[  685.240322]  [<ffffffffa0080b41>] jbd2__journal_restart+0x161/0x1b0 [jbd2]
[  685.240325]  [<ffffffffa0080ba3>] jbd2_journal_restart+0x13/0x20 [jbd2]
[  685.240340]  [<ffffffffa06d1cf4>] ocfs2_extend_trans+0x74/0x220 [ocfs2]
[  685.240347]  [<ffffffffa069762b>] ocfs2_free_cached_blocks+0x16b/0x4e0 [ocfs2]
[  685.240349]  [<ffffffff810e9131>] ? internal_add_timer+0x91/0xc0
[  685.240356]  [<ffffffffa06981b0>] ocfs2_run_deallocs+0x70/0x270 [ocfs2]
[  685.240363]  [<ffffffffa06a2894>] ocfs2_commit_truncate+0x474/0x6f0 [ocfs2]
[  685.240374]  [<ffffffffa0744a40>] ? ocfs2_xattr_tree_et_ops+0x60/0xfffffffffffe8c00 [ocfs2]
[  685.240384]  [<ffffffffa06d1960>] ? ocfs2_journal_access_eb+0x20/0x20 [ocfs2]
[  685.240385]  [<ffffffff81202303>] ? __sb_end_write+0x33/0x70
[  685.240394]  [<ffffffffa06ca57d>] ocfs2_truncate_for_delete+0xbd/0x380 [ocfs2]
[  685.240402]  [<ffffffffa06ca1f4>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[  685.240409]  [<ffffffffa06caed6>] ocfs2_wipe_inode+0x136/0x6a0 [ocfs2]
[  685.240415]  [<ffffffffa06ca1f4>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[  685.240422]  [<ffffffffa06cb6e2>] ocfs2_delete_inode+0x2a2/0x3e0 [ocfs2]
[  685.240424]  [<ffffffff812298c9>] ? __inode_wait_for_writeback+0x69/0xc0
[  685.240437]  [<ffffffffa0732100>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb500 [ocfs2]
[  685.240444]  [<ffffffffa06cc1f8>] ocfs2_evict_inode+0x28/0x60 [ocfs2]
[  685.240445]  [<ffffffff8121b81b>] evict+0xab/0x1a0
[  685.240456]  [<ffffffffa0732100>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb500 [ocfs2]
[  685.240457]  [<ffffffff8121ba06>] iput_final+0xf6/0x190
[  685.240458]  [<ffffffff8121bb68>] iput+0xc8/0xe0
[  685.240460]  [<ffffffff8120f9b7>] do_unlinkat+0x1b7/0x310
[  685.240462]  [<ffffffff81126dbc>] ? __audit_syscall_entry+0xac/0x110
[  685.240464]  [<ffffffff810236cc>] ? do_audit_syscall_entry+0x6c/0x70
[  685.240465]  [<ffffffff81023823>] ? syscall_trace_enter_phase1+0x153/0x180
[  685.240467]  [<ffffffff8120fd52>] SyS_unlinkat+0x22/0x40
[  685.240468]  [<ffffffff816c122e>] system_call_fastpath+0x12/0x71
[  685.240469] ---[ end trace a62437cb060baa71 ]---
[  685.240470] JBD2: rm wants too many credits (149 > 128)
Signed-off-by Junxiao Bi <[email protected]>
---
 fs/ocfs2/alloc.c |   27 +++++++++------------------
 1 file changed, 9 insertions(+), 18 deletions(-)
fs/ocfs2/alloc.c +9 -18
index 51128789a661..f165f867f332 100644
@@ -6404,43 +6404,34 @@ static int ocfs2_free_cached_blocks(struct ocfs2_super *osb,
 		goto out_mutex;
 	}
 
-	handle = ocfs2_start_trans(osb, OCFS2_SUBALLOC_FREE);
-	if (IS_ERR(handle)) {
-		ret = PTR_ERR(handle);
-		mlog_errno(ret);
-		goto out_unlock;
-	}
-
 	while (head) {
 		if (head->free_bg)
 			bg_blkno = head->free_bg;
 		else
 			bg_blkno = ocfs2_which_suballoc_group(head->free_blk,
 							      head->free_bit);
+		handle = ocfs2_start_trans(osb, OCFS2_SUBALLOC_FREE);
+		if (IS_ERR(handle)) {
+			ret = PTR_ERR(handle);
+			mlog_errno(ret);
+			goto out_unlock;
+		}
+
 		trace_ocfs2_free_cached_blocks(
 		     (unsigned long long)head->free_blk, head->free_bit);
 
 		ret = ocfs2_free_suballoc_bits(handle, inode, di_bh,
 					       head->free_bit, bg_blkno, 1);
-		if (ret) {
+		if (ret)
 			mlog_errno(ret);
-			goto out_journal;
-		}
 
-		ret = ocfs2_extend_trans(handle, OCFS2_SUBALLOC_FREE);
-		if (ret) {
-			mlog_errno(ret);
-			goto out_journal;
-		}
+		ocfs2_commit_trans(osb, handle);
 
 		tmp = head;
 		head = head->free_next;
 		kfree(tmp);
 	}
 
-out_journal:
-	ocfs2_commit_trans(osb, handle);
-
 out_unlock:
 	ocfs2_inode_unlock(inode, 1);
 	brelse(di_bh);
Signature · 1 line
1.7.9.5
#2 lore raw

PATCH 2/2 ocfs2: fix trans extend while free cached blocks

Thanks Junxiao.

Reviewed-by Joseph Qi <[email protected]>
Quoted 114 lines · Junxiao Bi

Root cause of this issue is the same with the one fixed by last patch, but this time credits for allocator inode and group descriptor may not be consumed before trans extend.

The following error was caught.

[  685.240276] WARNING: CPU: 0 PID: 2037 at fs/jbd2/transaction.c:269 start_this_handle+0x4c3/0x510 [jbd2]()
[  685.240294] Modules linked in: ocfs2 nfsd lockd grace nfs_acl auth_rpcgss sunrpc autofs4 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs sd_mod sg ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr ipv6 iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev xen_kbdfront fb_sys_fops sysimgblt sysfillrect syscopyarea xen_netfront parport_pc parport pcspkr i2c_piix4 i2c_core acpi_cpufreq ext4 jbd2 mbcache xen_blkfront floppy pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod
[  685.240296] CPU: 0 PID: 2037 Comm: rm Tainted: G        W       4.1.12-37.6.3.el6uek.bug24573128v2.x86_64 #2
[  685.240296] Hardware name: Xen HVM domU, BIOS 4.4.4OVM 02/11/2016
[  685.240298]  000000000000010d ffff88007ac3f808 ffffffff816bc5bc 000000000000010d
[  685.240300]  0000000000000000 ffff88007ac3f848 ffffffff81081475 ffff88007ac3f828
[  685.240301]  ffff880037bbf000 ffff880037688210 0000000000000095 0000000000000050
[  685.240301] Call Trace:
[  685.240305]  [<ffffffff816bc5bc>] dump_stack+0x48/0x5c
[  685.240308]  [<ffffffff81081475>] warn_slowpath_common+0x95/0xe0
[  685.240310]  [<ffffffff810814da>] warn_slowpath_null+0x1a/0x20
[  685.240313]  [<ffffffffa0080993>] start_this_handle+0x4c3/0x510 [jbd2]
[  685.240317]  [<ffffffffa0088f95>] ? __jbd2_log_start_commit+0xe5/0xf0 [jbd2]
[  685.240319]  [<ffffffff810c4eb3>] ? __wake_up+0x53/0x70
[  685.240322]  [<ffffffffa0080b41>] jbd2__journal_restart+0x161/0x1b0 [jbd2]
[  685.240325]  [<ffffffffa0080ba3>] jbd2_journal_restart+0x13/0x20 [jbd2]
[  685.240340]  [<ffffffffa06d1cf4>] ocfs2_extend_trans+0x74/0x220 [ocfs2]
[  685.240347]  [<ffffffffa069762b>] ocfs2_free_cached_blocks+0x16b/0x4e0 [ocfs2]
[  685.240349]  [<ffffffff810e9131>] ? internal_add_timer+0x91/0xc0
[  685.240356]  [<ffffffffa06981b0>] ocfs2_run_deallocs+0x70/0x270 [ocfs2]
[  685.240363]  [<ffffffffa06a2894>] ocfs2_commit_truncate+0x474/0x6f0 [ocfs2]
[  685.240374]  [<ffffffffa0744a40>] ? ocfs2_xattr_tree_et_ops+0x60/0xfffffffffffe8c00 [ocfs2]
[  685.240384]  [<ffffffffa06d1960>] ? ocfs2_journal_access_eb+0x20/0x20 [ocfs2]
[  685.240385]  [<ffffffff81202303>] ? __sb_end_write+0x33/0x70
[  685.240394]  [<ffffffffa06ca57d>] ocfs2_truncate_for_delete+0xbd/0x380 [ocfs2]
[  685.240402]  [<ffffffffa06ca1f4>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[  685.240409]  [<ffffffffa06caed6>] ocfs2_wipe_inode+0x136/0x6a0 [ocfs2]
[  685.240415]  [<ffffffffa06ca1f4>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[  685.240422]  [<ffffffffa06cb6e2>] ocfs2_delete_inode+0x2a2/0x3e0 [ocfs2]
[  685.240424]  [<ffffffff812298c9>] ? __inode_wait_for_writeback+0x69/0xc0
[  685.240437]  [<ffffffffa0732100>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb500 [ocfs2]
[  685.240444]  [<ffffffffa06cc1f8>] ocfs2_evict_inode+0x28/0x60 [ocfs2]
[  685.240445]  [<ffffffff8121b81b>] evict+0xab/0x1a0
[  685.240456]  [<ffffffffa0732100>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb500 [ocfs2]
[  685.240457]  [<ffffffff8121ba06>] iput_final+0xf6/0x190
[  685.240458]  [<ffffffff8121bb68>] iput+0xc8/0xe0
[  685.240460]  [<ffffffff8120f9b7>] do_unlinkat+0x1b7/0x310
[  685.240462]  [<ffffffff81126dbc>] ? __audit_syscall_entry+0xac/0x110
[  685.240464]  [<ffffffff810236cc>] ? do_audit_syscall_entry+0x6c/0x70
[  685.240465]  [<ffffffff81023823>] ? syscall_trace_enter_phase1+0x153/0x180
[  685.240467]  [<ffffffff8120fd52>] SyS_unlinkat+0x22/0x40
[  685.240468]  [<ffffffff816c122e>] system_call_fastpath+0x12/0x71
[  685.240469] ---[ end trace a62437cb060baa71 ]---
[  685.240470] JBD2: rm wants too many credits (149 > 128)
Signed-off-by Junxiao Bi <[email protected]>
---
 fs/ocfs2/alloc.c |   27 +++++++++------------------
 1 file changed, 9 insertions(+), 18 deletions(-)
fs/ocfs2/alloc.c +9 -18
index 51128789a661..f165f867f332 100644
@@ -6404,43 +6404,34 @@ static int ocfs2_free_cached_blocks(struct ocfs2_super *osb,
 		goto out_mutex;
 	}
 
-	handle = ocfs2_start_trans(osb, OCFS2_SUBALLOC_FREE);
-	if (IS_ERR(handle)) {
-		ret = PTR_ERR(handle);
-		mlog_errno(ret);
-		goto out_unlock;
-	}
-
 	while (head) {
 		if (head->free_bg)
 			bg_blkno = head->free_bg;
 		else
 			bg_blkno = ocfs2_which_suballoc_group(head->free_blk,
 							      head->free_bit);
+		handle = ocfs2_start_trans(osb, OCFS2_SUBALLOC_FREE);
+		if (IS_ERR(handle)) {
+			ret = PTR_ERR(handle);
+			mlog_errno(ret);
+			goto out_unlock;
+		}
+
 		trace_ocfs2_free_cached_blocks(
 		     (unsigned long long)head->free_blk, head->free_bit);
 
 		ret = ocfs2_free_suballoc_bits(handle, inode, di_bh,
 					       head->free_bit, bg_blkno, 1);
-		if (ret) {
+		if (ret)
 			mlog_errno(ret);
-			goto out_journal;
-		}
 
-		ret = ocfs2_extend_trans(handle, OCFS2_SUBALLOC_FREE);
-		if (ret) {
-			mlog_errno(ret);
-			goto out_journal;
-		}
+		ocfs2_commit_trans(osb, handle);
 
 		tmp = head;
 		head = head->free_next;
 		kfree(tmp);
 	}
 
-out_journal:
-	ocfs2_commit_trans(osb, handle);
-
 out_unlock:
 	ocfs2_inode_unlock(inode, 1);
 	brelse(di_bh);
#3 lore raw

PATCH 1/2 ocfs2: fix trans extend while flush truncate log

In reply to Junxiao Bi

Hi Junxiao,

Quoted 85 lines · Junxiao Bi

Every time, ocfs2_extend_trans() included a credit for truncate log inode, but as that inode had been managed by jbd2 running transaction first time, it will not consume that credit until jbd2_journal_restart(). Since total credits to extend always included the un-consumed ones, there will be more and more un-consumed credit, at last jbd2_journal_restart() will fail due to credit number over the half of max transction credit.

The following error was caught when unlink a large file with many extents.

[233096.013936] ------------[ cut here ]------------
[233096.018586] WARNING: CPU: 0 PID: 13626 at fs/jbd2/transaction.c:269 start_this_handle+0x4c3/0x510 [jbd2]()
[233096.028335] Modules linked in: ocfs2 nfsd lockd grace nfs_acl auth_rpcgss sunrpc autofs4 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs sd_mod sg ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr ipv6 iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev xen_kbdfront xen_netfront fb_sys_fops sysimgblt sysfillrect syscopyarea parport_pc parport pcspkr i2c_piix4 i2c_core acpi_cpufreq ext4 jbd2 mbcache xen_blkfront floppy pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod
[233096.081751] CPU: 0 PID: 13626 Comm: unlink Tainted: G        W       4.1.12-37.6.3.el6uek.x86_64 #2
[233096.088556] Hardware name: Xen HVM domU, BIOS 4.4.4OVM 02/11/2016
[233096.093125]  000000000000010d ffff88000018b768 ffffffff816bc5bc 000000000000010d
[233096.099082]  0000000000000000 ffff88000018b7a8 ffffffff81081475 ffff88000018b788
[233096.105038]  ffff88007a99a000 ffff88007b573390 00000000000000fb 0000000000000050
[233096.110540] Call Trace:
[233096.111893]  [<ffffffff816bc5bc>] dump_stack+0x48/0x5c
[233096.114637]  [<ffffffff81081475>] warn_slowpath_common+0x95/0xe0
[233096.117797]  [<ffffffff810814da>] warn_slowpath_null+0x1a/0x20
[233096.120984]  [<ffffffffa0080993>] start_this_handle+0x4c3/0x510 [jbd2]
[233096.124505]  [<ffffffffa0088f95>] ? __jbd2_log_start_commit+0xe5/0xf0 [jbd2]
[233096.128115]  [<ffffffff810c4eb3>] ? __wake_up+0x53/0x70
[233096.130924]  [<ffffffffa0080b41>] jbd2__journal_restart+0x161/0x1b0 [jbd2]
[233096.134523]  [<ffffffffa0080ba3>] jbd2_journal_restart+0x13/0x20 [jbd2]
[233096.137986]  [<ffffffffa06d1d94>] ocfs2_extend_trans+0x74/0x220 [ocfs2]
[233096.141407]  [<ffffffffa06d156a>] ? ocfs2_journal_dirty+0x3a/0x90 [ocfs2]
[233096.144921]  [<ffffffffa0692943>] ocfs2_replay_truncate_records+0x93/0x360 [ocfs2]
[233096.148819]  [<ffffffffa0697ace>] __ocfs2_flush_truncate_log+0x13e/0x3a0 [ocfs2]
[233096.152644]  [<ffffffffa0697304>] ? ocfs2_reserve_blocks_for_rec_trunc.clone.0+0x44/0x1f0 [ocfs2]
[233096.157310]  [<ffffffffa069f768>] ocfs2_remove_btree_range+0x458/0x7f0 [ocfs2]
[233096.161099]  [<ffffffffa0696777>] ? __ocfs2_find_path+0x187/0x2d0 [ocfs2]
[233096.164612]  [<ffffffffa06a2673>] ocfs2_commit_truncate+0x1b3/0x6f0 [ocfs2]
[233096.168204]  [<ffffffffa0744ac0>] ? ocfs2_xattr_tree_et_ops+0x60/0xfffffffffffe8c20 [ocfs2]
[233096.172539]  [<ffffffffa06d1a00>] ? ocfs2_journal_access_eb+0x20/0x20 [ocfs2]
[233096.176285]  [<ffffffff81202303>] ? __sb_end_write+0x33/0x70
[233096.179226]  [<ffffffffa06ca61d>] ocfs2_truncate_for_delete+0xbd/0x380 [ocfs2]
[233096.183009]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.186738]  [<ffffffffa06caf76>] ocfs2_wipe_inode+0x136/0x6a0 [ocfs2]
[233096.190165]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.193846]  [<ffffffffa06cb782>] ocfs2_delete_inode+0x2a2/0x3e0 [ocfs2]
[233096.197274]  [<ffffffff812298c9>] ? __inode_wait_for_writeback+0x69/0xc0
[233096.200736]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.205146]  [<ffffffffa06cc298>] ocfs2_evict_inode+0x28/0x60 [ocfs2]
[233096.208462]  [<ffffffff8121b81b>] evict+0xab/0x1a0
[233096.211020]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.215396]  [<ffffffff8121ba06>] iput_final+0xf6/0x190
[233096.218169]  [<ffffffff8121bb68>] iput+0xc8/0xe0
[233096.220586]  [<ffffffff8120f9b7>] do_unlinkat+0x1b7/0x310
[233096.223487]  [<ffffffff8106ae5b>] ? __do_page_fault+0x18b/0x480
[233096.226655]  [<ffffffff81126dbc>] ? __audit_syscall_entry+0xac/0x110
[233096.230009]  [<ffffffff810236cc>] ? do_audit_syscall_entry+0x6c/0x70
[233096.233346]  [<ffffffff81023823>] ? syscall_trace_enter_phase1+0x153/0x180
[233096.237103]  [<ffffffff8120fb26>] SyS_unlink+0x16/0x20
[233096.239800]  [<ffffffff816c122e>] system_call_fastpath+0x12/0x71
[233096.244346] ---[ end trace 28aa7410e69369cf ]---
[233096.247798] JBD2: unlink wants too many credits (251 > 128)
Signed-off-by Junxiao Bi <[email protected]>
---
 fs/ocfs2/alloc.c |   29 ++++++++++-------------------
 1 file changed, 10 insertions(+), 19 deletions(-)
fs/ocfs2/alloc.c +1 -1
index 7dabbc31060e..51128789a661 100644
@@ -5922,7 +5922,6 @@ bail:
 }
 
 static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
-					 handle_t *handle,
 					 struct inode *data_alloc_inode,
 					 struct buffer_head *data_alloc_bh)
 {

@@ -5935,11 +5934,19 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 	struct ocfs2_truncate_log *tl;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;
+	handle_t *handle;
 
 	di = (struct ocfs2_dinode *) tl_bh->b_data;
 	tl = &di->id2.i_dealloc;
 	i = le16_to_cpu(tl->tl_used) - 1;

fs/ocfs2/alloc.c static int ocfs2_replay_truncate_records(struct ocfs2_super *osb, · line 5951

Quoted 10 lines
fs/ocfs2/alloc.c +7 -0
 	while (i >= 0) {
+		handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
+		if (IS_ERR(handle)) {
+			status = PTR_ERR(handle);
+			mlog_errno(status);
+			goto bail;
+		}
+
 		/* Caller has given us at least enough credits to
 		 * update the truncate log dinode */

So we do not need this comment any more, am I right? Anyway it looks good to me.

Reviewed-by Joseph Qi <[email protected]>
Quoted 47 lines
fs/ocfs2/alloc.c +2 -18
 		status = ocfs2_journal_access_di(handle, INODE_CACHE(tl_inode), tl_bh,

@@ -5974,12 +5981,7 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 			}
 		}
 
-		status = ocfs2_extend_trans(handle,
-				OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-		if (status < 0) {
-			mlog_errno(status);
-			goto bail;
-		}
+		ocfs2_commit_trans(osb, handle);
 		i--;
 	}
 

@@ -5994,7 +5996,6 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 {
 	int status;
 	unsigned int num_to_flush;
-	handle_t *handle;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct inode *data_alloc_inode = NULL;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;

@@ -6038,21 +6039,11 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 		goto out_mutex;
 	}
 
-	handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-	if (IS_ERR(handle)) {
-		status = PTR_ERR(handle);
-		mlog_errno(status);
-		goto out_unlock;
-	}
-
-	status = ocfs2_replay_truncate_records(osb, handle, data_alloc_inode,
+	status = ocfs2_replay_truncate_records(osb, data_alloc_inode,
 					       data_alloc_bh);
 	if (status < 0)
 		mlog_errno(status);
 
-	ocfs2_commit_trans(osb, handle);
-
-out_unlock:
 	brelse(data_alloc_bh);
 	ocfs2_inode_unlock(data_alloc_inode, 1);
author
#4 lore raw

PATCH 1/2 ocfs2: fix trans extend while flush truncate log

Quoted 85 lines · Joseph Qi

Hi Junxiao,

Quoted 82 lines · Junxiao Bi

Every time, ocfs2_extend_trans() included a credit for truncate log inode, but as that inode had been managed by jbd2 running transaction first time, it will not consume that credit until jbd2_journal_restart(). Since total credits to extend always included the un-consumed ones, there will be more and more un-consumed credit, at last jbd2_journal_restart() will fail due to credit number over the half of max transction credit.

The following error was caught when unlink a large file with many extents.

[233096.013936] ------------[ cut here ]------------
[233096.018586] WARNING: CPU: 0 PID: 13626 at fs/jbd2/transaction.c:269 start_this_handle+0x4c3/0x510 [jbd2]()
[233096.028335] Modules linked in: ocfs2 nfsd lockd grace nfs_acl auth_rpcgss sunrpc autofs4 ocfs2_dlmfs ocfs2_stack_o2cb ocfs2_dlm ocfs2_nodemanager ocfs2_stackglue configfs sd_mod sg ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i cxgb4 cxgb3i libcxgbi cxgb3 mdio ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr ipv6 iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi ppdev xen_kbdfront xen_netfront fb_sys_fops sysimgblt sysfillrect syscopyarea parport_pc parport pcspkr i2c_piix4 i2c_core acpi_cpufreq ext4 jbd2 mbcache xen_blkfront floppy pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod
[233096.081751] CPU: 0 PID: 13626 Comm: unlink Tainted: G        W       4.1.12-37.6.3.el6uek.x86_64 #2
[233096.088556] Hardware name: Xen HVM domU, BIOS 4.4.4OVM 02/11/2016
[233096.093125]  000000000000010d ffff88000018b768 ffffffff816bc5bc 000000000000010d
[233096.099082]  0000000000000000 ffff88000018b7a8 ffffffff81081475 ffff88000018b788
[233096.105038]  ffff88007a99a000 ffff88007b573390 00000000000000fb 0000000000000050
[233096.110540] Call Trace:
[233096.111893]  [<ffffffff816bc5bc>] dump_stack+0x48/0x5c
[233096.114637]  [<ffffffff81081475>] warn_slowpath_common+0x95/0xe0
[233096.117797]  [<ffffffff810814da>] warn_slowpath_null+0x1a/0x20
[233096.120984]  [<ffffffffa0080993>] start_this_handle+0x4c3/0x510 [jbd2]
[233096.124505]  [<ffffffffa0088f95>] ? __jbd2_log_start_commit+0xe5/0xf0 [jbd2]
[233096.128115]  [<ffffffff810c4eb3>] ? __wake_up+0x53/0x70
[233096.130924]  [<ffffffffa0080b41>] jbd2__journal_restart+0x161/0x1b0 [jbd2]
[233096.134523]  [<ffffffffa0080ba3>] jbd2_journal_restart+0x13/0x20 [jbd2]
[233096.137986]  [<ffffffffa06d1d94>] ocfs2_extend_trans+0x74/0x220 [ocfs2]
[233096.141407]  [<ffffffffa06d156a>] ? ocfs2_journal_dirty+0x3a/0x90 [ocfs2]
[233096.144921]  [<ffffffffa0692943>] ocfs2_replay_truncate_records+0x93/0x360 [ocfs2]
[233096.148819]  [<ffffffffa0697ace>] __ocfs2_flush_truncate_log+0x13e/0x3a0 [ocfs2]
[233096.152644]  [<ffffffffa0697304>] ? ocfs2_reserve_blocks_for_rec_trunc.clone.0+0x44/0x1f0 [ocfs2]
[233096.157310]  [<ffffffffa069f768>] ocfs2_remove_btree_range+0x458/0x7f0 [ocfs2]
[233096.161099]  [<ffffffffa0696777>] ? __ocfs2_find_path+0x187/0x2d0 [ocfs2]
[233096.164612]  [<ffffffffa06a2673>] ocfs2_commit_truncate+0x1b3/0x6f0 [ocfs2]
[233096.168204]  [<ffffffffa0744ac0>] ? ocfs2_xattr_tree_et_ops+0x60/0xfffffffffffe8c20 [ocfs2]
[233096.172539]  [<ffffffffa06d1a00>] ? ocfs2_journal_access_eb+0x20/0x20 [ocfs2]
[233096.176285]  [<ffffffff81202303>] ? __sb_end_write+0x33/0x70
[233096.179226]  [<ffffffffa06ca61d>] ocfs2_truncate_for_delete+0xbd/0x380 [ocfs2]
[233096.183009]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.186738]  [<ffffffffa06caf76>] ocfs2_wipe_inode+0x136/0x6a0 [ocfs2]
[233096.190165]  [<ffffffffa06ca294>] ? ocfs2_query_inode_wipe+0xf4/0x320 [ocfs2]
[233096.193846]  [<ffffffffa06cb782>] ocfs2_delete_inode+0x2a2/0x3e0 [ocfs2]
[233096.197274]  [<ffffffff812298c9>] ? __inode_wait_for_writeback+0x69/0xc0
[233096.200736]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.205146]  [<ffffffffa06cc298>] ocfs2_evict_inode+0x28/0x60 [ocfs2]
[233096.208462]  [<ffffffff8121b81b>] evict+0xab/0x1a0
[233096.211020]  [<ffffffffa0732180>] ? __PRETTY_FUNCTION__.112282+0x20/0xffffffffffffb520 [ocfs2]
[233096.215396]  [<ffffffff8121ba06>] iput_final+0xf6/0x190
[233096.218169]  [<ffffffff8121bb68>] iput+0xc8/0xe0
[233096.220586]  [<ffffffff8120f9b7>] do_unlinkat+0x1b7/0x310
[233096.223487]  [<ffffffff8106ae5b>] ? __do_page_fault+0x18b/0x480
[233096.226655]  [<ffffffff81126dbc>] ? __audit_syscall_entry+0xac/0x110
[233096.230009]  [<ffffffff810236cc>] ? do_audit_syscall_entry+0x6c/0x70
[233096.233346]  [<ffffffff81023823>] ? syscall_trace_enter_phase1+0x153/0x180
[233096.237103]  [<ffffffff8120fb26>] SyS_unlink+0x16/0x20
[233096.239800]  [<ffffffff816c122e>] system_call_fastpath+0x12/0x71
[233096.244346] ---[ end trace 28aa7410e69369cf ]---
[233096.247798] JBD2: unlink wants too many credits (251 > 128)
Signed-off-by Junxiao Bi <[email protected]>
---
 fs/ocfs2/alloc.c |   29 ++++++++++-------------------
 1 file changed, 10 insertions(+), 19 deletions(-)
fs/ocfs2/alloc.c +1 -1
index 7dabbc31060e..51128789a661 100644
@@ -5922,7 +5922,6 @@ bail:
 }
 
 static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
-					 handle_t *handle,
 					 struct inode *data_alloc_inode,
 					 struct buffer_head *data_alloc_bh)
 {

@@ -5935,11 +5934,19 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 	struct ocfs2_truncate_log *tl;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;
+	handle_t *handle;
Quoted 14 lines

fs/ocfs2/alloc.c static int ocfs2_replay_truncate_records(struct ocfs2_super *osb, · line 5951

Quoted 13 lines
fs/ocfs2/alloc.c +7 -0
 	di = (struct ocfs2_dinode *) tl_bh->b_data;
 	tl = &di->id2.i_dealloc;
 	i = le16_to_cpu(tl->tl_used) - 1;
 	while (i >= 0) {
+		handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
+		if (IS_ERR(handle)) {
+			status = PTR_ERR(handle);
+			mlog_errno(status);
+			goto bail;
+		}
+
 		/* Caller has given us at least enough credits to
 		 * update the truncate log dinode */

So we do not need this comment any more, am I right?

Yes, that comment can be dropped.

Thanks,
Junxiao.

Quoted 53 lines

Anyway it looks good to me.

Reviewed-by Joseph Qi <[email protected]>
Quoted 47 lines
fs/ocfs2/alloc.c +2 -18
 		status = ocfs2_journal_access_di(handle, INODE_CACHE(tl_inode), tl_bh,

@@ -5974,12 +5981,7 @@ static int ocfs2_replay_truncate_records(struct ocfs2_super *osb,
 			}
 		}
 
-		status = ocfs2_extend_trans(handle,
-				OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-		if (status < 0) {
-			mlog_errno(status);
-			goto bail;
-		}
+		ocfs2_commit_trans(osb, handle);
 		i--;
 	}
 

@@ -5994,7 +5996,6 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 {
 	int status;
 	unsigned int num_to_flush;
-	handle_t *handle;
 	struct inode *tl_inode = osb->osb_tl_inode;
 	struct inode *data_alloc_inode = NULL;
 	struct buffer_head *tl_bh = osb->osb_tl_bh;

@@ -6038,21 +6039,11 @@ int __ocfs2_flush_truncate_log(struct ocfs2_super *osb)
 		goto out_mutex;
 	}
 
-	handle = ocfs2_start_trans(osb, OCFS2_TRUNCATE_LOG_FLUSH_ONE_REC);
-	if (IS_ERR(handle)) {
-		status = PTR_ERR(handle);
-		mlog_errno(status);
-		goto out_unlock;
-	}
-
-	status = ocfs2_replay_truncate_records(osb, handle, data_alloc_inode,
+	status = ocfs2_replay_truncate_records(osb, data_alloc_inode,
 					       data_alloc_bh);
 	if (status < 0)
 		mlog_errno(status);
 
-	ocfs2_commit_trans(osb, handle);
-
-out_unlock:
 	brelse(data_alloc_bh);
 	ocfs2_inode_unlock(data_alloc_inode, 1);