Re: [axboe-block:xfs-async-dio] [fs] f9f8b03900: stress-ng.msg.ops_per_sec 29.3% improvement

[Jens Axboe <axboe@kernel.dk>]

On 8/2/23 7:52?AM, kernel test robot wrote:
> 
> hi, Jens Axboe,
> 
> though all results in below formal report are improvement, Fengwei (CCed)
> checked on another Intel(R) Xeon(R) Gold 6336Y CPU @ 2.40GHz (Ice Lake)
> (sorry, since this machine doesn't belong to our team, we cannot intergrate
> the results in our report, only can heads-up you here), and found ~30%
> stress-ng.msg.ops_per_sec regression.
> 
> but by disable the TRACEPOINT, the regression will disappear.
> 
> Fengwei also tried to remove following section from the patch:
> @@ -351,7 +361,8 @@ enum rw_hint {
>  	{ IOCB_WRITE,		"WRITE" }, \
>  	{ IOCB_WAITQ,		"WAITQ" }, \
>  	{ IOCB_NOIO,		"NOIO" }, \
> -	{ IOCB_ALLOC_CACHE,	"ALLOC_CACHE" }
> +	{ IOCB_ALLOC_CACHE,	"ALLOC_CACHE" }, \
> +	{ IOCB_DIO_DEFER,	"DIO_DEFER" }
> 
> the regression is also gone.
> 
> Fengwei also mentioned to us that his understanding is this code update changed
> the data section layout of the kernel. Otherwise, it's hard to explain the
> regression/improvement this commit could bring.
> 
> these information and below formal report FYI.

Very funky. I ran this on my 256 thread box, and removing the
IOCB_DIO_DEFER (which is now IOCB_CALLER_COMP) trace point definition, I
get:

stress-ng: metrc: [4148] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s
stress-ng: metrc: [4148]                           (secs)    (secs)    (secs)   (real time) (usr+sys time)
stress-ng: metrc: [4148] msg           1626997107     60.61    171.63   4003.65  26845470.19      389673.05

and with it being the way it is in the branch:

stress-ng: metrc: [3678] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s
stress-ng: metrc: [3678]                           (secs)    (secs)    (secs)   (real time) (usr+sys time)
stress-ng: metrc: [3678] msg           1287795248     61.25    140.26   3755.50  21025449.92      330563.24

which is about a -21% bogo ops drop. Then I got a bit suspicious since
the previous strings fit in 64 bytes, and now they don't, and I simply
shortened the names so they still fit, as per below patch. With that,
the regression there is reclaimed.

That's as far as I've gotten yet, but I'm guessing we end up placing it
differently, maybe now overlapping with data that is dirtied? I didn't
profile it very much, just for an overview, and there's really nothing
to observe there. The task and system is clearly more idle when the
regression hits.
 

diff --git a/include/linux/fs.h b/include/linux/fs.h
index 1e6dbe309d52..52bd9e6a29ea 100644
--- a/include/linux/fs.h
+++ b/include/linux/fs.h
@@ -355,18 +355,18 @@ enum rw_hint {
 
 /* for use in trace events */
 #define TRACE_IOCB_STRINGS \
-	{ IOCB_HIPRI,		"HIPRI" }, \
+	{ IOCB_HIPRI,		"HPRI" }, \
 	{ IOCB_DSYNC,		"DSYNC" }, \
 	{ IOCB_SYNC,		"SYNC" }, \
-	{ IOCB_NOWAIT,		"NOWAIT" }, \
+	{ IOCB_NOWAIT,		"NWAIT" }, \
 	{ IOCB_APPEND,		"APPEND" }, \
-	{ IOCB_EVENTFD,		"EVENTFD"}, \
+	{ IOCB_EVENTFD,		"EVD"}, \
 	{ IOCB_DIRECT,		"DIRECT" }, \
 	{ IOCB_WRITE,		"WRITE" }, \
 	{ IOCB_WAITQ,		"WAITQ" }, \
 	{ IOCB_NOIO,		"NOIO" }, \
-	{ IOCB_ALLOC_CACHE,	"ALLOC_CACHE" }, \
-	{ IOCB_DIO_CALLER_COMP,	"CALLER_COMP" }
+	{ IOCB_ALLOC_CACHE,	"ALLOC" }, \
+	{ IOCB_DIO_CALLER_COMP,	"CALLER" }
 
 struct kiocb {
 	struct file		*ki_filp;

-- 
Jens Axboe