[PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Brian Foster]

Create a debug mode only sysfs option to force pin the tail of the
log. This option can be used by test infrastructure to induce head
behind tail conditions. Specifically, this is intended to be used by
xfstests to reproduce log recovery problems after failed/corrupted
log writes overwrite the last good tail LSN in the log.

When enabled, AIL push attempts see every log item on the AIL in the
pinned state. This stalls metadata writeback and thus prevents the
current tail of the log from moving forward. When disabled,
subsequent AIL pushes observe the log items in their appropriate
state and filesystem operation continues as normal.

Signed-off-by: Brian Foster <bfoster@redhat.com>
---

Hi all,

This patch is a supporting patch for an xfstests test I'm about to post
that pins the tail of the log in order to reproduce the log recovery
problem that appears to be the root of the problem in this[1] thread.
That is the primary motivation for the patch and so should probably be
reviewed with that context. IOW, if there's a better way to reproduce
the problem in the test without the need for kernel support, I'm happy
to drop this. Thoughts, reviews, flames appreciated.

Brian

[1] http://www.spinics.net/lists/linux-xfs/msg07499.html

 fs/xfs/xfs_log_priv.h  |  2 ++
 fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
 fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
 3 files changed, 67 insertions(+), 1 deletion(-)

diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
index c2604a5..bfbfde12 100644
--- a/fs/xfs/xfs_log_priv.h
+++ b/fs/xfs/xfs_log_priv.h
@@ -413,6 +413,8 @@ struct xlog {
 	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
 	/* log record crc error injection factor */
 	uint32_t		l_badcrc_factor;
+	/* force pin the log tail */
+	bool			l_pin_tail;
 #endif
 	/* log recovery lsn tracking (for buffer submission */
 	xfs_lsn_t		l_recovery_lsn;
diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
index ec6e0e2..b86148a 100644
--- a/fs/xfs/xfs_sysfs.c
+++ b/fs/xfs/xfs_sysfs.c
@@ -378,6 +378,51 @@ log_badcrc_factor_show(
 }
 
 XFS_SYSFS_ATTR_RW(log_badcrc_factor);
+
+/*
+ * DEBUG mode flag to force pin the tail of the log. Used from test
+ * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
+ * DIRECTLY. This will lock up the fs!
+ *
+ * When this option is enabled, all log items present in the AIL are emulated as
+ * being in the pinned state until the option is disabled. Once disabled, log
+ * items return to their natural state and fs operation continues as normal.
+ */
+STATIC ssize_t
+log_pin_tail_store(
+	struct kobject		*kobject,
+	const char		*buf,
+	size_t			count)
+{
+	struct xlog		*log = to_xlog(kobject);
+	int			ret;
+	int			val;
+
+	ret = kstrtoint(buf, 0, &val);
+	if (ret)
+		return ret;
+
+	if (val == 1)
+		log->l_pin_tail = true;
+	else if (val == 0)
+		log->l_pin_tail = false;
+	else
+		return -EINVAL;
+
+	return count;
+}
+
+STATIC ssize_t
+log_pin_tail_show(
+	struct kobject		*kobject,
+	char			*buf)
+{
+	struct xlog		*log = to_xlog(kobject);
+
+	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
+}
+XFS_SYSFS_ATTR_RW(log_pin_tail);
+
 #endif	/* DEBUG */
 
 static struct attribute *xfs_log_attrs[] = {
@@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
 	ATTR_LIST(write_grant_head),
 #ifdef DEBUG
 	ATTR_LIST(log_badcrc_factor),
+	ATTR_LIST(log_pin_tail),
 #endif
 	NULL,
 };
diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
index 9056c0f..c901e61 100644
--- a/fs/xfs/xfs_trans_ail.c
+++ b/fs/xfs/xfs_trans_ail.c
@@ -27,6 +27,7 @@
 #include "xfs_trace.h"
 #include "xfs_error.h"
 #include "xfs_log.h"
+#include "xfs_log_priv.h"
 
 #ifdef DEBUG
 /*
@@ -325,6 +326,23 @@ xfs_ail_delete(
 	xfs_trans_ail_cursor_clear(ailp, lip);
 }
 
+static inline uint
+xfsaild_push_item(
+	struct xfs_ail		*ailp,
+	struct xfs_log_item	*lip)
+{
+#ifdef DEBUG
+	/*
+	 * If tail pinning is enabled, skip the push and track all items as
+	 * pinned to force pin the log tail. This helps induce head-behind-tail
+	 * conditions.
+	 */
+	if (ailp->xa_mount->m_log->l_pin_tail)
+		return XFS_ITEM_PINNED;
+#endif
+	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
+}
+
 static long
 xfsaild_push(
 	struct xfs_ail		*ailp)
@@ -382,7 +400,7 @@ xfsaild_push(
 		 * rely on the AIL cursor implementation to be able to deal with
 		 * the dropped lock.
 		 */
-		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
+		lock_result = xfsaild_push_item(ailp, lip);
 		switch (lock_result) {
 		case XFS_ITEM_SUCCESS:
 			XFS_STATS_INC(mp, xs_push_ail_success);
-- 
2.7.5

[PATCH] tests/xfs: test for log recovery failure after tail overwrite

[Brian Foster]

XFS is susceptible to log recovery problems if the fs crashes under
certain circumstances. If the tail has been pinned for long enough
to the log to fill and the next batch of log buffer submissions
happen to fail, the filesystem shutsdown having potentially
overwritten part of the range between the last good tail->head range
in the log. This causes log recovery to fail with crc mismatch or
invalid log record errors.

This problem is not yet fixed and thus known/expected to fail. At
this time, this test serves as a reminder that the problem exists
and a reproducer for future verification purposes. Note that this
problem is currently only reproducible with larger (non-default) log
buffer sizes (i.e., '-o logbsize=256k') or smaller block sizes (1k).

Signed-off-by: Brian Foster <bfoster@redhat.com>
---

Hi all,

This patch uses the XFS debug kernel mechanism recently posted for
review[1] to reproduce an XFS log recovery problem. Note that this test
depends on the aforementioned patch and thus should not be merged
until/unless the corresponding kernel patch is merged.

Brian

[1] "xfs: debug mode sysfs flag to force [un]pin the log tail"

 tests/xfs/999     | 113 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 tests/xfs/999.out |   2 +
 tests/xfs/group   |   1 +
 3 files changed, 116 insertions(+)
 create mode 100644 tests/xfs/999
 create mode 100644 tests/xfs/999.out

diff --git a/tests/xfs/999 b/tests/xfs/999
new file mode 100644
index 0000000..6913a43
--- /dev/null
+++ b/tests/xfs/999
@@ -0,0 +1,113 @@
+#! /bin/bash
+# FS QA Test No. 999
+#
+# Attempt to reproduce log recovery failure by writing corrupt log records over
+# the last good tail in the log. The tail is force pinned while a workload runs
+# the head as close as possible behind the tail. Once the head is pinned,
+# corrupted log records are written to the log and the filesystem shuts down.
+#
+# While log recovery should handle the corrupted log records, it has historical
+# problems dealing with the situation where the corrupted log records may have
+# overwritten the tail of the previous good record in the log. If this occurs,
+# log recovery may fail.
+#
+# This can be reproduced more reliably under non-default conditions such as with
+# the smallest supported FSB sizes and/or largest supported log buffer sizes and
+# counts (logbufs and logbsize mount options).
+#
+# Note that this test requires a DEBUG mode kernel.
+#
+#-----------------------------------------------------------------------
+# Copyright (c) 2017 Red Hat, Inc. 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 "_cleanup; exit \$status" 0 1 2 3 15
+
+_cleanup()
+{
+	cd /
+	rm -f $tmp.*
+	$KILLALL_PROG -9 fsstress > /dev/null 2>&1
+	[ -e /sys/fs/xfs/$sdev/log/log_pin_tail ] &&
+		echo 0 > /sys/fs/xfs/$sdev/log/log_pin_tail
+	wait > /dev/null 2>&1
+}
+
+rm -f $seqres.full
+
+# get standard environment, filters and checks
+. ./common/rc
+
+# real QA test starts here
+
+# Modify as appropriate.
+_supported_fs xfs
+_supported_os Linux
+_require_xfs_sysfs $(_short_dev $TEST_DEV)/log/log_badcrc_factor
+_require_xfs_sysfs $(_short_dev $TEST_DEV)/log/log_pin_tail
+_require_scratch
+_require_command "$KILLALL_PROG" killall
+
+echo "Silence is golden."
+
+sdev=$(_short_dev $SCRATCH_DEV)
+
+_scratch_mkfs >> $seqres.full 2>&1 || _fail "mkfs failed"
+_scratch_mount || _fail "mount failed"
+
+# populate the fs with some data and cycle the mount to reset the log head/tail
+$FSSTRESS_PROG -d $SCRATCH_MNT -z -fcreat=1 -p 4 -n 100000 > /dev/null 2>&1
+_scratch_cycle_mount || _fail "mount failed"
+
+# Pin the tail and start a file removal workload. File removal tends to
+# reproduce the corruption more reliably.
+echo 1 > /sys/fs/xfs/$sdev/log/log_pin_tail
+
+rm -rf $SCRATCH_MNT/* > /dev/null 2>&1 &
+workpid=$!
+
+# wait for the head to stop pushing forward
+prevhead=-1
+head=`cat /sys/fs/xfs/$sdev/log/log_head_lsn`
+while [ "$head" != "$prevhead" ]; do
+	sleep 5
+	prevhead=$head
+	head=`cat /sys/fs/xfs/$sdev/log/log_head_lsn`
+done
+
+# Once the head is pinned behind the tail, enable log record corruption and
+# unpin the tail. All subsequent log buffer writes end up corrupted on-disk and
+# result in log I/O errors.
+echo 1 > /sys/fs/xfs/$sdev/log/log_badcrc_factor
+echo 0 > /sys/fs/xfs/$sdev/log/log_pin_tail
+
+# wait for fs shutdown to kill the workload
+wait $workpid
+
+# cycle mount to test log recovery
+_scratch_cycle_mount
+
+# success, all done
+status=0
+exit
diff --git a/tests/xfs/999.out b/tests/xfs/999.out
new file mode 100644
index 0000000..d254382
--- /dev/null
+++ b/tests/xfs/999.out
@@ -0,0 +1,2 @@
+QA output created by 999
+Silence is golden.
diff --git a/tests/xfs/group b/tests/xfs/group
index 792161a..d94f010 100644
--- a/tests/xfs/group
+++ b/tests/xfs/group
@@ -416,3 +416,4 @@
 416 dangerous_fuzzers dangerous_scrub dangerous_repair
 417 dangerous_fuzzers dangerous_scrub dangerous_online_repair
 418 dangerous_fuzzers dangerous_scrub dangerous_repair
+999 auto log
-- 
2.7.5

Re: [PATCH] tests/xfs: test for log recovery failure after tail overwrite

[Eryu Guan]

Hi Brian,

On Fri, Jun 16, 2017 at 12:46:19PM -0400, Brian Foster wrote:
> XFS is susceptible to log recovery problems if the fs crashes under
> certain circumstances. If the tail has been pinned for long enough
> to the log to fill and the next batch of log buffer submissions
> happen to fail, the filesystem shutsdown having potentially
> overwritten part of the range between the last good tail->head range
> in the log. This causes log recovery to fail with crc mismatch or
> invalid log record errors.
> 
> This problem is not yet fixed and thus known/expected to fail. At
> this time, this test serves as a reminder that the problem exists
> and a reproducer for future verification purposes. Note that this
> problem is currently only reproducible with larger (non-default) log
> buffer sizes (i.e., '-o logbsize=256k') or smaller block sizes (1k).
> 
> Signed-off-by: Brian Foster <bfoster@redhat.com>
> ---
> 
> Hi all,
> 
> This patch uses the XFS debug kernel mechanism recently posted for
> review[1] to reproduce an XFS log recovery problem. Note that this test
> depends on the aforementioned patch and thus should not be merged
> until/unless the corresponding kernel patch is merged.

Any decision made on the kernel side patch? Sorry, I'm a bit lost on the
kernel side discussions.

Thanks,
Eryu

Re: [PATCH] tests/xfs: test for log recovery failure after tail overwrite

[Darrick J. Wong]

On Fri, Jun 30, 2017 at 11:44:05AM +0800, Eryu Guan wrote:
> Hi Brian,
> 
> On Fri, Jun 16, 2017 at 12:46:19PM -0400, Brian Foster wrote:
> > XFS is susceptible to log recovery problems if the fs crashes under
> > certain circumstances. If the tail has been pinned for long enough
> > to the log to fill and the next batch of log buffer submissions
> > happen to fail, the filesystem shutsdown having potentially
> > overwritten part of the range between the last good tail->head range
> > in the log. This causes log recovery to fail with crc mismatch or
> > invalid log record errors.
> > 
> > This problem is not yet fixed and thus known/expected to fail. At
> > this time, this test serves as a reminder that the problem exists
> > and a reproducer for future verification purposes. Note that this
> > problem is currently only reproducible with larger (non-default) log
> > buffer sizes (i.e., '-o logbsize=256k') or smaller block sizes (1k).
> > 
> > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > ---
> > 
> > Hi all,
> > 
> > This patch uses the XFS debug kernel mechanism recently posted for
> > review[1] to reproduce an XFS log recovery problem. Note that this test
> > depends on the aforementioned patch and thus should not be merged
> > until/unless the corresponding kernel patch is merged.
> 
> Any decision made on the kernel side patch? Sorry, I'm a bit lost on the
> kernel side discussions.

Uhhhh, I think this test is being redone to work with the new xfs
errortag mechanism that'll be appearing soon.  I will send patches
to fix up xfstests momentarily.

--D

> 
> Thanks,
> Eryu
> --
> 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

Re: [PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Darrick J. Wong]

On Fri, Jun 16, 2017 at 12:44:33PM -0400, Brian Foster wrote:
> Create a debug mode only sysfs option to force pin the tail of the
> log. This option can be used by test infrastructure to induce head
> behind tail conditions. Specifically, this is intended to be used by
> xfstests to reproduce log recovery problems after failed/corrupted
> log writes overwrite the last good tail LSN in the log.
> 
> When enabled, AIL push attempts see every log item on the AIL in the
> pinned state. This stalls metadata writeback and thus prevents the
> current tail of the log from moving forward. When disabled,
> subsequent AIL pushes observe the log items in their appropriate
> state and filesystem operation continues as normal.
> 
> Signed-off-by: Brian Foster <bfoster@redhat.com>

Looks ok enough to test...
Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>

--D

> ---
> 
> Hi all,
> 
> This patch is a supporting patch for an xfstests test I'm about to post
> that pins the tail of the log in order to reproduce the log recovery
> problem that appears to be the root of the problem in this[1] thread.
> That is the primary motivation for the patch and so should probably be
> reviewed with that context. IOW, if there's a better way to reproduce
> the problem in the test without the need for kernel support, I'm happy
> to drop this. Thoughts, reviews, flames appreciated.
> 
> Brian
> 
> [1] http://www.spinics.net/lists/linux-xfs/msg07499.html
> 
>  fs/xfs/xfs_log_priv.h  |  2 ++
>  fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
>  fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
>  3 files changed, 67 insertions(+), 1 deletion(-)
> 
> diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> index c2604a5..bfbfde12 100644
> --- a/fs/xfs/xfs_log_priv.h
> +++ b/fs/xfs/xfs_log_priv.h
> @@ -413,6 +413,8 @@ struct xlog {
>  	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
>  	/* log record crc error injection factor */
>  	uint32_t		l_badcrc_factor;
> +	/* force pin the log tail */
> +	bool			l_pin_tail;
>  #endif
>  	/* log recovery lsn tracking (for buffer submission */
>  	xfs_lsn_t		l_recovery_lsn;
> diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
> index ec6e0e2..b86148a 100644
> --- a/fs/xfs/xfs_sysfs.c
> +++ b/fs/xfs/xfs_sysfs.c
> @@ -378,6 +378,51 @@ log_badcrc_factor_show(
>  }
>  
>  XFS_SYSFS_ATTR_RW(log_badcrc_factor);
> +
> +/*
> + * DEBUG mode flag to force pin the tail of the log. Used from test
> + * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
> + * DIRECTLY. This will lock up the fs!
> + *
> + * When this option is enabled, all log items present in the AIL are emulated as
> + * being in the pinned state until the option is disabled. Once disabled, log
> + * items return to their natural state and fs operation continues as normal.
> + */
> +STATIC ssize_t
> +log_pin_tail_store(
> +	struct kobject		*kobject,
> +	const char		*buf,
> +	size_t			count)
> +{
> +	struct xlog		*log = to_xlog(kobject);
> +	int			ret;
> +	int			val;
> +
> +	ret = kstrtoint(buf, 0, &val);
> +	if (ret)
> +		return ret;
> +
> +	if (val == 1)
> +		log->l_pin_tail = true;
> +	else if (val == 0)
> +		log->l_pin_tail = false;
> +	else
> +		return -EINVAL;
> +
> +	return count;
> +}
> +
> +STATIC ssize_t
> +log_pin_tail_show(
> +	struct kobject		*kobject,
> +	char			*buf)
> +{
> +	struct xlog		*log = to_xlog(kobject);
> +
> +	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
> +}
> +XFS_SYSFS_ATTR_RW(log_pin_tail);
> +
>  #endif	/* DEBUG */
>  
>  static struct attribute *xfs_log_attrs[] = {
> @@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
>  	ATTR_LIST(write_grant_head),
>  #ifdef DEBUG
>  	ATTR_LIST(log_badcrc_factor),
> +	ATTR_LIST(log_pin_tail),
>  #endif
>  	NULL,
>  };
> diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
> index 9056c0f..c901e61 100644
> --- a/fs/xfs/xfs_trans_ail.c
> +++ b/fs/xfs/xfs_trans_ail.c
> @@ -27,6 +27,7 @@
>  #include "xfs_trace.h"
>  #include "xfs_error.h"
>  #include "xfs_log.h"
> +#include "xfs_log_priv.h"
>  
>  #ifdef DEBUG
>  /*
> @@ -325,6 +326,23 @@ xfs_ail_delete(
>  	xfs_trans_ail_cursor_clear(ailp, lip);
>  }
>  
> +static inline uint
> +xfsaild_push_item(
> +	struct xfs_ail		*ailp,
> +	struct xfs_log_item	*lip)
> +{
> +#ifdef DEBUG
> +	/*
> +	 * If tail pinning is enabled, skip the push and track all items as
> +	 * pinned to force pin the log tail. This helps induce head-behind-tail
> +	 * conditions.
> +	 */
> +	if (ailp->xa_mount->m_log->l_pin_tail)
> +		return XFS_ITEM_PINNED;
> +#endif
> +	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> +}
> +
>  static long
>  xfsaild_push(
>  	struct xfs_ail		*ailp)
> @@ -382,7 +400,7 @@ xfsaild_push(
>  		 * rely on the AIL cursor implementation to be able to deal with
>  		 * the dropped lock.
>  		 */
> -		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> +		lock_result = xfsaild_push_item(ailp, lip);
>  		switch (lock_result) {
>  		case XFS_ITEM_SUCCESS:
>  			XFS_STATS_INC(mp, xs_push_ail_success);
> -- 
> 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

Re: [PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Brian Foster]

On Tue, Jun 20, 2017 at 02:48:32PM -0700, Darrick J. Wong wrote:
> On Fri, Jun 16, 2017 at 12:44:33PM -0400, Brian Foster wrote:
> > Create a debug mode only sysfs option to force pin the tail of the
> > log. This option can be used by test infrastructure to induce head
> > behind tail conditions. Specifically, this is intended to be used by
> > xfstests to reproduce log recovery problems after failed/corrupted
> > log writes overwrite the last good tail LSN in the log.
> > 
> > When enabled, AIL push attempts see every log item on the AIL in the
> > pinned state. This stalls metadata writeback and thus prevents the
> > current tail of the log from moving forward. When disabled,
> > subsequent AIL pushes observe the log items in their appropriate
> > state and filesystem operation continues as normal.
> > 
> > Signed-off-by: Brian Foster <bfoster@redhat.com>
> 
> Looks ok enough to test...
> Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
> 

I assume you mean Reviewed-by... thanks! :)

Brian

> --D
> 
> > ---
> > 
> > Hi all,
> > 
> > This patch is a supporting patch for an xfstests test I'm about to post
> > that pins the tail of the log in order to reproduce the log recovery
> > problem that appears to be the root of the problem in this[1] thread.
> > That is the primary motivation for the patch and so should probably be
> > reviewed with that context. IOW, if there's a better way to reproduce
> > the problem in the test without the need for kernel support, I'm happy
> > to drop this. Thoughts, reviews, flames appreciated.
> > 
> > Brian
> > 
> > [1] http://www.spinics.net/lists/linux-xfs/msg07499.html
> > 
> >  fs/xfs/xfs_log_priv.h  |  2 ++
> >  fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
> >  fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
> >  3 files changed, 67 insertions(+), 1 deletion(-)
> > 
> > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > index c2604a5..bfbfde12 100644
> > --- a/fs/xfs/xfs_log_priv.h
> > +++ b/fs/xfs/xfs_log_priv.h
> > @@ -413,6 +413,8 @@ struct xlog {
> >  	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
> >  	/* log record crc error injection factor */
> >  	uint32_t		l_badcrc_factor;
> > +	/* force pin the log tail */
> > +	bool			l_pin_tail;
> >  #endif
> >  	/* log recovery lsn tracking (for buffer submission */
> >  	xfs_lsn_t		l_recovery_lsn;
> > diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
> > index ec6e0e2..b86148a 100644
> > --- a/fs/xfs/xfs_sysfs.c
> > +++ b/fs/xfs/xfs_sysfs.c
> > @@ -378,6 +378,51 @@ log_badcrc_factor_show(
> >  }
> >  
> >  XFS_SYSFS_ATTR_RW(log_badcrc_factor);
> > +
> > +/*
> > + * DEBUG mode flag to force pin the tail of the log. Used from test
> > + * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
> > + * DIRECTLY. This will lock up the fs!
> > + *
> > + * When this option is enabled, all log items present in the AIL are emulated as
> > + * being in the pinned state until the option is disabled. Once disabled, log
> > + * items return to their natural state and fs operation continues as normal.
> > + */
> > +STATIC ssize_t
> > +log_pin_tail_store(
> > +	struct kobject		*kobject,
> > +	const char		*buf,
> > +	size_t			count)
> > +{
> > +	struct xlog		*log = to_xlog(kobject);
> > +	int			ret;
> > +	int			val;
> > +
> > +	ret = kstrtoint(buf, 0, &val);
> > +	if (ret)
> > +		return ret;
> > +
> > +	if (val == 1)
> > +		log->l_pin_tail = true;
> > +	else if (val == 0)
> > +		log->l_pin_tail = false;
> > +	else
> > +		return -EINVAL;
> > +
> > +	return count;
> > +}
> > +
> > +STATIC ssize_t
> > +log_pin_tail_show(
> > +	struct kobject		*kobject,
> > +	char			*buf)
> > +{
> > +	struct xlog		*log = to_xlog(kobject);
> > +
> > +	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
> > +}
> > +XFS_SYSFS_ATTR_RW(log_pin_tail);
> > +
> >  #endif	/* DEBUG */
> >  
> >  static struct attribute *xfs_log_attrs[] = {
> > @@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
> >  	ATTR_LIST(write_grant_head),
> >  #ifdef DEBUG
> >  	ATTR_LIST(log_badcrc_factor),
> > +	ATTR_LIST(log_pin_tail),
> >  #endif
> >  	NULL,
> >  };
> > diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
> > index 9056c0f..c901e61 100644
> > --- a/fs/xfs/xfs_trans_ail.c
> > +++ b/fs/xfs/xfs_trans_ail.c
> > @@ -27,6 +27,7 @@
> >  #include "xfs_trace.h"
> >  #include "xfs_error.h"
> >  #include "xfs_log.h"
> > +#include "xfs_log_priv.h"
> >  
> >  #ifdef DEBUG
> >  /*
> > @@ -325,6 +326,23 @@ xfs_ail_delete(
> >  	xfs_trans_ail_cursor_clear(ailp, lip);
> >  }
> >  
> > +static inline uint
> > +xfsaild_push_item(
> > +	struct xfs_ail		*ailp,
> > +	struct xfs_log_item	*lip)
> > +{
> > +#ifdef DEBUG
> > +	/*
> > +	 * If tail pinning is enabled, skip the push and track all items as
> > +	 * pinned to force pin the log tail. This helps induce head-behind-tail
> > +	 * conditions.
> > +	 */
> > +	if (ailp->xa_mount->m_log->l_pin_tail)
> > +		return XFS_ITEM_PINNED;
> > +#endif
> > +	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > +}
> > +
> >  static long
> >  xfsaild_push(
> >  	struct xfs_ail		*ailp)
> > @@ -382,7 +400,7 @@ xfsaild_push(
> >  		 * rely on the AIL cursor implementation to be able to deal with
> >  		 * the dropped lock.
> >  		 */
> > -		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > +		lock_result = xfsaild_push_item(ailp, lip);
> >  		switch (lock_result) {
> >  		case XFS_ITEM_SUCCESS:
> >  			XFS_STATS_INC(mp, xs_push_ail_success);
> > -- 
> > 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

Re: [PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Darrick J. Wong]

On Wed, Jun 21, 2017 at 06:16:54AM -0400, Brian Foster wrote:
> On Tue, Jun 20, 2017 at 02:48:32PM -0700, Darrick J. Wong wrote:
> > On Fri, Jun 16, 2017 at 12:44:33PM -0400, Brian Foster wrote:
> > > Create a debug mode only sysfs option to force pin the tail of the
> > > log. This option can be used by test infrastructure to induce head
> > > behind tail conditions. Specifically, this is intended to be used by
> > > xfstests to reproduce log recovery problems after failed/corrupted
> > > log writes overwrite the last good tail LSN in the log.
> > > 
> > > When enabled, AIL push attempts see every log item on the AIL in the
> > > pinned state. This stalls metadata writeback and thus prevents the
> > > current tail of the log from moving forward. When disabled,
> > > subsequent AIL pushes observe the log items in their appropriate
> > > state and filesystem operation continues as normal.
> > > 
> > > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > 
> > Looks ok enough to test...
> > Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
> > 
> 
> I assume you mean Reviewed-by... thanks! :)

Yep.  Though, having now pushed out the errortag-via-sysfs patchset,
I wonder if this could target that instead?

But, first things first, that series has to be reviewed.  We could (in
theory) push e-v-s and this for 4.13; or hold off on both for another
cycle; or integrate this patch for 4.13 and e-v-s for 4.14, and update
the test to sniff out the location of the knob dynamically like xfs/196
does.

<mostly just pre-coffee babbling at this point>

--D

> 
> Brian
> 
> > --D
> > 
> > > ---
> > > 
> > > Hi all,
> > > 
> > > This patch is a supporting patch for an xfstests test I'm about to post
> > > that pins the tail of the log in order to reproduce the log recovery
> > > problem that appears to be the root of the problem in this[1] thread.
> > > That is the primary motivation for the patch and so should probably be
> > > reviewed with that context. IOW, if there's a better way to reproduce
> > > the problem in the test without the need for kernel support, I'm happy
> > > to drop this. Thoughts, reviews, flames appreciated.
> > > 
> > > Brian
> > > 
> > > [1] http://www.spinics.net/lists/linux-xfs/msg07499.html
> > > 
> > >  fs/xfs/xfs_log_priv.h  |  2 ++
> > >  fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
> > >  fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
> > >  3 files changed, 67 insertions(+), 1 deletion(-)
> > > 
> > > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > > index c2604a5..bfbfde12 100644
> > > --- a/fs/xfs/xfs_log_priv.h
> > > +++ b/fs/xfs/xfs_log_priv.h
> > > @@ -413,6 +413,8 @@ struct xlog {
> > >  	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
> > >  	/* log record crc error injection factor */
> > >  	uint32_t		l_badcrc_factor;
> > > +	/* force pin the log tail */
> > > +	bool			l_pin_tail;
> > >  #endif
> > >  	/* log recovery lsn tracking (for buffer submission */
> > >  	xfs_lsn_t		l_recovery_lsn;
> > > diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
> > > index ec6e0e2..b86148a 100644
> > > --- a/fs/xfs/xfs_sysfs.c
> > > +++ b/fs/xfs/xfs_sysfs.c
> > > @@ -378,6 +378,51 @@ log_badcrc_factor_show(
> > >  }
> > >  
> > >  XFS_SYSFS_ATTR_RW(log_badcrc_factor);
> > > +
> > > +/*
> > > + * DEBUG mode flag to force pin the tail of the log. Used from test
> > > + * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
> > > + * DIRECTLY. This will lock up the fs!
> > > + *
> > > + * When this option is enabled, all log items present in the AIL are emulated as
> > > + * being in the pinned state until the option is disabled. Once disabled, log
> > > + * items return to their natural state and fs operation continues as normal.
> > > + */
> > > +STATIC ssize_t
> > > +log_pin_tail_store(
> > > +	struct kobject		*kobject,
> > > +	const char		*buf,
> > > +	size_t			count)
> > > +{
> > > +	struct xlog		*log = to_xlog(kobject);
> > > +	int			ret;
> > > +	int			val;
> > > +
> > > +	ret = kstrtoint(buf, 0, &val);
> > > +	if (ret)
> > > +		return ret;
> > > +
> > > +	if (val == 1)
> > > +		log->l_pin_tail = true;
> > > +	else if (val == 0)
> > > +		log->l_pin_tail = false;
> > > +	else
> > > +		return -EINVAL;
> > > +
> > > +	return count;
> > > +}
> > > +
> > > +STATIC ssize_t
> > > +log_pin_tail_show(
> > > +	struct kobject		*kobject,
> > > +	char			*buf)
> > > +{
> > > +	struct xlog		*log = to_xlog(kobject);
> > > +
> > > +	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
> > > +}
> > > +XFS_SYSFS_ATTR_RW(log_pin_tail);
> > > +
> > >  #endif	/* DEBUG */
> > >  
> > >  static struct attribute *xfs_log_attrs[] = {
> > > @@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
> > >  	ATTR_LIST(write_grant_head),
> > >  #ifdef DEBUG
> > >  	ATTR_LIST(log_badcrc_factor),
> > > +	ATTR_LIST(log_pin_tail),
> > >  #endif
> > >  	NULL,
> > >  };
> > > diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
> > > index 9056c0f..c901e61 100644
> > > --- a/fs/xfs/xfs_trans_ail.c
> > > +++ b/fs/xfs/xfs_trans_ail.c
> > > @@ -27,6 +27,7 @@
> > >  #include "xfs_trace.h"
> > >  #include "xfs_error.h"
> > >  #include "xfs_log.h"
> > > +#include "xfs_log_priv.h"
> > >  
> > >  #ifdef DEBUG
> > >  /*
> > > @@ -325,6 +326,23 @@ xfs_ail_delete(
> > >  	xfs_trans_ail_cursor_clear(ailp, lip);
> > >  }
> > >  
> > > +static inline uint
> > > +xfsaild_push_item(
> > > +	struct xfs_ail		*ailp,
> > > +	struct xfs_log_item	*lip)
> > > +{
> > > +#ifdef DEBUG
> > > +	/*
> > > +	 * If tail pinning is enabled, skip the push and track all items as
> > > +	 * pinned to force pin the log tail. This helps induce head-behind-tail
> > > +	 * conditions.
> > > +	 */
> > > +	if (ailp->xa_mount->m_log->l_pin_tail)
> > > +		return XFS_ITEM_PINNED;
> > > +#endif
> > > +	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > +}
> > > +
> > >  static long
> > >  xfsaild_push(
> > >  	struct xfs_ail		*ailp)
> > > @@ -382,7 +400,7 @@ xfsaild_push(
> > >  		 * rely on the AIL cursor implementation to be able to deal with
> > >  		 * the dropped lock.
> > >  		 */
> > > -		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > +		lock_result = xfsaild_push_item(ailp, lip);
> > >  		switch (lock_result) {
> > >  		case XFS_ITEM_SUCCESS:
> > >  			XFS_STATS_INC(mp, xs_push_ail_success);
> > > -- 
> > > 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
> --
> 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

Re: [PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Brian Foster]

On Wed, Jun 21, 2017 at 08:47:59AM -0700, Darrick J. Wong wrote:
> On Wed, Jun 21, 2017 at 06:16:54AM -0400, Brian Foster wrote:
> > On Tue, Jun 20, 2017 at 02:48:32PM -0700, Darrick J. Wong wrote:
> > > On Fri, Jun 16, 2017 at 12:44:33PM -0400, Brian Foster wrote:
> > > > Create a debug mode only sysfs option to force pin the tail of the
> > > > log. This option can be used by test infrastructure to induce head
> > > > behind tail conditions. Specifically, this is intended to be used by
> > > > xfstests to reproduce log recovery problems after failed/corrupted
> > > > log writes overwrite the last good tail LSN in the log.
> > > > 
> > > > When enabled, AIL push attempts see every log item on the AIL in the
> > > > pinned state. This stalls metadata writeback and thus prevents the
> > > > current tail of the log from moving forward. When disabled,
> > > > subsequent AIL pushes observe the log items in their appropriate
> > > > state and filesystem operation continues as normal.
> > > > 
> > > > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > > 
> > > Looks ok enough to test...
> > > Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
> > > 
> > 
> > I assume you mean Reviewed-by... thanks! :)
> 
> Yep.  Though, having now pushed out the errortag-via-sysfs patchset,
> I wonder if this could target that instead?
> 

Indeed, I think that is a good idea...

> But, first things first, that series has to be reviewed.  We could (in
> theory) push e-v-s and this for 4.13; or hold off on both for another
> cycle; or integrate this patch for 4.13 and e-v-s for 4.14, and update
> the test to sniff out the location of the knob dynamically like xfs/196
> does.
> 

I'm fine with deferring this particular mechanism and the test if we
have a general error injection mechanism in mind. This is really just
for reproducing the problem and verification (once I have a fix put
together ;P, though I think I now have a decent idea on how to fix
this), so to me it's fine to hold off so long as something is available
for reviewers to use in the meantime (i.e., same way I feel about
Carlos' AIL retry patches). That saves us from modifying the test again
if we can help it as well.

I assume this patch would morph into something like making ->iop_push()
an injection point (where an "error" means return XFS_ITEM_PINNED) and
rather than having the log_pin_tail knob, the test can just set that
error between 0 and 100% (but I'll try to get a look at the new patches
shortly...).

Brian

> <mostly just pre-coffee babbling at this point>
> 
> --D
> 
> > 
> > Brian
> > 
> > > --D
> > > 
> > > > ---
> > > > 
> > > > Hi all,
> > > > 
> > > > This patch is a supporting patch for an xfstests test I'm about to post
> > > > that pins the tail of the log in order to reproduce the log recovery
> > > > problem that appears to be the root of the problem in this[1] thread.
> > > > That is the primary motivation for the patch and so should probably be
> > > > reviewed with that context. IOW, if there's a better way to reproduce
> > > > the problem in the test without the need for kernel support, I'm happy
> > > > to drop this. Thoughts, reviews, flames appreciated.
> > > > 
> > > > Brian
> > > > 
> > > > [1] http://www.spinics.net/lists/linux-xfs/msg07499.html
> > > > 
> > > >  fs/xfs/xfs_log_priv.h  |  2 ++
> > > >  fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
> > > >  fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
> > > >  3 files changed, 67 insertions(+), 1 deletion(-)
> > > > 
> > > > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > > > index c2604a5..bfbfde12 100644
> > > > --- a/fs/xfs/xfs_log_priv.h
> > > > +++ b/fs/xfs/xfs_log_priv.h
> > > > @@ -413,6 +413,8 @@ struct xlog {
> > > >  	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
> > > >  	/* log record crc error injection factor */
> > > >  	uint32_t		l_badcrc_factor;
> > > > +	/* force pin the log tail */
> > > > +	bool			l_pin_tail;
> > > >  #endif
> > > >  	/* log recovery lsn tracking (for buffer submission */
> > > >  	xfs_lsn_t		l_recovery_lsn;
> > > > diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
> > > > index ec6e0e2..b86148a 100644
> > > > --- a/fs/xfs/xfs_sysfs.c
> > > > +++ b/fs/xfs/xfs_sysfs.c
> > > > @@ -378,6 +378,51 @@ log_badcrc_factor_show(
> > > >  }
> > > >  
> > > >  XFS_SYSFS_ATTR_RW(log_badcrc_factor);
> > > > +
> > > > +/*
> > > > + * DEBUG mode flag to force pin the tail of the log. Used from test
> > > > + * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
> > > > + * DIRECTLY. This will lock up the fs!
> > > > + *
> > > > + * When this option is enabled, all log items present in the AIL are emulated as
> > > > + * being in the pinned state until the option is disabled. Once disabled, log
> > > > + * items return to their natural state and fs operation continues as normal.
> > > > + */
> > > > +STATIC ssize_t
> > > > +log_pin_tail_store(
> > > > +	struct kobject		*kobject,
> > > > +	const char		*buf,
> > > > +	size_t			count)
> > > > +{
> > > > +	struct xlog		*log = to_xlog(kobject);
> > > > +	int			ret;
> > > > +	int			val;
> > > > +
> > > > +	ret = kstrtoint(buf, 0, &val);
> > > > +	if (ret)
> > > > +		return ret;
> > > > +
> > > > +	if (val == 1)
> > > > +		log->l_pin_tail = true;
> > > > +	else if (val == 0)
> > > > +		log->l_pin_tail = false;
> > > > +	else
> > > > +		return -EINVAL;
> > > > +
> > > > +	return count;
> > > > +}
> > > > +
> > > > +STATIC ssize_t
> > > > +log_pin_tail_show(
> > > > +	struct kobject		*kobject,
> > > > +	char			*buf)
> > > > +{
> > > > +	struct xlog		*log = to_xlog(kobject);
> > > > +
> > > > +	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
> > > > +}
> > > > +XFS_SYSFS_ATTR_RW(log_pin_tail);
> > > > +
> > > >  #endif	/* DEBUG */
> > > >  
> > > >  static struct attribute *xfs_log_attrs[] = {
> > > > @@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
> > > >  	ATTR_LIST(write_grant_head),
> > > >  #ifdef DEBUG
> > > >  	ATTR_LIST(log_badcrc_factor),
> > > > +	ATTR_LIST(log_pin_tail),
> > > >  #endif
> > > >  	NULL,
> > > >  };
> > > > diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
> > > > index 9056c0f..c901e61 100644
> > > > --- a/fs/xfs/xfs_trans_ail.c
> > > > +++ b/fs/xfs/xfs_trans_ail.c
> > > > @@ -27,6 +27,7 @@
> > > >  #include "xfs_trace.h"
> > > >  #include "xfs_error.h"
> > > >  #include "xfs_log.h"
> > > > +#include "xfs_log_priv.h"
> > > >  
> > > >  #ifdef DEBUG
> > > >  /*
> > > > @@ -325,6 +326,23 @@ xfs_ail_delete(
> > > >  	xfs_trans_ail_cursor_clear(ailp, lip);
> > > >  }
> > > >  
> > > > +static inline uint
> > > > +xfsaild_push_item(
> > > > +	struct xfs_ail		*ailp,
> > > > +	struct xfs_log_item	*lip)
> > > > +{
> > > > +#ifdef DEBUG
> > > > +	/*
> > > > +	 * If tail pinning is enabled, skip the push and track all items as
> > > > +	 * pinned to force pin the log tail. This helps induce head-behind-tail
> > > > +	 * conditions.
> > > > +	 */
> > > > +	if (ailp->xa_mount->m_log->l_pin_tail)
> > > > +		return XFS_ITEM_PINNED;
> > > > +#endif
> > > > +	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > > +}
> > > > +
> > > >  static long
> > > >  xfsaild_push(
> > > >  	struct xfs_ail		*ailp)
> > > > @@ -382,7 +400,7 @@ xfsaild_push(
> > > >  		 * rely on the AIL cursor implementation to be able to deal with
> > > >  		 * the dropped lock.
> > > >  		 */
> > > > -		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > > +		lock_result = xfsaild_push_item(ailp, lip);
> > > >  		switch (lock_result) {
> > > >  		case XFS_ITEM_SUCCESS:
> > > >  			XFS_STATS_INC(mp, xs_push_ail_success);
> > > > -- 
> > > > 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
> > --
> > 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

Re: [PATCH] xfs: debug mode sysfs flag to force [un]pin the log tail

[Darrick J. Wong]

On Wed, Jun 21, 2017 at 12:08:23PM -0400, Brian Foster wrote:
> On Wed, Jun 21, 2017 at 08:47:59AM -0700, Darrick J. Wong wrote:
> > On Wed, Jun 21, 2017 at 06:16:54AM -0400, Brian Foster wrote:
> > > On Tue, Jun 20, 2017 at 02:48:32PM -0700, Darrick J. Wong wrote:
> > > > On Fri, Jun 16, 2017 at 12:44:33PM -0400, Brian Foster wrote:
> > > > > Create a debug mode only sysfs option to force pin the tail of the
> > > > > log. This option can be used by test infrastructure to induce head
> > > > > behind tail conditions. Specifically, this is intended to be used by
> > > > > xfstests to reproduce log recovery problems after failed/corrupted
> > > > > log writes overwrite the last good tail LSN in the log.
> > > > > 
> > > > > When enabled, AIL push attempts see every log item on the AIL in the
> > > > > pinned state. This stalls metadata writeback and thus prevents the
> > > > > current tail of the log from moving forward. When disabled,
> > > > > subsequent AIL pushes observe the log items in their appropriate
> > > > > state and filesystem operation continues as normal.
> > > > > 
> > > > > Signed-off-by: Brian Foster <bfoster@redhat.com>
> > > > 
> > > > Looks ok enough to test...
> > > > Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
> > > > 
> > > 
> > > I assume you mean Reviewed-by... thanks! :)
> > 
> > Yep.  Though, having now pushed out the errortag-via-sysfs patchset,
> > I wonder if this could target that instead?
> > 
> 
> Indeed, I think that is a good idea...
> 
> > But, first things first, that series has to be reviewed.  We could (in
> > theory) push e-v-s and this for 4.13; or hold off on both for another
> > cycle; or integrate this patch for 4.13 and e-v-s for 4.14, and update
> > the test to sniff out the location of the knob dynamically like xfs/196
> > does.
> > 
> 
> I'm fine with deferring this particular mechanism and the test if we
> have a general error injection mechanism in mind. This is really just
> for reproducing the problem and verification (once I have a fix put
> together ;P, though I think I now have a decent idea on how to fix
> this), so to me it's fine to hold off so long as something is available
> for reviewers to use in the meantime (i.e., same way I feel about
> Carlos' AIL retry patches). That saves us from modifying the test again
> if we can help it as well.
> 
> I assume this patch would morph into something like making ->iop_push()
> an injection point (where an "error" means return XFS_ITEM_PINNED) and
> rather than having the log_pin_tail knob, the test can just set that
> error between 0 and 100% (but I'll try to get a look at the new patches
> shortly...).

Yes, you'd more or less just #define a new XFS_ERRTAG_PIN_LOGS and the
appropriate sysfs attributes, then:

static inline uint
xfsaild_push_item(
	struct xfs_ail		*ailp,
	struct xfs_log_item	*lip)
{
	if (XFS_TEST_ERROR(false, ailp->xa_mount, XFS_ERRTAG_PIN_LOGS))
		return XFS_ITEM_PINNED;

	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
}

...and then we can flip the whole thing on by:

echo 43 > /sys/fs/xfs/sda/errortag/pin_logs

...which will trigger the pinning about once every 43rd invocation.

--D

> 
> Brian
> 
> > <mostly just pre-coffee babbling at this point>
> > 
> > --D
> > 
> > > 
> > > Brian
> > > 
> > > > --D
> > > > 
> > > > > ---
> > > > > 
> > > > > Hi all,
> > > > > 
> > > > > This patch is a supporting patch for an xfstests test I'm about to post
> > > > > that pins the tail of the log in order to reproduce the log recovery
> > > > > problem that appears to be the root of the problem in this[1] thread.
> > > > > That is the primary motivation for the patch and so should probably be
> > > > > reviewed with that context. IOW, if there's a better way to reproduce
> > > > > the problem in the test without the need for kernel support, I'm happy
> > > > > to drop this. Thoughts, reviews, flames appreciated.
> > > > > 
> > > > > Brian
> > > > > 
> > > > > [1] http://www.spinics.net/lists/linux-xfs/msg07499.html
> > > > > 
> > > > >  fs/xfs/xfs_log_priv.h  |  2 ++
> > > > >  fs/xfs/xfs_sysfs.c     | 46 ++++++++++++++++++++++++++++++++++++++++++++++
> > > > >  fs/xfs/xfs_trans_ail.c | 20 +++++++++++++++++++-
> > > > >  3 files changed, 67 insertions(+), 1 deletion(-)
> > > > > 
> > > > > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > > > > index c2604a5..bfbfde12 100644
> > > > > --- a/fs/xfs/xfs_log_priv.h
> > > > > +++ b/fs/xfs/xfs_log_priv.h
> > > > > @@ -413,6 +413,8 @@ struct xlog {
> > > > >  	void			*l_iclog_bak[XLOG_MAX_ICLOGS];
> > > > >  	/* log record crc error injection factor */
> > > > >  	uint32_t		l_badcrc_factor;
> > > > > +	/* force pin the log tail */
> > > > > +	bool			l_pin_tail;
> > > > >  #endif
> > > > >  	/* log recovery lsn tracking (for buffer submission */
> > > > >  	xfs_lsn_t		l_recovery_lsn;
> > > > > diff --git a/fs/xfs/xfs_sysfs.c b/fs/xfs/xfs_sysfs.c
> > > > > index ec6e0e2..b86148a 100644
> > > > > --- a/fs/xfs/xfs_sysfs.c
> > > > > +++ b/fs/xfs/xfs_sysfs.c
> > > > > @@ -378,6 +378,51 @@ log_badcrc_factor_show(
> > > > >  }
> > > > >  
> > > > >  XFS_SYSFS_ATTR_RW(log_badcrc_factor);
> > > > > +
> > > > > +/*
> > > > > + * DEBUG mode flag to force pin the tail of the log. Used from test
> > > > > + * infrastructure to manufacture head-behind-tail conditions. DO NOT USE
> > > > > + * DIRECTLY. This will lock up the fs!
> > > > > + *
> > > > > + * When this option is enabled, all log items present in the AIL are emulated as
> > > > > + * being in the pinned state until the option is disabled. Once disabled, log
> > > > > + * items return to their natural state and fs operation continues as normal.
> > > > > + */
> > > > > +STATIC ssize_t
> > > > > +log_pin_tail_store(
> > > > > +	struct kobject		*kobject,
> > > > > +	const char		*buf,
> > > > > +	size_t			count)
> > > > > +{
> > > > > +	struct xlog		*log = to_xlog(kobject);
> > > > > +	int			ret;
> > > > > +	int			val;
> > > > > +
> > > > > +	ret = kstrtoint(buf, 0, &val);
> > > > > +	if (ret)
> > > > > +		return ret;
> > > > > +
> > > > > +	if (val == 1)
> > > > > +		log->l_pin_tail = true;
> > > > > +	else if (val == 0)
> > > > > +		log->l_pin_tail = false;
> > > > > +	else
> > > > > +		return -EINVAL;
> > > > > +
> > > > > +	return count;
> > > > > +}
> > > > > +
> > > > > +STATIC ssize_t
> > > > > +log_pin_tail_show(
> > > > > +	struct kobject		*kobject,
> > > > > +	char			*buf)
> > > > > +{
> > > > > +	struct xlog		*log = to_xlog(kobject);
> > > > > +
> > > > > +	return snprintf(buf, PAGE_SIZE, "%d\n", log->l_pin_tail ? 1 : 0);
> > > > > +}
> > > > > +XFS_SYSFS_ATTR_RW(log_pin_tail);
> > > > > +
> > > > >  #endif	/* DEBUG */
> > > > >  
> > > > >  static struct attribute *xfs_log_attrs[] = {
> > > > > @@ -387,6 +432,7 @@ static struct attribute *xfs_log_attrs[] = {
> > > > >  	ATTR_LIST(write_grant_head),
> > > > >  #ifdef DEBUG
> > > > >  	ATTR_LIST(log_badcrc_factor),
> > > > > +	ATTR_LIST(log_pin_tail),
> > > > >  #endif
> > > > >  	NULL,
> > > > >  };
> > > > > diff --git a/fs/xfs/xfs_trans_ail.c b/fs/xfs/xfs_trans_ail.c
> > > > > index 9056c0f..c901e61 100644
> > > > > --- a/fs/xfs/xfs_trans_ail.c
> > > > > +++ b/fs/xfs/xfs_trans_ail.c
> > > > > @@ -27,6 +27,7 @@
> > > > >  #include "xfs_trace.h"
> > > > >  #include "xfs_error.h"
> > > > >  #include "xfs_log.h"
> > > > > +#include "xfs_log_priv.h"
> > > > >  
> > > > >  #ifdef DEBUG
> > > > >  /*
> > > > > @@ -325,6 +326,23 @@ xfs_ail_delete(
> > > > >  	xfs_trans_ail_cursor_clear(ailp, lip);
> > > > >  }
> > > > >  
> > > > > +static inline uint
> > > > > +xfsaild_push_item(
> > > > > +	struct xfs_ail		*ailp,
> > > > > +	struct xfs_log_item	*lip)
> > > > > +{
> > > > > +#ifdef DEBUG
> > > > > +	/*
> > > > > +	 * If tail pinning is enabled, skip the push and track all items as
> > > > > +	 * pinned to force pin the log tail. This helps induce head-behind-tail
> > > > > +	 * conditions.
> > > > > +	 */
> > > > > +	if (ailp->xa_mount->m_log->l_pin_tail)
> > > > > +		return XFS_ITEM_PINNED;
> > > > > +#endif
> > > > > +	return lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > > > +}
> > > > > +
> > > > >  static long
> > > > >  xfsaild_push(
> > > > >  	struct xfs_ail		*ailp)
> > > > > @@ -382,7 +400,7 @@ xfsaild_push(
> > > > >  		 * rely on the AIL cursor implementation to be able to deal with
> > > > >  		 * the dropped lock.
> > > > >  		 */
> > > > > -		lock_result = lip->li_ops->iop_push(lip, &ailp->xa_buf_list);
> > > > > +		lock_result = xfsaild_push_item(ailp, lip);
> > > > >  		switch (lock_result) {
> > > > >  		case XFS_ITEM_SUCCESS:
> > > > >  			XFS_STATS_INC(mp, xs_push_ail_success);
> > > > > -- 
> > > > > 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
> > > --
> > > 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