Re: [herbert-cryptodev-2.6:master] [rhashtable] e1d3422c95: stress-ng.syscall.ops_per_sec 98.9% regression

[Oliver Sang <oliver.sang@intel.com>]

hi, Breno Leitao,

On Fri, Jan 03, 2025 at 05:41:56AM -0800, Breno Leitao wrote:
> Hello "kernel robot" team,
> 
> First of all, thank you very much for running these tests against the
> linux kernel.

you are welcome!

> 
> I am trying to reproduce this report, and I would appreciate some help
> to understand what is being measured, and try to reproduce the reported
> problem.
> 
> On Fri, Dec 27, 2024 at 11:10:11AM +0800, kernel test robot wrote:
> > kernel test robot noticed a 98.9% regression of stress-ng.syscall.ops_per_sec on:
> 
> Is this metric coming from `bogo ops/s` from stress-ng?

yes, it's from bogo ops/s (real time).

one thing we want to mention is the test runs unstably upon e1d3422c95.
as below, %stddev for it reaches 67%.
not very stable for parent, either, but 7% is much better.

f916e44487f56df4 e1d3422c95f003eba241c176adf 
---------------- --------------------------- 
         %stddev     %change         %stddev
             \          |                \  
   4115705 ±  7%     -98.9%      45562 ± 67%  stress-ng.syscall.ops_per_sec

below is the raw data of 6 runs for e1d3422c95 in our tests.
  "stress-ng.syscall.ops_per_sec": [
    12892.83,
    98074.65,
    65206.14,
    11507.57,
    55012.11,
    30684.44
  ],

take that 55012.11 as example, (part of) the stress-ng output is:
stress-ng: metrc: [6604] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s CPU used per       RSS Max
stress-ng: metrc: [6604]                           (secs)    (secs)    (secs)   (real time) (usr+sys time) instance (%)          (KB)
stress-ng: metrc: [6604] syscall         8878630    161.39      9.86  31058.22     55012.11         285.78        85.94         10512


another thing we want to mention is we also notice a WARNING for this commit in
another test, so we reported
"[herbert-cryptodev-2.6:master] [rhashtable] e1d3422c95: WARNING:at_mm/util.c:#__kvmalloc_node_noprof"
in
https://lore.kernel.org/all/202412311213.4e69877e-lkp@intel.com/

not sure if it's related or could supply any hint?

> 
> I am trying to reproduce this problem, running the following script:
> https://download.01.org/0day-ci/archive/20241227/202412271017.cad7675-lkp@intel.com/repro-script
> 
> And I see the output like the one below, but, it is unclear to me what
> metric regressed stress-ng.syscall.ops_per_sec means exactly.  Would you
> mind helping me to understand what is stress-ng.syscall.ops_per_sec and
> how it maps to stress-ng metrics?
> 
> Output of `stress-ng --timeout 60 --times --verify --metrics --no-rand-seed --syscall 224`:
> 
> 	stress-ng: info:  [59621] setting to a 1 min, 0 secs run per stressor
> 	stress-ng: info:  [59621] dispatching hogs: 224 syscall
> 	stress-ng: info:  [59647] syscall: using method 'fast75'
> 	stress-ng: info:  [59647] syscall: 292 system call tests, 219 (75.0%) fastest non-failing tests fully exercised
> 	stress-ng: info:  [59647] syscall: Top 10 fastest system calls (timings in nanosecs):
> 	stress-ng: info:  [59647] syscall:               System Call   Avg (ns)   Min (ns)   Max (ns)
> 	stress-ng: info:  [59647] syscall:                  pkey_get      156.0        127        185
> 	stress-ng: info:  [59647] syscall:                      time      212.5        195        230
> 	stress-ng: info:  [59647] syscall:                  pkey_set      235.5        193        278
> 	stress-ng: info:  [59647] syscall:              gettimeofday      282.5        255        310
> 	stress-ng: info:  [59647] syscall:                    getcpu      457.0        388        526
> 	stress-ng: info:  [59647] syscall:           set_robust_list      791.5        745        838
> 	stress-ng: info:  [59647] syscall:                    getgid     1137.0        974       1300
> 	stress-ng: info:  [59647] syscall:                 setresuid     1146.0       1070       1222
> 	stress-ng: info:  [59647] syscall:                    getuid     1162.5        902       1423
> 	stress-ng: info:  [59647] syscall:                 setresgid     1211.5       1159       1264
> 	stress-ng: metrc: [59621] stressor       bogo ops real time  usr time  sys time   bogo ops/s     bogo ops/s CPU used per       RSS Max
> 	stress-ng: metrc: [59621]                           (secs)    (secs)    (secs)   (real time) (usr+sys time) instance (%)          (KB)
> 	stress-ng: metrc: [59621] syscall          114464     86.78      1.27    364.05      1318.95         313.33         1.88          4500
> 	stress-ng: info:  [59621] for a 98.30s run time:
> 	stress-ng: info:  [59621]    3538.93s available CPU time
> 	stress-ng: info:  [59621]       1.26s user time   (  0.04%)
> 	stress-ng: info:  [59621]     366.66s system time ( 10.36%)
> 	stress-ng: info:  [59621]     367.92s total time  ( 10.40%)
> 	stress-ng: info:  [59621] load average: 80.45 43.94 20.82
> 	stress-ng: info:  [59621] skipped: 0
> 	stress-ng: info:  [59621] passed: 224: syscall (224)
> 	stress-ng: info:  [59621] failed: 0
> 	stress-ng: info:  [59621] metrics untrustworthy: 0
> 	stress-ng: info:  [59621] successful run completed in 1 min, 38.30 secs
> 
> Thank you!
> --breno
>