[RFC] xfs: remedy small writes during wrapped-log recovery

[Michael L. Semon]

On 01/09/15 15:02, Michael L. Semon wrote:
> A bisect still needs to be done to determine when the slow mount 
> behavior started.  It could very well be that somebody fixed the 
> buffer_io_error messages that I saw long ago, and the solution made 
> some mounts here rather miserable.

OK, I looked at this part.  bisect was unhelpful, so I checked out 
kernel 2.6.32.65 from -stable.  Lo and behold, the issue was there, 
too.  This means that Brian and Dave are right, that my hardware 
is slow and contended.  I'll add that the hardware gets worse with 
time and testing.  Something could still be made better here.

The test case I use is to copy xfsprogs source to $SCRATCH_MNT 
and do mount/touch/umount cycles, allowing the log to become 
wrapped and then unwrapped.  Run it through at least two cycles 
so you see that the new-FS case and repaired-FS case have 
different timings on v5 XFS.

Write caches are off for tests here.  The way hard drive write cache 
is shut off here is to have "/sbin/hdparm -W 0 /dev/sda" at the top 
of the first boot script.  It provides extra integrity during udev-
related catastrophes on boot, but slow mounts are made more obvious 
this way.

This test script should hopefully work (current cruft trimmed down 
while writing this E-mail):

#!/bin/sh
xfsprogs_src="/usr/src/xfs/xfsprogs"

umount $SCRATCH_DEV
mkfs.xfs -f -m crc=1,finobt=1 $SCRATCH_DEV
mount $SCRATCH_DEV $SCRATCH_MNT
echo -n "Files copied... "
cp -av $xfsprogs_src $SCRATCH_MNT/ | wc -l
sync
umount $SCRATCH_MNT
b=0

while true; do
        b=$((b+1))
        for a in `seq 1 75`; do
                echo "Loop $b, Pass $a:"
                time mount $SCRATCH_DEV $SCRATCH_MNT
                find $SCRATCH_MNT/xfsprogs -type f -exec touch {} \;
                sync
                umount $SCRATCH_MNT
                sync
		# Uncomment this to correlate wrapped logs with 
		# errors from xfs_logprint:
                # xfs_logprint $SCRATCH_DEV | grep "^xfs_logprint"
        done
        xfs_repair -v $SCRATCH_DEV
done

Really, though, the best way to spot this is to add a line of 
printk() to xlog_bwrite() and see how many times it is called on 
each mount.  In my opinion, it should be called not many times 
more for a wrapped-log mount than for a normal-log mount.

Thanks!

Michael