[LU-16762] sanity 123ad fails on a local setup

• Type: Bug
• Resolution: Fixed
• Priority: Minor
• Fix Version/s: Lustre 2.16.0
• Severity: 3
• Assignee: Qian Yingjin
• Reporter: Alex Zhuravlev

Description

this test is introduced in LU-14139 statahead: add test for batch statahead processing

== sanity test 123ad: Verify batching statahead works correctly ========================================================== 09:48:12 (1682243292)

batching: statahead_max=32 statahead_batch_max=32
mdc.lustre-MDT0000-mdc-ffff94639828b000.batch_stats=0
mdc.lustre-MDT0001-mdc-ffff94639828b000.batch_stats=0
llite.lustre-ffff94639828b000.statahead_max=32
llite.lustre-ffff94639828b000.statahead_batch_max=32
seq.cli-lustre-OST0000-super.width=0x1ffffff
seq.cli-lustre-OST0001-super.width=0x1ffffff
bochs
mdc.lustre-MDT0000-mdc-ffff94639828b000.batch_stats=0
mdc.lustre-MDT0001-mdc-ffff94639828b000.batch_stats=0
striped dir -i1 -c2 -H crush2 /mnt/lustre/d123ad.sanity
total: 100 open/close in 0.21 seconds: 470.99 ops/second
llite.lustre-ffff94639828b000.statahead_max=0
101

real	0m0.176s
user	0m0.000s
sys	0m0.085s
ls -l 100 files without statahead: 0 sec
llite.lustre-ffff94639828b000.statahead_max=32
32
101

real	0m0.226s
user	0m0.022s
sys	0m0.135s
ls -l 100 files with statahead: 1 sec
statahead total: 32
statahead wrong: 7
agl total: 32
hit_total: 886
miss_total: 322
statahead was stopped, maybe too many locks held!
total: 900 open/close in 1.80 seconds: 499.58 ops/second
llite.lustre-ffff94639828b000.statahead_max=0
1001

real	0m0.870s
user	0m0.008s
sys	0m0.374s
ls -l 1000 files without statahead: 0 sec
llite.lustre-ffff94639828b000.statahead_max=32
32
1001

real	0m1.147s
user	0m0.077s
sys	0m0.396s
ls -l 1000 files with statahead: 1 sec
statahead total: 33
statahead wrong: 8
agl total: 33
hit_total: 886
miss_total: 335
statahead was stopped, maybe too many locks held!
 - open/close 5164 (time 1682243309.81 total 10.01 last 515.66)
total: 9000 open/close in 18.85 seconds: 477.41 ops/second
llite.lustre-ffff94639828b000.statahead_max=0
10001

real	0m14.353s
user	0m0.235s
sys	0m6.314s
ls -l 10000 files without statahead: 15 sec
llite.lustre-ffff94639828b000.statahead_max=32
32
10001

real	0m12.395s
user	0m0.193s
sys	0m5.184s
ls -l 10000 files with statahead: 13 sec
statahead total: 34
statahead wrong: 9
agl total: 34
hit_total: 1054
miss_total: 375
statahead was stopped, maybe too many locks held!
ls -l done
rm -r /mnt/lustre/d123ad.sanity/: 18 seconds
rm done
statahead total: 34
statahead wrong: 9
agl total: 34
hit_total: 1054
miss_total: 375
mdc.lustre-MDT0000-mdc-ffff94639828b000.batch_stats=
snapshot_time:            1682243365.822393085 secs.nsecs
start_time:               1682243292.581304155 secs.nsecs
elapsed_time:             73.241088930 secs.nsecs
subreqs per batch   batches   % cum %
1:		         4  40  40
2:		         1  10  50
4:		         0   0  50
8:		         0   0  50
16:		         3  30  80
32:		         2  20 100
mdc.lustre-MDT0001-mdc-ffff94639828b000.batch_stats=
snapshot_time:            1682243365.827668934 secs.nsecs
start_time:               1682243292.581363839 secs.nsecs
elapsed_time:             73.246305095 secs.nsecs
subreqs per batch   batches   % cum %
1:		         3  33  33
2:		         0   0  33
4:		         0   0  33
8:		         1  11  44
16:		         5  55 100
 - open/close 5281 (time 1682243376.01 total 10.00 last 528.07)
total: 10000 open/close in 18.26 seconds: 547.71 ops/second
llite.lustre-ffff94639828b000.statahead_batch_max=0
llite.lustre-ffff94639828b000.statahead_stats=clear
mdc.lustre-MDT0000-mdc-ffff94639828b000.stats=clear
mdc.lustre-MDT0001-mdc-ffff94639828b000.stats=clear
10001

real	0m12.165s
user	0m0.156s
sys	0m4.960s
 sanity test_123ad: @@@@@@ FAIL: unbatched statahead hit count (0) is too low 
  Trace dump:
  = ./../tests/test-framework.sh:6579:error()
  = sanity.sh:13740:test_batch_statahead()
  = sanity.sh:13780:test_123ad()
  = ./../tests/test-framework.sh:6919:run_one()
  = ./../tests/test-framework.sh:6968:run_one_logged()
  = ./../tests/test-framework.sh:6805:run_test()
  = sanity.sh:13783:main()
Dumping lctl log to /tmp/ltest-logs/sanity.test_123ad.*.1682243399.log
Dumping logs only on local client.
seq.cli-lustre-OST0000-super.width=65536
seq.cli-lustre-OST0001-super.width=65536
llite.lustre-ffff94639828b000.statahead_batch_max=0
llite.lustre-ffff94639828b000.statahead_max=32
FAIL 123ad (125s)