Re: [PATCH v2] xfs: rewrite the fdatasync optimization

[Dave Chinner <david@fromorbit.com>]

On Mon, Feb 26, 2018 at 09:55:04AM -0500, Brian Foster wrote:
> On Thu, Feb 22, 2018 at 07:04:21AM -0800, Christoph Hellwig wrote:
> > Currently we need to the ilock over the log force in xfs_fsync so that we
> > can protect ili_fsync_fields against incorrect manipulation.
> > Unfortunately that can cause huge latency spikes for workloads that mix
> > fsync with writes from other thread or through aio on the same file.
> > 
> > Instead record the last dirty lsn that was not just a timestamp update in
> > the inode log item as long as the inode is pinned, and clear it when
> > unpinning the inode.  This removes the need for ili_fsync_fields and thus
> > holding the ilock over the log force, and drastically reduces latency on
> > multithreaded workloads that mix writes with fsync calls on the same file.
> > 
> > Signed-off-by: Christoph Hellwig <hch@lst.de>
> > ---
> > 
> > Changes since V1:
> >  - reomve the XFS_ILOG_VERSION optimization
> > 
> >  fs/xfs/xfs_file.c        | 20 ++++++--------------
> >  fs/xfs/xfs_inode.c       |  2 --
> >  fs/xfs/xfs_inode_item.c  | 10 ++++++++--
> >  fs/xfs/xfs_inode_item.h  |  2 +-
> >  fs/xfs/xfs_iomap.c       |  3 +--
> >  fs/xfs/xfs_trans_inode.c |  9 ---------
> >  6 files changed, 16 insertions(+), 30 deletions(-)
> > 
> > diff --git a/fs/xfs/xfs_file.c b/fs/xfs/xfs_file.c
> > index 9ea08326f876..ccb331f96a6d 100644
> > --- a/fs/xfs/xfs_file.c
> > +++ b/fs/xfs/xfs_file.c
> > @@ -165,27 +165,19 @@ xfs_file_fsync(
> >  	 * All metadata updates are logged, which means that we just have to
> >  	 * flush the log up to the latest LSN that touched the inode. If we have
> >  	 * concurrent fsync/fdatasync() calls, we need them to all block on the
> > -	 * log force before we clear the ili_fsync_fields field. This ensures
> > -	 * that we don't get a racing sync operation that does not wait for the
> > -	 * metadata to hit the journal before returning. If we race with
> > -	 * clearing the ili_fsync_fields, then all that will happen is the log
> > -	 * force will do nothing as the lsn will already be on disk. We can't
> > -	 * race with setting ili_fsync_fields because that is done under
> > -	 * XFS_ILOCK_EXCL, and that can't happen because we hold the lock shared
> > -	 * until after the ili_fsync_fields is cleared.
> > +	 * log force before returning.
> >  	 */
> >  	xfs_ilock(ip, XFS_ILOCK_SHARED);
> >  	if (xfs_ipincount(ip)) {
> > -		if (!datasync ||
> > -		    (ip->i_itemp->ili_fsync_fields & ~XFS_ILOG_TIMESTAMP))
> > +		if (datasync)
> > +			lsn = ip->i_itemp->ili_datasync_lsn;
> > +		else
> >  			lsn = ip->i_itemp->ili_last_lsn;
> >  	}
> > +	xfs_iunlock(ip, XFS_ILOCK_SHARED);
> >  
> > -	if (lsn) {
> > +	if (lsn)
> >  		error = _xfs_log_force_lsn(mp, lsn, XFS_LOG_SYNC, &log_flushed);
> > -		ip->i_itemp->ili_fsync_fields = 0;
> > -	}
> > -	xfs_iunlock(ip, XFS_ILOCK_SHARED);
> >  
> >  	/*
> >  	 * If we only have a single device, and the log force about was
> > diff --git a/fs/xfs/xfs_inode.c b/fs/xfs/xfs_inode.c
> > index 604ee384a00a..a57772553a2a 100644
> > --- a/fs/xfs/xfs_inode.c
> > +++ b/fs/xfs/xfs_inode.c
> > @@ -2385,7 +2385,6 @@ xfs_ifree_cluster(
> >  
> >  			iip->ili_last_fields = iip->ili_fields;
> >  			iip->ili_fields = 0;
> > -			iip->ili_fsync_fields = 0;
> >  			iip->ili_logged = 1;
> >  			xfs_trans_ail_copy_lsn(mp->m_ail, &iip->ili_flush_lsn,
> >  						&iip->ili_item.li_lsn);
> > @@ -3649,7 +3648,6 @@ xfs_iflush_int(
> >  	 */
> >  	iip->ili_last_fields = iip->ili_fields;
> >  	iip->ili_fields = 0;
> > -	iip->ili_fsync_fields = 0;
> >  	iip->ili_logged = 1;
> >  
> >  	xfs_trans_ail_copy_lsn(mp->m_ail, &iip->ili_flush_lsn,
> > diff --git a/fs/xfs/xfs_inode_item.c b/fs/xfs/xfs_inode_item.c
> > index d5037f060d6f..b60592e82833 100644
> > --- a/fs/xfs/xfs_inode_item.c
> > +++ b/fs/xfs/xfs_inode_item.c
> > @@ -630,6 +630,9 @@ xfs_inode_item_committed(
> >  	struct xfs_inode_log_item *iip = INODE_ITEM(lip);
> >  	struct xfs_inode	*ip = iip->ili_inode;
> >  
> > +	iip->ili_last_lsn = 0;
> > +	iip->ili_datasync_lsn = 0;
> > +
> 
> Hmm, it's not clear to me why we're messing with ili_last_lsn here as
> well since I don't see any mention of it anywhere. That aside, I'm not
> quite sure this is safe even with regard to ->ili_datasync_lsn.

Actually, it's not safe with regard to iip->ili_last_lsn, either:

[ 6158.067488] run fstests generic/476 at 2018-03-05 16:26:36
[ 6159.036562] XFS (sdg): Mounting V5 Filesystem
[ 6159.074800] XFS (sdg): Ending clean mount
[ 6370.748497] kworker/dying (24679) used greatest stack depth: 11168 bytes left
[ 6527.664801] XFS: Assertion failed: lsn != 0, file: fs/xfs/xfs_log.c, line: 3458
[ 6527.667593] ------------[ cut here ]------------
[ 6527.669286] kernel BUG at fs/xfs/xfs_message.c:114!
[ 6527.670253] invalid opcode: 0000 [#1] PREEMPT SMP
[ 6527.673091] CPU: 2 PID: 697 Comm: kswapd0 Not tainted 4.16.0-rc2-dgc #383
[ 6527.675120] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 6527.677410] RIP: 0010:assfail+0x28/0x30
[ 6527.678402] RSP: 0018:ffffc900016b7a88 EFLAGS: 00010202
[ 6527.679852] RAX: 00000000ffffffea RBX: 0000000000000000 RCX: 0000000000000000
[ 6527.681579] RDX: 00000000ffffffc0 RSI: 000000000000000a RDI: ffffffff82271753
[ 6527.683235] RBP: ffff8801276e1400 R08: 0000000000000000 R09: 0000000000000000
[ 6527.684467] R10: ffff8800ba50f028 R11: f000000000000000 R12: ffff880121420000
[ 6527.685549] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000002079f51
[ 6527.686604] FS:  0000000000000000(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
[ 6527.687896] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 6527.688739] CR2: 00007f5ac5bbb000 CR3: 000000013a3e4000 CR4: 00000000000006e0
[ 6527.689759] Call Trace:
[ 6527.690141]  _xfs_log_force_lsn+0x323/0x340
[ 6527.690758]  ? xfs_reclaim_inode+0x71/0x400
[ 6527.691365]  __xfs_iunpin_wait+0xa4/0x170
[ 6527.691981]  ? woken_wake_function+0x10/0x10
[ 6527.692602]  xfs_reclaim_inode+0x71/0x400
[ 6527.693271]  xfs_reclaim_inodes_ag+0x1a5/0x2e0
[ 6527.693904]  xfs_reclaim_inodes_nr+0x31/0x40
[ 6527.694515]  super_cache_scan+0x14d/0x1a0
[ 6527.695086]  shrink_slab.part.66+0x171/0x370
[ 6527.695739]  shrink_node+0x7e/0x1a0
[ 6527.696238]  kswapd+0x270/0x6b0
[ 6527.696723]  ? node_reclaim+0x220/0x220
[ 6527.697271]  kthread+0x111/0x130
[ 6527.697737]  ? __kthread_create_worker+0x120/0x120
[ 6527.698421]  ? call_usermodehelper_exec_async+0x11c/0x150
[ 6527.699196]  ret_from_fork+0x24/0x30
[ 6527.699741] Code: 0b c3 90 0f 1f 44 00 00 48 89 f1 41 89 d0 48 c7 c6 d0 64 2d 82 48 89 fa 31 ff e8 84 fa ff ff 80 3d d1 e3 0d 01 00 75 03 0f 0b c3 <0f> 0b 66 0f 1f 44 00 00 0f 1f 44 00 00 4
[ 6527.702441] RIP: assfail+0x28/0x30 RSP: ffffc900016b7a88
[ 6527.704099] ---[ end trace bbf263c1abbd8799 ]---

On log checkpoint completion, there is a big window between
->iop_committed and ->iop_unpin calls where we are in the state
i_pincount > 0 and ili_last_lsn = zero.

If anything calls xfs_iunpin()/xfs_iunpin_wait() in this window,
then we run this:

	xfs_log_force_lsn(ip->i_mount, ip->i_itemp->ili_last_lsn, 0);

Which then fires the above assert because the force lsn is zero.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com