* Re: [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement
[not found] <Yti6PccitrglBtIj@xsang-OptiPlex-9020>
@ 2022-07-21 22:01 ` Dave Chinner
2022-08-02 6:36 ` [LKP] " Yin, Fengwei
0 siblings, 1 reply; 4+ messages in thread
From: Dave Chinner @ 2022-07-21 22:01 UTC (permalink / raw)
To: kernel test robot
Cc: Dave Chinner, Darrick J. Wong, LKML, Linux Memory Management List,
linux-xfs, lkp, lkp, ying.huang, feng.tang, zhengjun.xing,
fengwei.yin
On Thu, Jul 21, 2022 at 10:30:21AM +0800, kernel test robot wrote:
>
>
> Greeting,
>
> FYI, we noticed a 58.4% improvement of stress-ng.xattr.ops_per_sec due to commit:
>
>
> commit: 016a23388cdcb2740deb1379dc408f21c84efb11 ("xfs: Add order IDs to log items in CIL")
> https://git.kernel.org/cgit/linux/kernel/git/next/linux-next.git master
>
> in testcase: stress-ng
> on test machine: 96 threads 2 sockets Ice Lake with 256G memory
> with following parameters:
>
> nr_threads: 10%
> disk: 1HDD
> testtime: 60s
> fs: xfs
> class: filesystem
> test: xattr
> cpufreq_governor: performance
> ucode: 0xb000280
>
>
>
>
>
>
> Details are as below:
> -------------------------------------------------------------------------------------------------->
>
>
> To reproduce:
>
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> sudo bin/lkp install job.yaml # job file is attached in this email
> bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
> sudo bin/lkp run generated-yaml-file
>
> # if come across any failure that blocks the test,
> # please remove ~/.lkp and /lkp dir to run from a clean state.
>
> =========================================================================================
> class/compiler/cpufreq_governor/disk/fs/kconfig/nr_threads/rootfs/tbox_group/test/testcase/testtime/ucode:
> filesystem/gcc-11/performance/1HDD/xfs/x86_64-rhel-8.3/10%/debian-11.1-x86_64-20220510.cgz/lkp-icl-2sp1/xattr/stress-ng/60s/0xb000280
>
> commit:
> df7a4a2134 ("xfs: convert CIL busy extents to per-cpu")
> 016a23388c ("xfs: Add order IDs to log items in CIL")
This bisect looks like it's identified the wrong commit. The reason
things went faster was:
> df7a4a2134b0a201 016a23388cdcb2740deb1379dc4
> ---------------- ---------------------------
> %stddev %change %stddev
> \ | \
.....
> 25.64 ± 8% -25.6 0.00 perf-profile.calltrace.cycles-pp.native_queued_spin_lock_slowpath._raw_spin_lock.xlog_cil_insert_items.xlog_cil_commit.__xfs_trans_commit
A huge amount of spinlock contention in the xlog_commit_cil() path
went away. The commit identified doesn't remove/change any
spinlocks, it actually adds more overhead to the critical section of
the above spinlock in preparation for removing said spinlocks.
That removal happens in the next commit in that series - c0fb4765c508 ("xfs:
convert CIL to unordered per cpu lists") - so I'd be expecting a
bisect to demonstrate that the spinlock contention goes away with
the commit that removed the spinlocks (as it does in all the testing
of this I've done over the past 2 years), not the commit this bisect
identified. Hence I think the bisect went wrong somewhere...
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [LKP] Re: [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement
2022-07-21 22:01 ` [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement Dave Chinner
@ 2022-08-02 6:36 ` Yin, Fengwei
2022-08-03 1:02 ` Dave Chinner
0 siblings, 1 reply; 4+ messages in thread
From: Yin, Fengwei @ 2022-08-02 6:36 UTC (permalink / raw)
To: Dave Chinner, kernel test robot
Cc: Dave Chinner, Darrick J. Wong, LKML, Linux Memory Management List,
linux-xfs, lkp, lkp
Hi Dave,
On 7/22/2022 6:01 AM, Dave Chinner wrote:
> A huge amount of spinlock contention in the xlog_commit_cil() path
> went away. The commit identified doesn't remove/change any
> spinlocks, it actually adds more overhead to the critical section of
> the above spinlock in preparation for removing said spinlocks.
>
> That removal happens in the next commit in that series - c0fb4765c508 ("xfs:
> convert CIL to unordered per cpu lists") - so I'd be expecting a
> bisect to demonstrate that the spinlock contention goes away with
> the commit that removed the spinlocks (as it does in all the testing
> of this I've done over the past 2 years), not the commit this bisect
> identified. Hence I think the bisect went wrong somewhere...
We did some investigation and got:
commit:
df7a4a2134b0a ("xfs: convert CIL busy extents to per-cpu")
016a23388cdcb ("xfs: Add order IDs to log items in CIL")
c0fb4765c5086 ("xfs: convert CIL to unordered per cpu lists")
df7a4a2134b0a201 016a23388cdcb2740deb1379dc4 c0fb4765c5086cfd00f1158f5f4
---------------- --------------------------- ---------------------------
%stddev %change %stddev %change %stddev
\ | \ | \
62.07 +0.0% 62.09 -0.0% 62.06 stress-ng.time.elapsed_time
62.07 +0.0% 62.09 -0.0% 62.06 stress-ng.time.elapsed_time.max
2237 +0.0% 2237 +0.0% 2237 stress-ng.time.file_system_inputs
1842 ± 4% +16.9% 2152 ± 3% +17.6% 2166 stress-ng.time.involuntary_context_switches
551.00 -0.3% 549.10 -0.3% 549.40 stress-ng.time.major_page_faults
6376 -1.1% 6305 ± 2% +0.6% 6416 stress-ng.time.maximum_resident_set_size
9704 -0.3% 9676 -0.1% 9691 stress-ng.time.minor_page_faults
4096 +0.0% 4096 +0.0% 4096 stress-ng.time.page_size
841.90 -2.4% 821.70 -2.4% 821.90 stress-ng.time.percent_of_cpu_this_job_got
512.83 -3.4% 495.24 -3.6% 494.18 stress-ng.time.system_time
10.05 ± 8% +52.3% 15.30 ± 3% +61.1% 16.19 ± 2% stress-ng.time.user_time
2325 ± 16% +66.5% 3873 ± 7% +70.3% 3962 ± 6% stress-ng.time.voluntary_context_switches
1544 ± 4% +54.4% 2385 +63.9% 2531 stress-ng.xattr.ops
Yes. commit c0fb4765c5086 ("xfs: convert CIL to unordered per cpu lists")
could bring performance gain also. But the most performance gain (54.4%)
is from commit 016a23388cdcb ("xfs: Add order IDs to log items in CIL").
Based on commit 016a23388cdcb and add following change:
diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
index 6bc540898e3a..7c6c91a0a12d 100644
--- a/fs/xfs/xfs_log_cil.c
+++ b/fs/xfs/xfs_log_cil.c
@@ -659,9 +659,14 @@ xlog_cil_insert_items(
continue;
lip->li_order_id = order;
- if (!list_empty(&lip->li_cil))
- continue;
- list_add_tail(&lip->li_cil, &cil->xc_cil);
+
+ /*
+ * Only move the item if it isn't already at the tail. This is
+ * to prevent a transient list_empty() state when reinserting
+ * an item that is already the only item in the CIL.
+ */
+ if (!list_is_last(&lip->li_cil, &cil->xc_cil))
+ list_move_tail(&lip->li_cil, &cil->xc_cil);
}
The performance will drop to the same level as commit df7a4a2134b0a
("xfs: convert CIL busy extents to per-cpu"):
commit:
016a23388cdcb2740deb1379dc408f21c84efb11
a8bef09e7d8e65207c8403e030a0965db43ce3de
016a23388cdcb274 a8bef09e7d8e65207c8403e030a
---------------- ---------------------------
%stddev %change %stddev
\ | \
62.06 -0.0% 62.05 stress-ng.time.elapsed_time
62.06 -0.0% 62.05 stress-ng.time.elapsed_time.max
2237 +0.0% 2237 stress-ng.time.file_system_inputs
2226 -16.7% 1855 ± 4% stress-ng.time.involuntary_context_switches
549.00 +0.5% 551.67 stress-ng.time.major_page_faults
6286 +0.1% 6292 stress-ng.time.maximum_resident_set_size
9636 +0.1% 9641 stress-ng.time.minor_page_faults
4096 +0.0% 4096 stress-ng.time.page_size
823.00 +3.0% 847.33 stress-ng.time.percent_of_cpu_this_job_got
496.02 +4.2% 516.61 stress-ng.time.system_time
15.08 -38.1% 9.33 ± 4% stress-ng.time.user_time
4034 ± 3% -43.0% 2299 ± 6% stress-ng.time.voluntary_context_switches
2368 -37.4% 1482 ± 4% stress-ng.xattr.ops
Regards
Yin, Fengwei
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [LKP] Re: [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement
2022-08-02 6:36 ` [LKP] " Yin, Fengwei
@ 2022-08-03 1:02 ` Dave Chinner
2022-08-03 14:11 ` Yin, Fengwei
0 siblings, 1 reply; 4+ messages in thread
From: Dave Chinner @ 2022-08-03 1:02 UTC (permalink / raw)
To: Yin, Fengwei
Cc: kernel test robot, Dave Chinner, Darrick J. Wong, LKML,
Linux Memory Management List, linux-xfs, lkp, lkp
On Tue, Aug 02, 2022 at 02:36:00PM +0800, Yin, Fengwei wrote:
> Hi Dave,
>
> On 7/22/2022 6:01 AM, Dave Chinner wrote:
> > A huge amount of spinlock contention in the xlog_commit_cil() path
> > went away. The commit identified doesn't remove/change any
> > spinlocks, it actually adds more overhead to the critical section of
> > the above spinlock in preparation for removing said spinlocks.
> >
> > That removal happens in the next commit in that series - c0fb4765c508 ("xfs:
> > convert CIL to unordered per cpu lists") - so I'd be expecting a
> > bisect to demonstrate that the spinlock contention goes away with
> > the commit that removed the spinlocks (as it does in all the testing
> > of this I've done over the past 2 years), not the commit this bisect
> > identified. Hence I think the bisect went wrong somewhere...
>
> We did some investigation and got:
>
> commit:
> df7a4a2134b0a ("xfs: convert CIL busy extents to per-cpu")
> 016a23388cdcb ("xfs: Add order IDs to log items in CIL")
> c0fb4765c5086 ("xfs: convert CIL to unordered per cpu lists")
>
> df7a4a2134b0a201 016a23388cdcb2740deb1379dc4 c0fb4765c5086cfd00f1158f5f4
> ---------------- --------------------------- ---------------------------
> %stddev %change %stddev %change %stddev
> \ | \ | \
> 62.07 +0.0% 62.09 -0.0% 62.06 stress-ng.time.elapsed_time
> 62.07 +0.0% 62.09 -0.0% 62.06 stress-ng.time.elapsed_time.max
> 2237 +0.0% 2237 +0.0% 2237 stress-ng.time.file_system_inputs
> 1842 ± 4% +16.9% 2152 ± 3% +17.6% 2166 stress-ng.time.involuntary_context_switches
> 551.00 -0.3% 549.10 -0.3% 549.40 stress-ng.time.major_page_faults
> 6376 -1.1% 6305 ± 2% +0.6% 6416 stress-ng.time.maximum_resident_set_size
> 9704 -0.3% 9676 -0.1% 9691 stress-ng.time.minor_page_faults
> 4096 +0.0% 4096 +0.0% 4096 stress-ng.time.page_size
> 841.90 -2.4% 821.70 -2.4% 821.90 stress-ng.time.percent_of_cpu_this_job_got
> 512.83 -3.4% 495.24 -3.6% 494.18 stress-ng.time.system_time
> 10.05 ± 8% +52.3% 15.30 ± 3% +61.1% 16.19 ± 2% stress-ng.time.user_time
> 2325 ± 16% +66.5% 3873 ± 7% +70.3% 3962 ± 6% stress-ng.time.voluntary_context_switches
> 1544 ± 4% +54.4% 2385 +63.9% 2531 stress-ng.xattr.ops
>
> Yes. commit c0fb4765c5086 ("xfs: convert CIL to unordered per cpu lists")
> could bring performance gain also. But the most performance gain (54.4%)
> is from commit 016a23388cdcb ("xfs: Add order IDs to log items in CIL").
>
>
> Based on commit 016a23388cdcb and add following change:
>
> diff --git a/fs/xfs/xfs_log_cil.c b/fs/xfs/xfs_log_cil.c
> index 6bc540898e3a..7c6c91a0a12d 100644
> --- a/fs/xfs/xfs_log_cil.c
> +++ b/fs/xfs/xfs_log_cil.c
> @@ -659,9 +659,14 @@ xlog_cil_insert_items(
> continue;
>
> lip->li_order_id = order;
> - if (!list_empty(&lip->li_cil))
> - continue;
> - list_add_tail(&lip->li_cil, &cil->xc_cil);
> +
> + /*
> + * Only move the item if it isn't already at the tail. This is
> + * to prevent a transient list_empty() state when reinserting
> + * an item that is already the only item in the CIL.
> + */
> + if (!list_is_last(&lip->li_cil, &cil->xc_cil))
> + list_move_tail(&lip->li_cil, &cil->xc_cil);
> }
>
> The performance will drop to the same level as commit df7a4a2134b0a
> ("xfs: convert CIL busy extents to per-cpu"):
Thanks for looking into this.
This looks like a case of the workload being right at the threshold
of catastrophic cache line contention breakdown on this workload.
i.e. a single extra exclusive cache miss inside the spin lock
critical region is sufficient overload the memory bus bandwidth and
so the cacheline contention on the lock from nothing to "all the
spare CPU time is spent contending on the spin lock cache line".
IOWs, the lock contention problem doesn't go away with this commit,
it just falls back under the critical threshold where the cache
coherency protocol runs out of memory bus bandwidth bouncing dirty
cachelines around all the CPU cores and so causes spinlock overhead
to go from linear cost to exponential cost.
That a single cacheline miss avoids all the spinlock contention is
just pure luck - it'll come back if other work is being done on the
machine that consumes enough memory bandwidth to push this back over
the edge. Hence the real fix for the spinlock contention problem is
still the patch I pointed out that removes the spinlocks
altogether...
Cheers,
Dave.
--
Dave Chinner
david@fromorbit.com
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [LKP] Re: [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement
2022-08-03 1:02 ` Dave Chinner
@ 2022-08-03 14:11 ` Yin, Fengwei
0 siblings, 0 replies; 4+ messages in thread
From: Yin, Fengwei @ 2022-08-03 14:11 UTC (permalink / raw)
To: Dave Chinner
Cc: kernel test robot, Dave Chinner, Darrick J. Wong, LKML,
Linux Memory Management List, linux-xfs, lkp, lkp
Hi Dave,
On 8/3/2022 9:02 AM, Dave Chinner wrote:
> That a single cacheline miss avoids all the spinlock contention is
> just pure luck - it'll come back if other work is being done on the
> machine that consumes enough memory bandwidth to push this back over
> the edge.
Agree. We did see some strange performance boost which can't be connected
to the code change. And worried later unrelated change reduce the
mysterious performance gain (and report it as regression).
Regards
Yin, Fengwei
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2022-08-03 14:11 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <Yti6PccitrglBtIj@xsang-OptiPlex-9020>
2022-07-21 22:01 ` [xfs] 016a23388c: stress-ng.xattr.ops_per_sec 58.4% improvement Dave Chinner
2022-08-02 6:36 ` [LKP] " Yin, Fengwei
2022-08-03 1:02 ` Dave Chinner
2022-08-03 14:11 ` Yin, Fengwei
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox