[RFC PATCH 0/2] xfs: hard limit background CIL push size

[RFC PATCH 0/2] xfs: hard limit background CIL push size

[Dave Chinner]

Hi folks,

As we've been discussing from the recent generic/530 hangs, the CIL
push work can get held off for an arbitrary amount of time and
result in the CIL checkpoint growing large enough that it can
consume the entire log. This is not allowed - the log recovery
algorithm for finding the head and tail of the log requires two
checkpoints in the log so it can find the last full checkpoint that
it needs to recover. That puts a hard limit on the size of the CIL
checkpoints of just under 50% of the log.

The CIL currently doesn't have any enforcement on that - log space
hangs due to CIL overruns are not something we've see in test or
production systems until the recent unlinked list modifications we
made. Hence this has laregely been a theoretical problem rather than
a practical problem up to this point.

While we've made changes that avoid the CIL hold-off vectors that
lead to the generic/530 hangs, we have enough data on the CIL
characteristics and performance to be able to put in place hard
limits without compromising performance.

The first patch limits the CIL size on large logs - we don't need to
aggregate hundreds of megabytes of metadata in the CIL to realise
the relogging benefits that the CIL provides. Measures show that the
point at which performance starts to be affected is somewhere
between 16MB and 32MB of aggregated changes in the CIL. Hence
the background push threshold is limited to be 32MB on large logs,
but remains at 12.5% of the log on small logs.

The second patch adds a hard limit on the CIL background push
threshold. This is set to double the size of the push threshold, so
at most a single CIL context will consume 25% of the log before
attempts to do background pushes will block waiting for the
background push of that context to start. This means that all
processes that commit to a push context that is over the hard limit
will sleep until the background CIL push work starts on that
context. At that point, they will be woken and their next
transaction commits will occur into the new CIL commit that the
background push will switch over to.

This provides a hard limit on the size of CIL checkpoint of ~1/4 of
the entire log, well inside the size limit that log recovery imposes
on us. For maximally sized logs, this hard limit ends up being about
3% of the entire log, so it serves to keep the logged objects moving
from the CIL to the AIL at a reasonable rate and spreads them over a
wider range of LSNs giving more graduated (less bursty) tail pushing
behaviour.

Comments welcome.

-Dave.

[PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Dave Chinner]

From: Dave Chinner <dchinner@redhat.com>

The current CIL size aggregation limit is 1/8th the log size. This
means for large logs we might be aggregating at least 250MB of dirty objects
in memory before the CIL is flushed to the journal. With CIL shadow
buffers sitting around, this means the CIL is often consuming >500MB
of temporary memory that is all allocated under GFP_NOFS conditions.

Flushing the CIL can take some time to do if there is other IO
ongoing, and can introduce substantial log force latency by itself.
It also pins the memory until the objects are in the AIL and can be
written back and reclaimed by shrinkers. Hence this threshold also
tends to determine the minimum amount of memory XFS can operate in
under heavy modification without triggering the OOM killer.

Modify the CIL space limit to prevent such huge amounts of pinned
metadata from aggregating. We can have 2MB of log IO in flight at
once, so limit aggregation to 16x this size. This threshold was
chosen as it little impact on performance (on 16-way fsmark) or log
traffic but pins a lot less memory on large logs especially under
heavy memory pressure.  An aggregation limit of 8x had 5-10%
performance degradation and a 50% increase in log throughput for
the same workload, so clearly that was too small for highly
concurrent workloads on large logs.

This was found via trace analysis of AIL behaviour. e.g. insertion
from a single CIL flush:

xfs_ail_insert: old lsn 0/0 new lsn 1/3033090 type XFS_LI_INODE flags IN_AIL

$ grep xfs_ail_insert /mnt/scratch/s.t |grep "new lsn 1/3033090" |wc -l
1721823
$

So there were 1.7 million objects inserted into the AIL from this
CIL checkpoint, the first at 2323.392108, the last at 2325.667566 which
was the end of the trace (i.e. it hadn't finished). Clearly a major
problem.

Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 fs/xfs/xfs_log_priv.h | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
index b880c23cb6e4..187a43ffeaf7 100644
--- a/fs/xfs/xfs_log_priv.h
+++ b/fs/xfs/xfs_log_priv.h
@@ -329,7 +329,8 @@ struct xfs_cil {
  * enforced to ensure we stay within our maximum checkpoint size bounds.
  * threshold, yet give us plenty of space for aggregation on large logs.
  */
-#define XLOG_CIL_SPACE_LIMIT(log)	(log->l_logsize >> 3)
+#define XLOG_CIL_SPACE_LIMIT(log)	\
+	min_t(int, (log)->l_logsize >> 3, BBTOB(XLOG_TOTAL_REC_SHIFT(log)) << 4)
 
 /*
  * ticket grant locks, queues and accounting have their own cachlines
-- 
2.23.0.rc1

[PATCH 2/2] xfs: hard limit the background CIL push

[Dave Chinner]

From: Dave Chinner <dchinner@redhat.com>

In certain situations the background CIL push can be indefinitely
delayed. While we have workarounds from the obvious cases now, it
doesn't solve the underlying issue. This issue is that there is no
upper limit on the CIL where we will either force or wait for
a background push to start, hence allowing the CIL to grow without
bound until it consumes all log space.

To fix this, add a new wait queue to the CIL which allows background
pushes to wait for the CIL context to be switched out. This happens
when the push starts, so it will allow us to block incoming
transaction commit completion until the push has started. This will
only affect processes that are running modifications, and only when
the CIL threshold has been significantly overrun.

This has no apparent impact on performance, and doesn't even trigger
until over 45 million inodes had been created in a 16-way fsmark
test on a 2GB log. That was limiting at 64MB of log space used, so
the active CIL size is only about 3% of the total log in that case.
The concurrent removal of those files did not trigger the background
sleep at all.

Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 fs/xfs/xfs_log_cil.c  | 30 +++++++++++++++++++++++++-----
 fs/xfs/xfs_log_priv.h |  1 +
 2 files changed, 26 insertions(+), 5 deletions(-)

diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index ef652abd112c..eec9b32f5e08 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -670,6 +670,11 @@ xlog_cil_push(
 	push_seq = cil->xc_push_seq;
 	ASSERT(push_seq <= ctx->sequence);
 
+	/*
+	 * Wake up any background push waiters now this context is being pushed.
+	 */
+	wake_up_all(&ctx->push_wait);
+
 	/*
 	 * Check if we've anything to push. If there is nothing, then we don't
 	 * move on to a new sequence number and so we have to be able to push
@@ -746,6 +751,7 @@ xlog_cil_push(
 	 */
 	INIT_LIST_HEAD(&new_ctx->committing);
 	INIT_LIST_HEAD(&new_ctx->busy_extents);
+	init_waitqueue_head(&new_ctx->push_wait);
 	new_ctx->sequence = ctx->sequence + 1;
 	new_ctx->cil = cil;
 	cil->xc_ctx = new_ctx;
@@ -898,7 +904,7 @@ xlog_cil_push_work(
  * checkpoint), but commit latency and memory usage limit this to a smaller
  * size.
  */
-static void
+static bool
 xlog_cil_push_background(
 	struct xlog	*log)
 {
@@ -915,14 +921,28 @@ xlog_cil_push_background(
 	 * space available yet.
 	 */
 	if (cil->xc_ctx->space_used < XLOG_CIL_SPACE_LIMIT(log))
-		return;
+		return false;
 
 	spin_lock(&cil->xc_push_lock);
 	if (cil->xc_push_seq < cil->xc_current_sequence) {
 		cil->xc_push_seq = cil->xc_current_sequence;
 		queue_work(log->l_mp->m_cil_workqueue, &cil->xc_push_work);
 	}
+
+	/*
+	 * If we are well over the space limit, throttle the work that is being
+	 * done until the push work on this context has begun. This will prevent
+	 * the CIL from violating maximum transaction size limits if the CIL
+	 * push is delayed for some reason.
+	 */
+	if (cil->xc_ctx->space_used > XLOG_CIL_SPACE_LIMIT(log) * 2) {
+		up_read(&cil->xc_ctx_lock);
+		trace_printk("CIL space used %d", cil->xc_ctx->space_used);
+		xlog_wait(&cil->xc_ctx->push_wait, &cil->xc_push_lock);
+		return true;
+	}
 	spin_unlock(&cil->xc_push_lock);
+	return false;
 
 }
 
@@ -1038,9 +1058,8 @@ xfs_log_commit_cil(
 		if (lip->li_ops->iop_committing)
 			lip->li_ops->iop_committing(lip, xc_commit_lsn);
 	}
-	xlog_cil_push_background(log);
-
-	up_read(&cil->xc_ctx_lock);
+	if (!xlog_cil_push_background(log))
+		up_read(&cil->xc_ctx_lock);
 }
 
 /*
@@ -1199,6 +1218,7 @@ xlog_cil_init(
 
 	INIT_LIST_HEAD(&ctx->committing);
 	INIT_LIST_HEAD(&ctx->busy_extents);
+	init_waitqueue_head(&ctx->push_wait);
 	ctx->sequence = 1;
 	ctx->cil = cil;
 	cil->xc_ctx = ctx;
diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
index 187a43ffeaf7..466259fd1e4a 100644
--- a/fs/xfs/xfs_log_priv.h
+++ b/fs/xfs/xfs_log_priv.h
@@ -247,6 +247,7 @@ struct xfs_cil_ctx {
 	struct xfs_log_vec	*lv_chain;	/* logvecs being pushed */
 	struct list_head	iclog_entry;
 	struct list_head	committing;	/* ctx committing list */
+	wait_queue_head_t	push_wait;	/* background push throttle */
 	struct work_struct	discard_endio_work;
 };
 
-- 
2.23.0.rc1

Re: [PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Darrick J. Wong]

On Mon, Sep 09, 2019 at 11:51:58AM +1000, Dave Chinner wrote:
> From: Dave Chinner <dchinner@redhat.com>
> 
> The current CIL size aggregation limit is 1/8th the log size. This
> means for large logs we might be aggregating at least 250MB of dirty objects
> in memory before the CIL is flushed to the journal. With CIL shadow
> buffers sitting around, this means the CIL is often consuming >500MB
> of temporary memory that is all allocated under GFP_NOFS conditions.
> 
> Flushing the CIL can take some time to do if there is other IO
> ongoing, and can introduce substantial log force latency by itself.
> It also pins the memory until the objects are in the AIL and can be
> written back and reclaimed by shrinkers. Hence this threshold also
> tends to determine the minimum amount of memory XFS can operate in
> under heavy modification without triggering the OOM killer.
> 
> Modify the CIL space limit to prevent such huge amounts of pinned
> metadata from aggregating. We can have 2MB of log IO in flight at
> once, so limit aggregation to 16x this size. This threshold was
> chosen as it little impact on performance (on 16-way fsmark) or log
> traffic but pins a lot less memory on large logs especially under
> heavy memory pressure.  An aggregation limit of 8x had 5-10%
> performance degradation and a 50% increase in log throughput for
> the same workload, so clearly that was too small for highly
> concurrent workloads on large logs.

It would be nice to capture at least some of this reasoning in the
already lengthy comment preceeding the #define....

> This was found via trace analysis of AIL behaviour. e.g. insertion
> from a single CIL flush:
> 
> xfs_ail_insert: old lsn 0/0 new lsn 1/3033090 type XFS_LI_INODE flags IN_AIL
> 
> $ grep xfs_ail_insert /mnt/scratch/s.t |grep "new lsn 1/3033090" |wc -l
> 1721823
> $
> 
> So there were 1.7 million objects inserted into the AIL from this
> CIL checkpoint, the first at 2323.392108, the last at 2325.667566 which
> was the end of the trace (i.e. it hadn't finished). Clearly a major
> problem.
> 
> Signed-off-by: Dave Chinner <dchinner@redhat.com>
> ---
>  fs/xfs/xfs_log_priv.h | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> index b880c23cb6e4..187a43ffeaf7 100644
> --- a/fs/xfs/xfs_log_priv.h
> +++ b/fs/xfs/xfs_log_priv.h
> @@ -329,7 +329,8 @@ struct xfs_cil {
>   * enforced to ensure we stay within our maximum checkpoint size bounds.
>   * threshold, yet give us plenty of space for aggregation on large logs.

...also, does XLOG_CIL_SPACE_LIMIT correspond to "a lower threshold at
which background pushing is attempted", or "a separate, higher bound"?
I think it's the first (????) but ... I don't know.  The name made me
think it was the second, but the single use of the symbol suggests the
first. :)

--D

>   */
> -#define XLOG_CIL_SPACE_LIMIT(log)	(log->l_logsize >> 3)
> +#define XLOG_CIL_SPACE_LIMIT(log)	\
> +	min_t(int, (log)->l_logsize >> 3, BBTOB(XLOG_TOTAL_REC_SHIFT(log)) << 4)
>  
>  /*
>   * ticket grant locks, queues and accounting have their own cachlines
> -- 
> 2.23.0.rc1
> 

Re: [PATCH 2/2] xfs: hard limit the background CIL push

[Darrick J. Wong]

On Mon, Sep 09, 2019 at 11:51:59AM +1000, Dave Chinner wrote:
> From: Dave Chinner <dchinner@redhat.com>
> 
> In certain situations the background CIL push can be indefinitely
> delayed. While we have workarounds from the obvious cases now, it
> doesn't solve the underlying issue. This issue is that there is no
> upper limit on the CIL where we will either force or wait for
> a background push to start, hence allowing the CIL to grow without
> bound until it consumes all log space.
> 
> To fix this, add a new wait queue to the CIL which allows background
> pushes to wait for the CIL context to be switched out. This happens
> when the push starts, so it will allow us to block incoming
> transaction commit completion until the push has started. This will
> only affect processes that are running modifications, and only when
> the CIL threshold has been significantly overrun.
> 
> This has no apparent impact on performance, and doesn't even trigger
> until over 45 million inodes had been created in a 16-way fsmark
> test on a 2GB log. That was limiting at 64MB of log space used, so
> the active CIL size is only about 3% of the total log in that case.
> The concurrent removal of those files did not trigger the background
> sleep at all.
> 
> Signed-off-by: Dave Chinner <dchinner@redhat.com>
> ---
>  fs/xfs/xfs_log_cil.c  | 30 +++++++++++++++++++++++++-----
>  fs/xfs/xfs_log_priv.h |  1 +
>  2 files changed, 26 insertions(+), 5 deletions(-)
> 
> diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> index ef652abd112c..eec9b32f5e08 100644
> --- a/fs/xfs/xfs_log_cil.c
> +++ b/fs/xfs/xfs_log_cil.c
> @@ -670,6 +670,11 @@ xlog_cil_push(
>  	push_seq = cil->xc_push_seq;
>  	ASSERT(push_seq <= ctx->sequence);
>  
> +	/*
> +	 * Wake up any background push waiters now this context is being pushed.
> +	 */
> +	wake_up_all(&ctx->push_wait);
> +
>  	/*
>  	 * Check if we've anything to push. If there is nothing, then we don't
>  	 * move on to a new sequence number and so we have to be able to push
> @@ -746,6 +751,7 @@ xlog_cil_push(
>  	 */
>  	INIT_LIST_HEAD(&new_ctx->committing);
>  	INIT_LIST_HEAD(&new_ctx->busy_extents);
> +	init_waitqueue_head(&new_ctx->push_wait);
>  	new_ctx->sequence = ctx->sequence + 1;
>  	new_ctx->cil = cil;
>  	cil->xc_ctx = new_ctx;
> @@ -898,7 +904,7 @@ xlog_cil_push_work(
>   * checkpoint), but commit latency and memory usage limit this to a smaller
>   * size.
>   */
> -static void
> +static bool
>  xlog_cil_push_background(
>  	struct xlog	*log)
>  {
> @@ -915,14 +921,28 @@ xlog_cil_push_background(
>  	 * space available yet.
>  	 */
>  	if (cil->xc_ctx->space_used < XLOG_CIL_SPACE_LIMIT(log))
> -		return;
> +		return false;
>  
>  	spin_lock(&cil->xc_push_lock);
>  	if (cil->xc_push_seq < cil->xc_current_sequence) {
>  		cil->xc_push_seq = cil->xc_current_sequence;
>  		queue_work(log->l_mp->m_cil_workqueue, &cil->xc_push_work);
>  	}
> +
> +	/*
> +	 * If we are well over the space limit, throttle the work that is being
> +	 * done until the push work on this context has begun. This will prevent
> +	 * the CIL from violating maximum transaction size limits if the CIL
> +	 * push is delayed for some reason.
> +	 */
> +	if (cil->xc_ctx->space_used > XLOG_CIL_SPACE_LIMIT(log) * 2) {
> +		up_read(&cil->xc_ctx_lock);
> +		trace_printk("CIL space used %d", cil->xc_ctx->space_used);

Needs a real tracepoint before this drops RFC status.

> +		xlog_wait(&cil->xc_ctx->push_wait, &cil->xc_push_lock);
> +		return true;
> +	}
>  	spin_unlock(&cil->xc_push_lock);
> +	return false;
>  
>  }
>  
> @@ -1038,9 +1058,8 @@ xfs_log_commit_cil(
>  		if (lip->li_ops->iop_committing)
>  			lip->li_ops->iop_committing(lip, xc_commit_lsn);
>  	}
> -	xlog_cil_push_background(log);
> -
> -	up_read(&cil->xc_ctx_lock);
> +	if (!xlog_cil_push_background(log))
> +		up_read(&cil->xc_ctx_lock);

Hmmmm... the return value here tell us if ctx_lock has been dropped.
/me wonders if this would be cleaner if xlog_cil_push_background
returned having called up_read...?

--D

>  }
>  
>  /*
> @@ -1199,6 +1218,7 @@ xlog_cil_init(
>  
>  	INIT_LIST_HEAD(&ctx->committing);
>  	INIT_LIST_HEAD(&ctx->busy_extents);
> +	init_waitqueue_head(&ctx->push_wait);
>  	ctx->sequence = 1;
>  	ctx->cil = cil;
>  	cil->xc_ctx = ctx;
> diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> index 187a43ffeaf7..466259fd1e4a 100644
> --- a/fs/xfs/xfs_log_priv.h
> +++ b/fs/xfs/xfs_log_priv.h
> @@ -247,6 +247,7 @@ struct xfs_cil_ctx {
>  	struct xfs_log_vec	*lv_chain;	/* logvecs being pushed */
>  	struct list_head	iclog_entry;
>  	struct list_head	committing;	/* ctx committing list */
> +	wait_queue_head_t	push_wait;	/* background push throttle */
>  	struct work_struct	discard_endio_work;
>  };
>  
> -- 
> 2.23.0.rc1
> 

Re: [PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Dave Chinner]

On Mon, Sep 16, 2019 at 09:33:25AM -0700, Darrick J. Wong wrote:
> On Mon, Sep 09, 2019 at 11:51:58AM +1000, Dave Chinner wrote:
> > From: Dave Chinner <dchinner@redhat.com>
> > 
> > The current CIL size aggregation limit is 1/8th the log size. This
> > means for large logs we might be aggregating at least 250MB of dirty objects
> > in memory before the CIL is flushed to the journal. With CIL shadow
> > buffers sitting around, this means the CIL is often consuming >500MB
> > of temporary memory that is all allocated under GFP_NOFS conditions.
> > 
> > Flushing the CIL can take some time to do if there is other IO
> > ongoing, and can introduce substantial log force latency by itself.
> > It also pins the memory until the objects are in the AIL and can be
> > written back and reclaimed by shrinkers. Hence this threshold also
> > tends to determine the minimum amount of memory XFS can operate in
> > under heavy modification without triggering the OOM killer.
> > 
> > Modify the CIL space limit to prevent such huge amounts of pinned
> > metadata from aggregating. We can have 2MB of log IO in flight at
> > once, so limit aggregation to 16x this size. This threshold was
> > chosen as it little impact on performance (on 16-way fsmark) or log
> > traffic but pins a lot less memory on large logs especially under
> > heavy memory pressure.  An aggregation limit of 8x had 5-10%
> > performance degradation and a 50% increase in log throughput for
> > the same workload, so clearly that was too small for highly
> > concurrent workloads on large logs.
> 
> It would be nice to capture at least some of this reasoning in the
> already lengthy comment preceeding the #define....

A lot of it is already there, but I will revise it.

> 
> > This was found via trace analysis of AIL behaviour. e.g. insertion
> > from a single CIL flush:
> > 
> > xfs_ail_insert: old lsn 0/0 new lsn 1/3033090 type XFS_LI_INODE flags IN_AIL
> > 
> > $ grep xfs_ail_insert /mnt/scratch/s.t |grep "new lsn 1/3033090" |wc -l
> > 1721823
> > $
> > 
> > So there were 1.7 million objects inserted into the AIL from this
> > CIL checkpoint, the first at 2323.392108, the last at 2325.667566 which
> > was the end of the trace (i.e. it hadn't finished). Clearly a major
> > problem.
> > 
> > Signed-off-by: Dave Chinner <dchinner@redhat.com>
> > ---
> >  fs/xfs/xfs_log_priv.h | 3 ++-
> >  1 file changed, 2 insertions(+), 1 deletion(-)
> > 
> > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > index b880c23cb6e4..187a43ffeaf7 100644
> > --- a/fs/xfs/xfs_log_priv.h
> > +++ b/fs/xfs/xfs_log_priv.h
> > @@ -329,7 +329,8 @@ struct xfs_cil {
> >   * enforced to ensure we stay within our maximum checkpoint size bounds.
> >   * threshold, yet give us plenty of space for aggregation on large logs.
> 
> ...also, does XLOG_CIL_SPACE_LIMIT correspond to "a lower threshold at
> which background pushing is attempted", or "a separate, higher bound"?
> I think it's the first (????) but ... I don't know.  The name made me
> think it was the second, but the single use of the symbol suggests the
> first. :)

See, the comment here talks about two limits, because that was how
the initial implementation worked - the background CIL push was not
async, so there was some juggling done to prevent new commits from
blocking on background pushes in progress unless the size was
actually growing to large.  This patch pretty much describes the
whole issue here:

https://lore.kernel.org/linux-xfs/1285552073-14663-2-git-send-email-david@fromorbit.com/

That's in commit 80168676ebfe ("xfs: force background CIL push under
sustained load") which went into 2.6.38 or so. The cause of the
problem in that case was concurrent transaction commit load causing
lock contention and preventing a background push from getting the
context lock to do the actual push.

The hard limit in the CIL code was dropped when the background push
was converted to run asynchronously to use a work queue in 2012 as
it allowed the locking to be changed (down_write_trylock ->
down_write) to turn it into a transaction commit barrier while the
contexts are switched over.  That was done in 2012 via commit
4c2d542f2e78 ("xfs: Do background CIL flushes via a workqueue") and
so we haven't actually capped CIL checkpoint sizes since 2012.

Essentially, the comment you point out documents the two limits from
the original code, and this commit is restoring that behaviour for
background CIL pushes....

I'll do some work to update it all.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH 2/2] xfs: hard limit the background CIL push

[Dave Chinner]

On Mon, Sep 16, 2019 at 09:42:55AM -0700, Darrick J. Wong wrote:
> On Mon, Sep 09, 2019 at 11:51:59AM +1000, Dave Chinner wrote:
> > From: Dave Chinner <dchinner@redhat.com>
> > 
> > In certain situations the background CIL push can be indefinitely
> > delayed. While we have workarounds from the obvious cases now, it
> > doesn't solve the underlying issue. This issue is that there is no
> > upper limit on the CIL where we will either force or wait for
> > a background push to start, hence allowing the CIL to grow without
> > bound until it consumes all log space.
> > 
> > To fix this, add a new wait queue to the CIL which allows background
> > pushes to wait for the CIL context to be switched out. This happens
> > when the push starts, so it will allow us to block incoming
> > transaction commit completion until the push has started. This will
> > only affect processes that are running modifications, and only when
> > the CIL threshold has been significantly overrun.
> > 
> > This has no apparent impact on performance, and doesn't even trigger
> > until over 45 million inodes had been created in a 16-way fsmark
> > test on a 2GB log. That was limiting at 64MB of log space used, so
> > the active CIL size is only about 3% of the total log in that case.
> > The concurrent removal of those files did not trigger the background
> > sleep at all.
> > 
> > Signed-off-by: Dave Chinner <dchinner@redhat.com>
> > ---
> >  fs/xfs/xfs_log_cil.c  | 30 +++++++++++++++++++++++++-----
> >  fs/xfs/xfs_log_priv.h |  1 +
> >  2 files changed, 26 insertions(+), 5 deletions(-)
> > 
> > diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> > index ef652abd112c..eec9b32f5e08 100644
> > --- a/fs/xfs/xfs_log_cil.c
> > +++ b/fs/xfs/xfs_log_cil.c
> > @@ -670,6 +670,11 @@ xlog_cil_push(
> >  	push_seq = cil->xc_push_seq;
> >  	ASSERT(push_seq <= ctx->sequence);
> >  
> > +	/*
> > +	 * Wake up any background push waiters now this context is being pushed.
> > +	 */
> > +	wake_up_all(&ctx->push_wait);
> > +
> >  	/*
> >  	 * Check if we've anything to push. If there is nothing, then we don't
> >  	 * move on to a new sequence number and so we have to be able to push
> > @@ -746,6 +751,7 @@ xlog_cil_push(
> >  	 */
> >  	INIT_LIST_HEAD(&new_ctx->committing);
> >  	INIT_LIST_HEAD(&new_ctx->busy_extents);
> > +	init_waitqueue_head(&new_ctx->push_wait);
> >  	new_ctx->sequence = ctx->sequence + 1;
> >  	new_ctx->cil = cil;
> >  	cil->xc_ctx = new_ctx;
> > @@ -898,7 +904,7 @@ xlog_cil_push_work(
> >   * checkpoint), but commit latency and memory usage limit this to a smaller
> >   * size.
> >   */
> > -static void
> > +static bool
> >  xlog_cil_push_background(
> >  	struct xlog	*log)
> >  {
> > @@ -915,14 +921,28 @@ xlog_cil_push_background(
> >  	 * space available yet.
> >  	 */
> >  	if (cil->xc_ctx->space_used < XLOG_CIL_SPACE_LIMIT(log))
> > -		return;
> > +		return false;
> >  
> >  	spin_lock(&cil->xc_push_lock);
> >  	if (cil->xc_push_seq < cil->xc_current_sequence) {
> >  		cil->xc_push_seq = cil->xc_current_sequence;
> >  		queue_work(log->l_mp->m_cil_workqueue, &cil->xc_push_work);
> >  	}
> > +
> > +	/*
> > +	 * If we are well over the space limit, throttle the work that is being
> > +	 * done until the push work on this context has begun. This will prevent
> > +	 * the CIL from violating maximum transaction size limits if the CIL
> > +	 * push is delayed for some reason.
> > +	 */
> > +	if (cil->xc_ctx->space_used > XLOG_CIL_SPACE_LIMIT(log) * 2) {
> > +		up_read(&cil->xc_ctx_lock);
> > +		trace_printk("CIL space used %d", cil->xc_ctx->space_used);
> 
> Needs a real tracepoint before this drops RFC status.

Ok, that was just debugging stuff I forgot to remove, but I can turn
it into a real tracepoint if you want.

> 
> > +		xlog_wait(&cil->xc_ctx->push_wait, &cil->xc_push_lock);
> > +		return true;
> > +	}
> >  	spin_unlock(&cil->xc_push_lock);
> > +	return false;
> >  
> >  }
> >  
> > @@ -1038,9 +1058,8 @@ xfs_log_commit_cil(
> >  		if (lip->li_ops->iop_committing)
> >  			lip->li_ops->iop_committing(lip, xc_commit_lsn);
> >  	}
> > -	xlog_cil_push_background(log);
> > -
> > -	up_read(&cil->xc_ctx_lock);
> > +	if (!xlog_cil_push_background(log))
> > +		up_read(&cil->xc_ctx_lock);
> 
> Hmmmm... the return value here tell us if ctx_lock has been dropped.
> /me wonders if this would be cleaner if xlog_cil_push_background
> returned having called up_read...?

I thought about that - was on the fence about what to do. I'll
change it to be unconditional.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH 2/2] xfs: hard limit the background CIL push

[Darrick J. Wong]

On Wed, Sep 25, 2019 at 08:36:25AM +1000, Dave Chinner wrote:
> On Mon, Sep 16, 2019 at 09:42:55AM -0700, Darrick J. Wong wrote:
> > On Mon, Sep 09, 2019 at 11:51:59AM +1000, Dave Chinner wrote:
> > > From: Dave Chinner <dchinner@redhat.com>
> > > 
> > > In certain situations the background CIL push can be indefinitely
> > > delayed. While we have workarounds from the obvious cases now, it
> > > doesn't solve the underlying issue. This issue is that there is no
> > > upper limit on the CIL where we will either force or wait for
> > > a background push to start, hence allowing the CIL to grow without
> > > bound until it consumes all log space.
> > > 
> > > To fix this, add a new wait queue to the CIL which allows background
> > > pushes to wait for the CIL context to be switched out. This happens
> > > when the push starts, so it will allow us to block incoming
> > > transaction commit completion until the push has started. This will
> > > only affect processes that are running modifications, and only when
> > > the CIL threshold has been significantly overrun.
> > > 
> > > This has no apparent impact on performance, and doesn't even trigger
> > > until over 45 million inodes had been created in a 16-way fsmark
> > > test on a 2GB log. That was limiting at 64MB of log space used, so
> > > the active CIL size is only about 3% of the total log in that case.
> > > The concurrent removal of those files did not trigger the background
> > > sleep at all.
> > > 
> > > Signed-off-by: Dave Chinner <dchinner@redhat.com>
> > > ---
> > >  fs/xfs/xfs_log_cil.c  | 30 +++++++++++++++++++++++++-----
> > >  fs/xfs/xfs_log_priv.h |  1 +
> > >  2 files changed, 26 insertions(+), 5 deletions(-)
> > > 
> > > diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> > > index ef652abd112c..eec9b32f5e08 100644
> > > --- a/fs/xfs/xfs_log_cil.c
> > > +++ b/fs/xfs/xfs_log_cil.c
> > > @@ -670,6 +670,11 @@ xlog_cil_push(
> > >  	push_seq = cil->xc_push_seq;
> > >  	ASSERT(push_seq <= ctx->sequence);
> > >  
> > > +	/*
> > > +	 * Wake up any background push waiters now this context is being pushed.
> > > +	 */
> > > +	wake_up_all(&ctx->push_wait);
> > > +
> > >  	/*
> > >  	 * Check if we've anything to push. If there is nothing, then we don't
> > >  	 * move on to a new sequence number and so we have to be able to push
> > > @@ -746,6 +751,7 @@ xlog_cil_push(
> > >  	 */
> > >  	INIT_LIST_HEAD(&new_ctx->committing);
> > >  	INIT_LIST_HEAD(&new_ctx->busy_extents);
> > > +	init_waitqueue_head(&new_ctx->push_wait);
> > >  	new_ctx->sequence = ctx->sequence + 1;
> > >  	new_ctx->cil = cil;
> > >  	cil->xc_ctx = new_ctx;
> > > @@ -898,7 +904,7 @@ xlog_cil_push_work(
> > >   * checkpoint), but commit latency and memory usage limit this to a smaller
> > >   * size.
> > >   */
> > > -static void
> > > +static bool
> > >  xlog_cil_push_background(
> > >  	struct xlog	*log)
> > >  {
> > > @@ -915,14 +921,28 @@ xlog_cil_push_background(
> > >  	 * space available yet.
> > >  	 */
> > >  	if (cil->xc_ctx->space_used < XLOG_CIL_SPACE_LIMIT(log))
> > > -		return;
> > > +		return false;
> > >  
> > >  	spin_lock(&cil->xc_push_lock);
> > >  	if (cil->xc_push_seq < cil->xc_current_sequence) {
> > >  		cil->xc_push_seq = cil->xc_current_sequence;
> > >  		queue_work(log->l_mp->m_cil_workqueue, &cil->xc_push_work);
> > >  	}
> > > +
> > > +	/*
> > > +	 * If we are well over the space limit, throttle the work that is being
> > > +	 * done until the push work on this context has begun. This will prevent
> > > +	 * the CIL from violating maximum transaction size limits if the CIL
> > > +	 * push is delayed for some reason.
> > > +	 */
> > > +	if (cil->xc_ctx->space_used > XLOG_CIL_SPACE_LIMIT(log) * 2) {
> > > +		up_read(&cil->xc_ctx_lock);
> > > +		trace_printk("CIL space used %d", cil->xc_ctx->space_used);
> > 
> > Needs a real tracepoint before this drops RFC status.
> 
> Ok, that was just debugging stuff I forgot to remove, but I can turn
> it into a real tracepoint if you want.

<shrug> You could drop it too; I was just point out the trace_printk.

(For those of you following at home, trace_printk calls generate huge
debugging warnings at module load time.)

> > 
> > > +		xlog_wait(&cil->xc_ctx->push_wait, &cil->xc_push_lock);
> > > +		return true;
> > > +	}
> > >  	spin_unlock(&cil->xc_push_lock);
> > > +	return false;
> > >  
> > >  }
> > >  
> > > @@ -1038,9 +1058,8 @@ xfs_log_commit_cil(
> > >  		if (lip->li_ops->iop_committing)
> > >  			lip->li_ops->iop_committing(lip, xc_commit_lsn);
> > >  	}
> > > -	xlog_cil_push_background(log);
> > > -
> > > -	up_read(&cil->xc_ctx_lock);
> > > +	if (!xlog_cil_push_background(log))
> > > +		up_read(&cil->xc_ctx_lock);
> > 
> > Hmmmm... the return value here tell us if ctx_lock has been dropped.
> > /me wonders if this would be cleaner if xlog_cil_push_background
> > returned having called up_read...?
> 
> I thought about that - was on the fence about what to do. I'll
> change it to be unconditional.

<nod>

--D

> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com

Re: [PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Brian Foster]

On Wed, Sep 25, 2019 at 08:29:01AM +1000, Dave Chinner wrote:
> On Mon, Sep 16, 2019 at 09:33:25AM -0700, Darrick J. Wong wrote:
> > On Mon, Sep 09, 2019 at 11:51:58AM +1000, Dave Chinner wrote:
> > > From: Dave Chinner <dchinner@redhat.com>
> > > 
> > > The current CIL size aggregation limit is 1/8th the log size. This
> > > means for large logs we might be aggregating at least 250MB of dirty objects
> > > in memory before the CIL is flushed to the journal. With CIL shadow
> > > buffers sitting around, this means the CIL is often consuming >500MB
> > > of temporary memory that is all allocated under GFP_NOFS conditions.
> > > 
> > > Flushing the CIL can take some time to do if there is other IO
> > > ongoing, and can introduce substantial log force latency by itself.
> > > It also pins the memory until the objects are in the AIL and can be
> > > written back and reclaimed by shrinkers. Hence this threshold also
> > > tends to determine the minimum amount of memory XFS can operate in
> > > under heavy modification without triggering the OOM killer.
> > > 
> > > Modify the CIL space limit to prevent such huge amounts of pinned
> > > metadata from aggregating. We can have 2MB of log IO in flight at
> > > once, so limit aggregation to 16x this size. This threshold was
> > > chosen as it little impact on performance (on 16-way fsmark) or log
> > > traffic but pins a lot less memory on large logs especially under
> > > heavy memory pressure.  An aggregation limit of 8x had 5-10%
> > > performance degradation and a 50% increase in log throughput for
> > > the same workload, so clearly that was too small for highly
> > > concurrent workloads on large logs.
> > 
> > It would be nice to capture at least some of this reasoning in the
> > already lengthy comment preceeding the #define....
> 
> A lot of it is already there, but I will revise it.
> 
> > 
> > > This was found via trace analysis of AIL behaviour. e.g. insertion
> > > from a single CIL flush:
> > > 
> > > xfs_ail_insert: old lsn 0/0 new lsn 1/3033090 type XFS_LI_INODE flags IN_AIL
> > > 
> > > $ grep xfs_ail_insert /mnt/scratch/s.t |grep "new lsn 1/3033090" |wc -l
> > > 1721823
> > > $
> > > 
> > > So there were 1.7 million objects inserted into the AIL from this
> > > CIL checkpoint, the first at 2323.392108, the last at 2325.667566 which
> > > was the end of the trace (i.e. it hadn't finished). Clearly a major
> > > problem.
> > > 
> > > Signed-off-by: Dave Chinner <dchinner@redhat.com>
> > > ---
> > >  fs/xfs/xfs_log_priv.h | 3 ++-
> > >  1 file changed, 2 insertions(+), 1 deletion(-)
> > > 
> > > diff --git a/fs/xfs/xfs_log_priv.h b/fs/xfs/xfs_log_priv.h
> > > index b880c23cb6e4..187a43ffeaf7 100644
> > > --- a/fs/xfs/xfs_log_priv.h
> > > +++ b/fs/xfs/xfs_log_priv.h
> > > @@ -329,7 +329,8 @@ struct xfs_cil {
> > >   * enforced to ensure we stay within our maximum checkpoint size bounds.
> > >   * threshold, yet give us plenty of space for aggregation on large logs.
> > 
> > ...also, does XLOG_CIL_SPACE_LIMIT correspond to "a lower threshold at
> > which background pushing is attempted", or "a separate, higher bound"?
> > I think it's the first (????) but ... I don't know.  The name made me
> > think it was the second, but the single use of the symbol suggests the
> > first. :)
> 
> See, the comment here talks about two limits, because that was how
> the initial implementation worked - the background CIL push was not
> async, so there was some juggling done to prevent new commits from
> blocking on background pushes in progress unless the size was
> actually growing to large.  This patch pretty much describes the
> whole issue here:
> 
> https://lore.kernel.org/linux-xfs/1285552073-14663-2-git-send-email-david@fromorbit.com/
> 
> That's in commit 80168676ebfe ("xfs: force background CIL push under
> sustained load") which went into 2.6.38 or so. The cause of the
> problem in that case was concurrent transaction commit load causing
> lock contention and preventing a background push from getting the
> context lock to do the actual push.
> 

More related to the next patch, but what prevents a similar but
generally unbound concurrent workload from exceeding the new hard limit
once transactions start to block post commit?

Brian

> The hard limit in the CIL code was dropped when the background push
> was converted to run asynchronously to use a work queue in 2012 as
> it allowed the locking to be changed (down_write_trylock ->
> down_write) to turn it into a transaction commit barrier while the
> contexts are switched over.  That was done in 2012 via commit
> 4c2d542f2e78 ("xfs: Do background CIL flushes via a workqueue") and
> so we haven't actually capped CIL checkpoint sizes since 2012.
> 
> Essentially, the comment you point out documents the two limits from
> the original code, and this commit is restoring that behaviour for
> background CIL pushes....
> 
> I'll do some work to update it all.
> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com

Re: [PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Dave Chinner]

On Wed, Sep 25, 2019 at 08:08:59AM -0400, Brian Foster wrote:
> On Wed, Sep 25, 2019 at 08:29:01AM +1000, Dave Chinner wrote:
> > That's in commit 80168676ebfe ("xfs: force background CIL push under
> > sustained load") which went into 2.6.38 or so. The cause of the
> > problem in that case was concurrent transaction commit load causing
> > lock contention and preventing a background push from getting the
> > context lock to do the actual push.
> > 
> 
> More related to the next patch, but what prevents a similar but
> generally unbound concurrent workload from exceeding the new hard limit
> once transactions start to block post commit?

The new code, like the original code, is not actually a "hard" limit.
It's essentially just throttles ongoing work until the CIL push
starts. In this case, it forces the current process to give up the
CPU immediately once over the CIL high limit, which allows the
workqueue to run the push work straight away.

I thought about making it a "hard limit" by blocking before the CIL
insert, but that's no guarantee that by the time we get woken and
add the new commit to the CIL that this new context has not already
gone over the hard limit. i.e. we block the unbound concurrency
before commit, then let it all go in a thundering herd on the new
context and immeidately punch that way over the hard threshold
again. To avoid this, we'd probably need a CIL ticket and grant
mechanism to make CIL insertion FIFO and wakeups limited by
remaining space in the CIL. I'm not sure we actually need such a
complex solution, especially considering the potential serialisation
problems it introduces in what is a highly concurrent fast path...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [PATCH 1/2] xfs: Lower CIL flush limit for large logs

[Brian Foster]

On Sat, Sep 28, 2019 at 08:47:58AM +1000, Dave Chinner wrote:
> On Wed, Sep 25, 2019 at 08:08:59AM -0400, Brian Foster wrote:
> > On Wed, Sep 25, 2019 at 08:29:01AM +1000, Dave Chinner wrote:
> > > That's in commit 80168676ebfe ("xfs: force background CIL push under
> > > sustained load") which went into 2.6.38 or so. The cause of the
> > > problem in that case was concurrent transaction commit load causing
> > > lock contention and preventing a background push from getting the
> > > context lock to do the actual push.
> > > 
> > 
> > More related to the next patch, but what prevents a similar but
> > generally unbound concurrent workload from exceeding the new hard limit
> > once transactions start to block post commit?
> 
> The new code, like the original code, is not actually a "hard" limit.
> It's essentially just throttles ongoing work until the CIL push
> starts. In this case, it forces the current process to give up the
> CPU immediately once over the CIL high limit, which allows the
> workqueue to run the push work straight away.
> 
> I thought about making it a "hard limit" by blocking before the CIL
> insert, but that's no guarantee that by the time we get woken and
> add the new commit to the CIL that this new context has not already
> gone over the hard limit. i.e. we block the unbound concurrency
> before commit, then let it all go in a thundering herd on the new
> context and immeidately punch that way over the hard threshold
> again. To avoid this, we'd probably need a CIL ticket and grant
> mechanism to make CIL insertion FIFO and wakeups limited by
> remaining space in the CIL. I'm not sure we actually need such a
> complex solution, especially considering the potential serialisation
> problems it introduces in what is a highly concurrent fast path...
> 

Ok. The latter is more of what I'd expect to see if the objective is
truly to hard cap CIL size, FWIW. This seems more reasonable if the
objective is to yield committers under overloaded CIL conditions, with
the caveat that CIL size is still not hard capped, so long as the
documentation and whatnot is updated to more accurately reflect the
implementation (and at a glance, it looks like that has happened in the
next version..).

Brian

> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com