Hi Dave, On Fri, 28 Aug 2015, Dave Chinner wrote: > > From: Dave Chinner <dchinner@xxxxxxxxxx> > > Sage Weil reported that a ceph test workload was writing to the > log on every fdatasync during an overwrite workload. Event tracing > showed that the only metadata modification being made was the > timestamp updates during the write(2) syscall, but fdatasync(2) > is supposed to ignore them. The key observation was that the > transactions in the log all looked like this: > > INODE: #regs: 4 ino: 0x8b flags: 0x45 dsize: 32 > > And contained a flags field of 0x45 or 0x85, and had data and > attribute forks following the inode core. This means that the > timestamp updates were triggering dirty relogging of previously > logged parts of the inode that hadn't yet been flushed back to > disk. > > This is caused by xfs_trans_log_inode(), where it folds the dirty > fields that have previously been logged back into the current > transaction dirty fields from the inode item ili_last_fields. The > issue is that ili_last_fields only contains a non-zero value when > the inode is in the process of being flushed. The typical state > progression is this, using a core field update as the modification > occuring: > > state ili_fields ili_last_fields > clean 0 0 > modified, logged XFS_ILOG_CORE 0 > flushed to buffer 0 XFS_ILOG_CORE > <buffer submitted> > buffer IO done (clean) 0 0 > > However, if we run a new transaction after it has been flushed to > buffer but before the buffer IO is done, we don't know if the > modifications in the inode buffer (i.e. what is in ili_last_fields) > will reach the disk before the new transaction reaches the log. > Hence to keep transactional ordering correct in recovery, we need to > ensure the new transaction re-logs the modifications that are being > flushed to disk. > > By relogging, we ensure that if the transaction makes it to disk and > the buffer doesn't, then recovery replays all the changes upto that > point correctly. If the transaction does not make it disk, but the > buffer does, then recovery will see that the inode on disk is more > recent than in the log and won't overwrite it with changes that it > already contains. > > The upshot of this is that while the inode buffer sits in memory > with the inode in the "flushed" state, fdatasync is going to see > the relogged state in the ili_fields. i.e: > > What is happening here is this: > > state ili_fields ili_last_fields > clean 0 0 > modified, logged CORE 0 > flushed to buffer 0 CORE > <write> > timestamp update TIMESTAMP CORE > <xfs_trans_inode_log pulls in ili_last_fields> > CORE|TIMESTAMP CORE > <fdatasync> > sees field other than TIMESTAMP in ili_fields, > triggers xfs_log_force_lsn to flush inode > > <buffer submittted> > buffer IO done (clean) CORE|TIMESTAMP 0 > ..... > <write> > timestamp update CORE|TIMESTAMP 0 > <fdatasync> > sees field other than TIMESTAMP in ili_fields, > triggers xfs_log_force_lsn to flush inode > ..... > <write> > timestamp update CORE|TIMESTAMP 0 > <fdatasync> > sees field other than TIMESTAMP in ili_fields, > triggers xfs_log_force_lsn to flush inode > > So, essentially, once a race condition on the buffer flush has > occurred, the condition is not cleared until the inode is flushed to > the buffer again and it is written without racing against the inode > being dirtied again. > > The behaviour we really want here is to capture the timestamp > update transactionally, but not trigger fdatasync because of the > relogged fields that haven't been modified since the inode was > flushed to the buffer. We still need to relog them, but we don't > need to force the log in the fdatasync case. > > To do this, don't fold the ili_last_fields value into ili_fields > when logging the inode. Instead, fold it into the fields that get > logged during formatting of the inode item. This means that we will > stop logging those fields the moment we know that there is a more > recent version of the inode on disk than we have in the log and so > we don't need to log those fields anymore as the next transaction on > disk doesn't need to replay them. > > Doing this separates changes that are in memory but are not being > flushed from those that have been flushed. Hence we can now look at > ili_fields and hence see what fields have been modified since the > last flush, and hence whether fdatasync needs to force the log or > not. If non-timestamp changes have been made since the inode was > flushed to the backing buffer, then fdatasync will do exactly the > right thing (i.e. force the log). > > Reported-by: Sage Weil <sage@xxxxxxxxxx> > Signed-off-by: Dave Chinner <dchinner@xxxxxxxxxx> > --- > Version 2: > - include the hunk from fs/xfs/xfs_trans_inode.c that I missed > when committing the patch locally the first time. I gave this a go on my machine but I'm still seeing the same symptom. I've gathered the trace, strace, and other useful bits at http://newdream.net/~sage/drop/rocksdb.2/ This is pretty easy to reproduce with the ceph_test_keyvaluedb binary (built on fedora 22), also in that dir: rm -rf kv_test_temp_dir/ ./ceph_test_keyvaluedb --gtest_filter=KeyValueDB/KVTest.BenchCommit/1 Thanks for looking into this! sage > > fs/xfs/xfs_inode_item.c | 161 +++++++++++++++++++++++++++++++++-------------- > fs/xfs/xfs_inode_item.h | 1 + > fs/xfs/xfs_trans_inode.c | 8 --- > 3 files changed, 115 insertions(+), 55 deletions(-) > > diff --git a/fs/xfs/xfs_inode_item.c b/fs/xfs/xfs_inode_item.c > index 62bd80f..be04eb2 100644 > --- a/fs/xfs/xfs_inode_item.c > +++ b/fs/xfs/xfs_inode_item.c > @@ -29,6 +29,63 @@ > #include "xfs_trans_priv.h" > #include "xfs_log.h" > > +/* > + * Notes on ili_fields, ili_format_fields and ili_last_fields. > + * > + * ili_fields contains the flags that reflect the current changes that are in > + * memory and have been logged, but have not been flushed to the backing buffer > + * for writeback yet. When a transaction is done, the fields that are modified > + * are added to ili_fields and all those fields are logged. This results in > + * repeated transactions correctly relogging all the other changes in memory and > + * allows the inode to be re-ordered (moved forward) in the AIL safely. > + * ili_fields is copied to ili_last_fields when the inode is flushed to the > + * backing buffer and is then cleared, indicating that the inode in memory is > + * now clean from a transactional change point of view and does not need to > + * relog those fields anymore on tranaction commit. > + * > + * ili_last_fields, therefore, is only set while there is an unresolved inode > + * flush being done (i.e. flush lock is held). We need to keep this state > + * available to avoid a transaction recovery vs inode buffer IO completion race > + * if we crash. If the inode is logged again makes it to disk before the inode > + * buffer IO complete, log recovery will replay the latest inode transaction and > + * can lose the changes that were in the inode buffer. Hence we still need to > + * log the changes that have been flushed so that transactions issued during the > + * inode buffer write still contain the modifications being flushed. Once the > + * inode buffer IO completes, we no longer need to log those changes as the > + * inode on disk the same as the inode in memory apart from the changes made > + * since the inode was flushed (i.e. those recorded in ili_fields). > + * > + * ili_format_fields is only used during transaction commit. It is the > + * aggregation of ili_fields and ili_last_fields, as sampled during the sizing > + * of the inode item to be logged. We need this field definition to be constant > + * between sizing and formatting, but inode buffer IO can complete > + * asynchronously with transaction commit and so we must only read it once so > + * that the different stages of the item formatting work correctly. We don't > + * care about the async completion clearing ili_last_fields after we've sampled > + * it - if we log too much then so be it - we won't log it next time. Once we've > + * formatted the inode item, we need to propagate the ili_format_fields value to > + * the on-disk inode log item format field, and then use it to clear all the > + * fields that we marked for logging but were not dirty from ili_fields. > + * > + * This separation of changes allows us to accurately determine what fields in > + * the inode have changed since it was last flushed to disk. This is important > + * for fdatasync() performance as there are certain fields that, if modified, > + * should not trigger log forces because they contain metadata that fdatasync() > + * does not need to guarantee is safe on disk. This is, currently, just > + * XFS_ILOG_TIMESTAMP, though may be extended in future to cover other metadata. > + * > + * If we simply fold ili_last_fields back into ili_fields when we log the inode > + * in a transaction, then if we have a flush/modification race it results in > + * every timestamp update causing fdatasync to flush the log because ili_fields > + * has fields other than XFS_ILOG_TIMESTAMP set in it. This behaviour will > + * persist until the inode is next flushed to it's backing buffer and that > + * buffer is written and completed without another flush/modification race > + * occuring. Hence we keep the change state separate and only combine them when > + * formatting the inode into the log. > + * > + * For more information, there's another big comment in xfs_iflush_int() about > + * this flush/modification race condition. > + */ > > kmem_zone_t *xfs_ili_zone; /* inode log item zone */ > > @@ -40,6 +97,7 @@ static inline struct xfs_inode_log_item *INODE_ITEM(struct xfs_log_item *lip) > STATIC void > xfs_inode_item_data_fork_size( > struct xfs_inode_log_item *iip, > + unsigned int fields, > int *nvecs, > int *nbytes) > { > @@ -47,7 +105,7 @@ xfs_inode_item_data_fork_size( > > switch (ip->i_d.di_format) { > case XFS_DINODE_FMT_EXTENTS: > - if ((iip->ili_fields & XFS_ILOG_DEXT) && > + if ((fields & XFS_ILOG_DEXT) && > ip->i_d.di_nextents > 0 && > ip->i_df.if_bytes > 0) { > /* worst case, doesn't subtract delalloc extents */ > @@ -56,14 +114,14 @@ xfs_inode_item_data_fork_size( > } > break; > case XFS_DINODE_FMT_BTREE: > - if ((iip->ili_fields & XFS_ILOG_DBROOT) && > + if ((fields & XFS_ILOG_DBROOT) && > ip->i_df.if_broot_bytes > 0) { > *nbytes += ip->i_df.if_broot_bytes; > *nvecs += 1; > } > break; > case XFS_DINODE_FMT_LOCAL: > - if ((iip->ili_fields & XFS_ILOG_DDATA) && > + if ((fields & XFS_ILOG_DDATA) && > ip->i_df.if_bytes > 0) { > *nbytes += roundup(ip->i_df.if_bytes, 4); > *nvecs += 1; > @@ -82,6 +140,7 @@ xfs_inode_item_data_fork_size( > STATIC void > xfs_inode_item_attr_fork_size( > struct xfs_inode_log_item *iip, > + unsigned int fields, > int *nvecs, > int *nbytes) > { > @@ -89,7 +148,7 @@ xfs_inode_item_attr_fork_size( > > switch (ip->i_d.di_aformat) { > case XFS_DINODE_FMT_EXTENTS: > - if ((iip->ili_fields & XFS_ILOG_AEXT) && > + if ((fields & XFS_ILOG_AEXT) && > ip->i_d.di_anextents > 0 && > ip->i_afp->if_bytes > 0) { > /* worst case, doesn't subtract unused space */ > @@ -98,14 +157,14 @@ xfs_inode_item_attr_fork_size( > } > break; > case XFS_DINODE_FMT_BTREE: > - if ((iip->ili_fields & XFS_ILOG_ABROOT) && > + if ((fields & XFS_ILOG_ABROOT) && > ip->i_afp->if_broot_bytes > 0) { > *nbytes += ip->i_afp->if_broot_bytes; > *nvecs += 1; > } > break; > case XFS_DINODE_FMT_LOCAL: > - if ((iip->ili_fields & XFS_ILOG_ADATA) && > + if ((fields & XFS_ILOG_ADATA) && > ip->i_afp->if_bytes > 0) { > *nbytes += roundup(ip->i_afp->if_bytes, 4); > *nvecs += 1; > @@ -133,13 +192,17 @@ xfs_inode_item_size( > struct xfs_inode_log_item *iip = INODE_ITEM(lip); > struct xfs_inode *ip = iip->ili_inode; > > + iip->ili_format_fields = iip->ili_fields | iip->ili_last_fields; > + > *nvecs += 2; > *nbytes += sizeof(struct xfs_inode_log_format) + > xfs_icdinode_size(ip->i_d.di_version); > > - xfs_inode_item_data_fork_size(iip, nvecs, nbytes); > + xfs_inode_item_data_fork_size(iip, iip->ili_format_fields, > + nvecs, nbytes); > if (XFS_IFORK_Q(ip)) > - xfs_inode_item_attr_fork_size(iip, nvecs, nbytes); > + xfs_inode_item_attr_fork_size(iip, iip->ili_format_fields, > + nvecs, nbytes); > } > > STATIC void > @@ -151,14 +214,14 @@ xfs_inode_item_format_data_fork( > { > struct xfs_inode *ip = iip->ili_inode; > size_t data_bytes; > + unsigned int fields = iip->ili_format_fields; > > switch (ip->i_d.di_format) { > case XFS_DINODE_FMT_EXTENTS: > - iip->ili_fields &= > - ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > - XFS_ILOG_DEV | XFS_ILOG_UUID); > + fields &= ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > + XFS_ILOG_DEV | XFS_ILOG_UUID); > > - if ((iip->ili_fields & XFS_ILOG_DEXT) && > + if ((fields & XFS_ILOG_DEXT) && > ip->i_d.di_nextents > 0 && > ip->i_df.if_bytes > 0) { > struct xfs_bmbt_rec *p; > @@ -175,15 +238,14 @@ xfs_inode_item_format_data_fork( > ilf->ilf_dsize = data_bytes; > ilf->ilf_size++; > } else { > - iip->ili_fields &= ~XFS_ILOG_DEXT; > + fields &= ~XFS_ILOG_DEXT; > } > break; > case XFS_DINODE_FMT_BTREE: > - iip->ili_fields &= > - ~(XFS_ILOG_DDATA | XFS_ILOG_DEXT | > - XFS_ILOG_DEV | XFS_ILOG_UUID); > + fields &= ~(XFS_ILOG_DDATA | XFS_ILOG_DEXT | > + XFS_ILOG_DEV | XFS_ILOG_UUID); > > - if ((iip->ili_fields & XFS_ILOG_DBROOT) && > + if ((fields & XFS_ILOG_DBROOT) && > ip->i_df.if_broot_bytes > 0) { > ASSERT(ip->i_df.if_broot != NULL); > xlog_copy_iovec(lv, vecp, XLOG_REG_TYPE_IBROOT, > @@ -192,16 +254,15 @@ xfs_inode_item_format_data_fork( > ilf->ilf_dsize = ip->i_df.if_broot_bytes; > ilf->ilf_size++; > } else { > - ASSERT(!(iip->ili_fields & > - XFS_ILOG_DBROOT)); > - iip->ili_fields &= ~XFS_ILOG_DBROOT; > + ASSERT(!(fields & XFS_ILOG_DBROOT)); > + fields &= ~XFS_ILOG_DBROOT; > } > break; > case XFS_DINODE_FMT_LOCAL: > - iip->ili_fields &= > - ~(XFS_ILOG_DEXT | XFS_ILOG_DBROOT | > - XFS_ILOG_DEV | XFS_ILOG_UUID); > - if ((iip->ili_fields & XFS_ILOG_DDATA) && > + fields &= ~(XFS_ILOG_DEXT | XFS_ILOG_DBROOT | > + XFS_ILOG_DEV | XFS_ILOG_UUID); > + > + if ((fields & XFS_ILOG_DDATA) && > ip->i_df.if_bytes > 0) { > /* > * Round i_bytes up to a word boundary. > @@ -218,27 +279,28 @@ xfs_inode_item_format_data_fork( > ilf->ilf_dsize = (unsigned)data_bytes; > ilf->ilf_size++; > } else { > - iip->ili_fields &= ~XFS_ILOG_DDATA; > + fields &= ~XFS_ILOG_DDATA; > } > break; > case XFS_DINODE_FMT_DEV: > - iip->ili_fields &= > - ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > - XFS_ILOG_DEXT | XFS_ILOG_UUID); > - if (iip->ili_fields & XFS_ILOG_DEV) > + fields &= ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > + XFS_ILOG_DEXT | XFS_ILOG_UUID); > + if (fields & XFS_ILOG_DEV) > ilf->ilf_u.ilfu_rdev = ip->i_df.if_u2.if_rdev; > break; > case XFS_DINODE_FMT_UUID: > - iip->ili_fields &= > - ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > - XFS_ILOG_DEXT | XFS_ILOG_DEV); > - if (iip->ili_fields & XFS_ILOG_UUID) > + fields &= ~(XFS_ILOG_DDATA | XFS_ILOG_DBROOT | > + XFS_ILOG_DEXT | XFS_ILOG_DEV); > + if (fields & XFS_ILOG_UUID) > ilf->ilf_u.ilfu_uuid = ip->i_df.if_u2.if_uuid; > break; > default: > ASSERT(0); > break; > } > + > + /* reflect the logged fields back in ili_format_fields */ > + iip->ili_format_fields = fields; > } > > STATIC void > @@ -250,13 +312,13 @@ xfs_inode_item_format_attr_fork( > { > struct xfs_inode *ip = iip->ili_inode; > size_t data_bytes; > + unsigned int fields = iip->ili_format_fields; > > switch (ip->i_d.di_aformat) { > case XFS_DINODE_FMT_EXTENTS: > - iip->ili_fields &= > - ~(XFS_ILOG_ADATA | XFS_ILOG_ABROOT); > + fields &= ~(XFS_ILOG_ADATA | XFS_ILOG_ABROOT); > > - if ((iip->ili_fields & XFS_ILOG_AEXT) && > + if ((fields & XFS_ILOG_AEXT) && > ip->i_d.di_anextents > 0 && > ip->i_afp->if_bytes > 0) { > struct xfs_bmbt_rec *p; > @@ -272,14 +334,13 @@ xfs_inode_item_format_attr_fork( > ilf->ilf_asize = data_bytes; > ilf->ilf_size++; > } else { > - iip->ili_fields &= ~XFS_ILOG_AEXT; > + fields &= ~XFS_ILOG_AEXT; > } > break; > case XFS_DINODE_FMT_BTREE: > - iip->ili_fields &= > - ~(XFS_ILOG_ADATA | XFS_ILOG_AEXT); > + fields &= ~(XFS_ILOG_ADATA | XFS_ILOG_AEXT); > > - if ((iip->ili_fields & XFS_ILOG_ABROOT) && > + if ((fields & XFS_ILOG_ABROOT) && > ip->i_afp->if_broot_bytes > 0) { > ASSERT(ip->i_afp->if_broot != NULL); > > @@ -289,14 +350,13 @@ xfs_inode_item_format_attr_fork( > ilf->ilf_asize = ip->i_afp->if_broot_bytes; > ilf->ilf_size++; > } else { > - iip->ili_fields &= ~XFS_ILOG_ABROOT; > + fields &= ~XFS_ILOG_ABROOT; > } > break; > case XFS_DINODE_FMT_LOCAL: > - iip->ili_fields &= > - ~(XFS_ILOG_AEXT | XFS_ILOG_ABROOT); > + fields &= ~(XFS_ILOG_AEXT | XFS_ILOG_ABROOT); > > - if ((iip->ili_fields & XFS_ILOG_ADATA) && > + if ((fields & XFS_ILOG_ADATA) && > ip->i_afp->if_bytes > 0) { > /* > * Round i_bytes up to a word boundary. > @@ -313,13 +373,16 @@ xfs_inode_item_format_attr_fork( > ilf->ilf_asize = (unsigned)data_bytes; > ilf->ilf_size++; > } else { > - iip->ili_fields &= ~XFS_ILOG_ADATA; > + fields &= ~XFS_ILOG_ADATA; > } > break; > default: > ASSERT(0); > break; > } > + > + /* reflect the logged fields back in ili_format_fields */ > + iip->ili_format_fields = fields; > } > > /* > @@ -359,12 +422,16 @@ xfs_inode_item_format( > if (XFS_IFORK_Q(ip)) { > xfs_inode_item_format_attr_fork(iip, ilf, lv, &vecp); > } else { > - iip->ili_fields &= > + iip->ili_format_fields &= > ~(XFS_ILOG_ADATA | XFS_ILOG_ABROOT | XFS_ILOG_AEXT); > } > > /* update the format with the exact fields we actually logged */ > - ilf->ilf_fields |= (iip->ili_fields & ~XFS_ILOG_TIMESTAMP); > + ilf->ilf_fields |= (iip->ili_format_fields & ~XFS_ILOG_TIMESTAMP); > + > + /* clear any fields we didn't log from ili_fields */ > + iip->ili_fields &= iip->ili_format_fields; > + iip->ili_format_fields = 0; > } > > /* > diff --git a/fs/xfs/xfs_inode_item.h b/fs/xfs/xfs_inode_item.h > index 488d812..43a9e1c 100644 > --- a/fs/xfs/xfs_inode_item.h > +++ b/fs/xfs/xfs_inode_item.h > @@ -34,6 +34,7 @@ typedef struct xfs_inode_log_item { > unsigned short ili_logged; /* flushed logged data */ > unsigned int ili_last_fields; /* fields when flushed */ > unsigned int ili_fields; /* fields to be logged */ > + unsigned int ili_format_fields; /* combined log fields */ > } xfs_inode_log_item_t; > > static inline int xfs_inode_clean(xfs_inode_t *ip) > diff --git a/fs/xfs/xfs_trans_inode.c b/fs/xfs/xfs_trans_inode.c > index 17280cd..77f1e8a 100644 > --- a/fs/xfs/xfs_trans_inode.c > +++ b/fs/xfs/xfs_trans_inode.c > @@ -123,13 +123,5 @@ xfs_trans_log_inode( > tp->t_flags |= XFS_TRANS_DIRTY; > ip->i_itemp->ili_item.li_desc->lid_flags |= XFS_LID_DIRTY; > > - /* > - * Always OR in the bits from the ili_last_fields field. > - * This is to coordinate with the xfs_iflush() and xfs_iflush_done() > - * routines in the eventual clearing of the ili_fields bits. > - * See the big comment in xfs_iflush() for an explanation of > - * this coordination mechanism. > - */ > - flags |= ip->i_itemp->ili_last_fields; > ip->i_itemp->ili_fields |= flags; > } > > _______________________________________________ xfs mailing list xfs@xxxxxxxxxxx http://oss.sgi.com/mailman/listinfo/xfs
