Re: [PATCH] xfs: free uncommitted transactions during log recovery

[Brian Foster <bfoster@redhat.com>]

On Thu, Jun 15, 2017 at 10:07:57AM -0700, Darrick J. Wong wrote:
> On Fri, Jun 09, 2017 at 01:38:09PM -0400, Brian Foster wrote:
> > Log recovery allocates in-core transaction and member item data
> > structures on-demand as it processes the on-disk log. Transactions
> > are allocated on first encounter on-disk and stored in a hash table
> > structure where they are easily accessible for subsequent lookups.
> > Transaction items are also allocated on demand and are attached to
> > the associated transactions.
> > 
> > When a commit record is encountered in the log, the transaction is
> > committed to the fs and the in-core structures are freed. If a
> > filesystem crashes or shuts down before all in-core log buffers are
> > flushed to the log, however, not all transactions may have commit
> > records in the log. As expected, the modifications in such an
> > incomplete transaction are not replayed to the fs. The in-core data
> > structures for the partial transaction are never freed, however,
> > resulting in a memory leak.
> > 
> > Update xlog_do_recovery_pass() to walk the hash table of transaction
> > lists as the last step before it goes out of scope and free any
> > transactions that may remain on the lists. This prevents a memory
> > leak of partial transactions in the log.
> > 
> > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > ---
> > 
> > FYI, I suspect this has been a problem for a while and and rare/harmless
> > enough that this can target 4.13.
> > 
> > Brian
> > 
> >  fs/xfs/xfs_log_recover.c | 14 ++++++++++++++
> >  1 file changed, 14 insertions(+)
> > 
> > diff --git a/fs/xfs/xfs_log_recover.c b/fs/xfs/xfs_log_recover.c
> > index 4a98762..37b34c5 100644
> > --- a/fs/xfs/xfs_log_recover.c
> > +++ b/fs/xfs/xfs_log_recover.c
> > @@ -5224,6 +5224,7 @@ xlog_do_recovery_pass(
> >  	int			error2 = 0;
> >  	int			bblks, split_bblks;
> >  	int			hblks, split_hblks, wrapped_hblks;
> > +	int			i;
> >  	struct hlist_head	rhash[XLOG_RHASH_SIZE];
> >  	LIST_HEAD		(buffer_list);
> >  
> > @@ -5466,6 +5467,19 @@ xlog_do_recovery_pass(
> >  	if (error && first_bad)
> >  		*first_bad = rhead_blk;
> >  
> > +	/*
> > +	 * Transactions are freed at commit time but transactions without commit
> > +	 * records on disk are never committed. Free any that may be left in the
> > +	 * hash table.
> > +	 */
> > +	for (i = 0; i < XLOG_RHASH_SIZE; i++) {
> > +		struct hlist_node	*tmp;
> > +		struct xlog_recover	*trans;
> > +
> > +		hlist_for_each_entry_safe(trans, tmp, &rhash[i], r_list)
> > +			xlog_recover_free_trans(trans);
> > +	}
> 
> Hmm, I just got the following crash in xfs/051:
> 
> [  131.456722] XFS (dm-0): Mounting V5 Filesystem
> [  131.462826] XFS (dm-0): Delaying log recovery for 10 seconds.
> [  141.532271] XFS (dm-0): Starting recovery (logdev: internal)
> [  141.534418] XFS (dm-0): metadata I/O error: block 0x182e70 ("xlog_bread_noalign") error 5 numblks 8
> [  141.539561] general protection fault: 0000 [#1] PREEMPT SMP

Ugh, not sure how I missed that. Must have disabled debug mode or
something. Anyways, I can reproduce and I'll look into it. Thanks for
catching this.

Brian

> [  141.542236] Dumping ftrace buffer:
> [  141.542972]    (ftrace buffer empty)
> [  141.543083] Modules linked in: xfs dm_flakey libcrc32c dax_pmem device_dax nd_pmem binfmt_misc nfsd auth_rpcgss sch_fq_codel af_packet [last unloaded: xfs]
> [  141.543083] CPU: 1 PID: 3246 Comm: mount Not tainted 4.12.0-rc5-dgc #1
> [  141.543083] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> [  141.543083] task: ffff88006e0ca900 task.stack: ffffc90001d70000
> [  141.543083] RIP: 0010:xlog_recover_free_trans+0x1d/0xb0 [xfs]
> [  141.543083] RSP: 0018:ffffc90001d73b30 EFLAGS: 00010286
> [  141.543083] RAX: ffffc90001d73bc0 RBX: 00000000fffffffb RCX: ffffc90001d73bc0
> [  141.543083] RDX: 0000000000000000 RSI: 00000000ffffffff RDI: ffff8800756ae800
> [  141.543083] RBP: ffffc90001d73b58 R08: 0000000000000001 R09: 0000000000000000
> [  141.543083] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8800756ae830
> [  141.543083] R13: ffff8800756ae800 R14: ffffc90001d73bd0 R15: 206b636f6c62203a
> [  141.543083] FS:  00007fe28e0d6840(0000) GS:ffff88007f200000(0000) knlGS:0000000000000000
> [  141.543083] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [  141.543083] CR2: 00007fe28d6a0cf9 CR3: 000000007b3de000 CR4: 00000000001406e0
> [  141.543083] Call Trace:
> [  141.543083]  xlog_do_recovery_pass+0x3ec/0x740 [xfs]
> [  141.543083]  ? rcu_read_lock_sched_held+0x72/0x80
> [  141.543083]  ? __kmalloc+0x26c/0x2d0
> [  141.543083]  ? kmem_alloc+0x81/0x100 [xfs]
> [  141.543083]  ? kmem_alloc+0x81/0x100 [xfs]
> [  141.543083]  xlog_do_log_recovery+0x70/0x150 [xfs]
> [  141.543083]  xlog_do_recover+0x1b/0x170 [xfs]
> [  141.543083]  xlog_recover+0xa2/0x130 [xfs]
> [  141.543083]  xfs_log_mount+0xdb/0x2e0 [xfs]
> [  141.543083]  xfs_mountfs+0x579/0xad0 [xfs]
> [  141.543083]  xfs_fs_fill_super+0x483/0x610 [xfs]
> [  141.543083]  mount_bdev+0x180/0x1b0
> [  141.543083]  ? xfs_finish_flags+0x150/0x150 [xfs]
> [  141.543083]  xfs_fs_mount+0x15/0x20 [xfs]
> [  141.543083]  mount_fs+0x14/0x80
> [  141.543083]  vfs_kern_mount+0x67/0x150
> [  141.543083]  do_mount+0x195/0xd10
> [  141.543083]  ? _copy_from_user+0x47/0x80
> [  141.543083]  ? memdup_user+0x60/0x90
> [  141.543083]  SyS_mount+0x95/0xe0
> [  141.543083]  entry_SYSCALL_64_fastpath+0x1f/0xbe
> [  141.543083] RIP: 0033:0x7fe28d9b7faa
> [  141.543083] RSP: 002b:00007ffe9168f628 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5
> [  141.543083] RAX: ffffffffffffffda RBX: 00007fe28dcb063a RCX: 00007fe28d9b7faa
> [  141.543083] RDX: 0000000001ab2240 RSI: 0000000001ab2280 RDI: 0000000001ab2260
> [  141.543083] RBP: 0000000001ab2120 R08: 0000000000000000 R09: 0000000000000012
> [  141.543083] R10: 00000000c0ed0000 R11: 0000000000000206 R12: 00007fe28dec083c
> [  141.543083] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000003
> [  141.543083] Code: 5d c3 31 c0 c3 66 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 4c 8d 67 30 53 4c 8b 7f 30 49 89 fd <49> 8b 1f 4d 39 e7 48 89 d8 74 6f 49 8b 57 08 45 31 f6 48 89 50 
> [  141.543083] RIP: xlog_recover_free_trans+0x1d/0xb0 [xfs] RSP: ffffc90001d73b30
> [  141.591289] ---[ end trace b3d5b2775a86318f ]---
> 
> FWIW I was testing 4.13 for-next with the following xfstest config:
> 
> FSTYP         -- xfs (debug)
> PLATFORM      -- Linux/x86_64 birch-mtr0 4.12.0-rc5-dgc
> MKFS_OPTIONS  -- -f -m reflink=1,rmapbt=1, -i sparse=1, /dev/pmem1
> MOUNT_OPTIONS -- /dev/pmem1 /opt
> 
> --D
> 
> > +
> >  	return error ? error : error2;
> >  }
> >  
> > -- 
> > 2.7.5
> > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html