Re: [PATCH] generic/391: check inode metadata on f{data}sync after power-cut

[Eryu Guan <eguan@redhat.com>]

On Thu, Nov 17, 2016 at 07:56:58AM -0500, Brian Foster wrote:
> On Thu, Nov 17, 2016 at 04:35:27PM +0800, Eryu Guan wrote:
> > [cc'ed linux-xfs for inputs on a flush log issue]
> > 
> > On Wed, Nov 16, 2016 at 07:27:53PM -0800, Jaegeuk Kim wrote:
> > > This patch adds tests/generic/391 to test fsync and fdatasync with power-cuts.
> > > 
> > > The rule to check is:
> > > 1) fsync should guarantee all the inode metadata after power-cut,
> > > 2) fdatasync should guarantee i_size and i_blocks at least after power-cut.
> > > 
> > > Suggested-by: Chao Yu <yuchao0@huawei.com>
> > > Signed-off-by: Jaegeuk Kim <jaegeuk@kernel.org>
> > > ---
> > >  tests/generic/391     | 125 ++++++++++++++++++++++++++++++++++++++++++++++++++
> > >  tests/generic/391.out |  11 +++++
> > >  tests/generic/group   |   1 +
> > >  3 files changed, 137 insertions(+)
> > >  create mode 100644 tests/generic/391
> > >  create mode 100644 tests/generic/391.out
> > > 
> > > diff --git a/tests/generic/391 b/tests/generic/391
> > > new file mode 100644
> > > index 0000000..17c3fd3
> > > --- /dev/null
> > > +++ b/tests/generic/391
> > > @@ -0,0 +1,125 @@
> > > +#! /bin/bash
> > > +# FS QA Test 391
> > > +#
> > > +# Test inode's metadata after fsync or fdatasync calls.
> > > +# In the case of fsync, filesystem should recover all the inode metadata, while
> > > +# recovering i_blocks and i_size at least for fdatasync.
> > > +#
> > > +#-----------------------------------------------------------------------
> > > +# Copyright (c) 2016 Jaegeuk Kim.  All Rights Reserved.
> > > +#
> > > +# This program is free software; you can redistribute it and/or
> > > +# modify it under the terms of the GNU General Public License as
> > > +# published by the Free Software Foundation.
> > > +#
> > > +# This program is distributed in the hope that it would be useful,
> > > +# but WITHOUT ANY WARRANTY; without even the implied warranty of
> > > +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
> > > +# GNU General Public License for more details.
> > > +#
> > > +# You should have received a copy of the GNU General Public License
> > > +# along with this program; if not, write the Free Software Foundation,
> > > +# Inc.,  51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
> > > +#-----------------------------------------------------------------------
> > > +#
> > > +
> > > +seq=`basename $0`
> > > +seqres=$RESULT_DIR/$seq
> > > +echo "QA output created by $seq"
> > > +
> > > +here=`pwd`
> > > +tmp=/tmp/$$
> > > +status=1	# failure is the default!
> > > +trap "rm -f $tmp.*; exit \$status" 0 1 2 3 15
> > 
> > Better to follow the template and other tests on how to do cleanup, i.e.
> > trap _cleanup on exit and do real cleanups in it. e.g.
> > 
> > trap "_cleanup; exit \$status" 0 1 2 3 15
> > 
> > _cleanup()
> > {
> > 	cd /
> > 	rm -f $tmp.*
> > }
> > 
> > Not a big deal, but it's better to maintain consistency :)
> > 
> > > +
> > > +# get standard environment, filters and checks
> > > +. ./common/rc
> > > +. ./common/filter
> > > +. ./common/punch
> > > +
> > > +# real QA test starts here
> > > +_supported_fs generic
> > > +_supported_os Linux
> > > +
> > > +rm -f $seqres.full
> > > +_require_scratch
> > > +_require_scratch_shutdown
> > > +_require_xfs_io_command "fpunch"
> > > +
> > > +_scratch_mkfs >/dev/null 2>&1
> > > +_scratch_mount
> > > +
> > > +testfile=$SCRATCH_MNT/testfile
> > > +
> > > +# check inode metadata after shutdown
> > > +_check_inode_metadata()
> > 
> > No need to name local functions with the leading "_", that's for global
> > helper functions.
> > 
> > > +{
> > > +	src/godown $SCRATCH_MNT >> $seqres.full
> > > +	$XFS_IO_PROG -r -c "stat -v" $1 >$tmp.before
> > 
> > Shouldn't we call godown *after* xfs_io -c stat? I saw EIO on this
> > xfs_io command and all sub-tests reported stat diff.
> > 
> 
> Yeah.. I haven't run the test, but I would expect pretty much anything
> to return an error after an fs shutdown.
> 
> > And perhaps we need to flush the log on godown for XFS? i.e.
> > 
> > src/godown -f $SCRATCH_MNT >> $seqres.full
> > 
> 
> I don't think this is necessary. The semantics of fsync() dictate that
> the fs do what is necessary to make the file persistent on disk. This
> means it is the fs responsibility to ensure the changes are logged on
> disk. Indeed, xfs_file_fsync() calls _xfs_log_force_lsn() to flush the
> log up to the most recent LSN that covered the inode in question.
> 
> > Otherwise XFS fails all the "1024" & fsync tests (after I fixed the
> > godown & xfs_io order locally), fdatasync tests are fine.
> > 
> > @@ -1,8 +1,16 @@
> >  QA output created by 391
> >  ==== i_size 1024 test with fsync ====
> > +6c6
> > +< stat.blocks = 8200
> > +---
> > +> stat.blocks = 16256
> >  ==== i_size 4096 test with fsync ====
> >  ==== i_time test with fsync ====
> >  ==== fpunch 1024 test with fsync ====
> > +6c6
> > +< stat.blocks = 8208
> > +---
> > +> stat.blocks = 24576
> >  ==== fpunch 4096 test with fsync ====
> > 
> > Not sure if this is the expected behavior on XFS. cc'ed xfs list for
> > some inputs.
> > 
> 
> Am I reading this correctly that you're seeing more blocks than
> expected? If so, preallocation perhaps?

Yes, you're correct, I see more blocks after godown than before godown.

I tried adding "-o allocsize=4k" to MOUNT_OPTIONS, it works but not
always. e.g. on a host with sunit/swidth reported from underlying block
device, test still fails.

# xfs_info /mnt/xfs
meta-data=/dev/mapper/systemvg-testlv2 isize=512    agcount=16, agsize=245696 blks
         =                       sectsz=512   attr=2, projid32bit=1
         =                       crc=1        finobt=1 spinodes=0 rmapbt=0
         =                       reflink=0
data     =                       bsize=4096   blocks=3931136, imaxpct=25
         =                       sunit=64     swidth=192 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal               bsize=4096   blocks=2560, version=2
         =                       sectsz=512   sunit=64 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

Part of the test diff:
 ==== i_size 1024 test with fsync ====
+6c6
+< stat.blocks = 8200
+---
+> stat.blocks = 8704

On the other hand, adding "-f" to godown always works for me.

Thanks,
Eryu

> 
> Brian
> 
> > > +	_scratch_cycle_mount
> > > +	$XFS_IO_PROG -r -c "stat -v" $1 >$tmp.after
> > > +	diff $tmp.before $tmp.after >>$tmp.diff
> > 
> > I think $tmp.diff should be overwritten on each sub-test.
> > 
> > > +
> > > +	if [ "$2" = "fdatasync" ]; then
> > > +		cat $tmp.diff | grep stat.size
> > > +		cat $tmp.diff | grep stat.blocks
> > > +	else
> > > +		cat $tmp.diff
> > > +	fi
> > > +	cat $tmp.before >> $seqres.full
> > > +	cat $tmp.after >> $seqres.full
> > > +}
> > > +
> > > +# append XX KB with f{data}sync, followed by power-cut
> > > +_test_i_size()
> > > +{
> > > +	echo "==== i_size $2 test with $1 ===="
> > 
> > I find it's much easier to read the $seqres.full log if we append these
> > kind of logs to $seqres.full too, e.g.
> > 
> > 	echo "==== i_size $2 test with $1 ====" | tee -a $seqres.full
> > 
> > Thanks,
> > Eryu
> > 
> > > +	$XFS_IO_PROG -f -c "pwrite 0 4M"	\
> > > +			-c "fsync"		\
> > > +			-c "pwrite 4M $2"	\
> > > +			-c "$1"			\
> > > +			$testfile >/dev/null
> > > +	_check_inode_metadata $testfile $1
> > > +}
> > > +
> > > +# update times with f{data}sync, followed by power-cut
> > > +_test_i_time()
> > > +{
> > > +	echo "==== i_time test with $1 ===="
> > > +	$XFS_IO_PROG -f -c "pwrite 0 4M"	\
> > > +			-c "fsync"		\
> > > +			$testfile >/dev/null
> > > +	sleep 1
> > > +	touch $testfile
> > > +	$XFS_IO_PROG -c "$1"			\
> > > +			$testfile >/dev/null
> > > +	_check_inode_metadata $testfile $1
> > > +}
> > > +
> > > +# punch XX KB with f{data}sync, followed by power-cut
> > > +_test_punch()
> > > +{
> > > +	echo "==== fpunch $2 test with $1 ===="
> > > +	$XFS_IO_PROG -f -c "pwrite 0 4202496"	\
> > > +			-c "fsync"		\
> > > +			-c "fpunch 4194304 $2"\
> > > +			-c "$1"			\
> > > +			$testfile >/dev/null
> > > +
> > > +	_check_inode_metadata $testfile $1
> > > +}
> > > +
> > > +for i in fsync fdatasync
> > > +do
> > > +	_test_i_size $i 1024
> > > +	_test_i_size $i 4096
> > > +	_test_i_time $i
> > > +	_test_punch $i 1024
> > > +	_test_punch $i 4096
> > > +done
> > > +
> > > +rm -f $tmp.*
> > > +
> > > +# success, all done
> > > +status=0
> > > +exit
> > > diff --git a/tests/generic/391.out b/tests/generic/391.out
> > > new file mode 100644
> > > index 0000000..7c66776
> > > --- /dev/null
> > > +++ b/tests/generic/391.out
> > > @@ -0,0 +1,11 @@
> > > +QA output created by 391
> > > +==== i_size 1024 test with fsync ====
> > > +==== i_size 4096 test with fsync ====
> > > +==== i_time test with fsync ====
> > > +==== fpunch 1024 test with fsync ====
> > > +==== fpunch 4096 test with fsync ====
> > > +==== i_size 1024 test with fdatasync ====
> > > +==== i_size 4096 test with fdatasync ====
> > > +==== i_time test with fdatasync ====
> > > +==== fpunch 1024 test with fdatasync ====
> > > +==== fpunch 4096 test with fdatasync ====
> > > diff --git a/tests/generic/group b/tests/generic/group
> > > index 08007d7..9de3415 100644
> > > --- a/tests/generic/group
> > > +++ b/tests/generic/group
> > > @@ -392,3 +392,4 @@
> > >  387 auto clone
> > >  388 auto log metadata
> > >  389 auto quick acl
> > > +391 auto quick metadata
> > > -- 
> > > 2.8.3
> > > 
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe fstests" 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 fstests" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html