* Re: xfs/566 execution time
2025-05-21 22:49 ` Darrick J. Wong
@ 2025-05-23 0:59 ` Shinichiro Kawasaki
0 siblings, 0 replies; 5+ messages in thread
From: Shinichiro Kawasaki @ 2025-05-23 0:59 UTC (permalink / raw)
To: Darrick J. Wong; +Cc: hch@infradead.org, fstests@vger.kernel.org
On May 21, 2025 / 15:49, Darrick J. Wong wrote:
> On Wed, May 21, 2025 at 09:37:53AM +0000, Shinichiro Kawasaki wrote:
> > On May 20, 2025 / 20:19, Darrick J. Wong wrote:
> > > On Tue, May 20, 2025 at 07:08:58AM -0700, Christoph Hellwig wrote:
> > > > Hi Darrick,
> > > >
> > > > we regularly see execution times of more than half a day for xfs/566
> > > > on a 30ish TB SMR HDD. Do you think there might be a useful way to
> > > > scale down the load on rotational devices?
> > >
> > > Hrmm. Is that the only one that does that, or do the other scrub tests
> > > take a while too?
> >
> > As to the test with SMR HDDs, I observed very long test run on two test cases:
> > xfs/566 and xfs/732.
> >
> > > If it's just that one, and setting SOAK_DURATION=2m
> > > results in the test cutting off after 2min, then I'll craft some sort of
> > > fix to constrain the runtime.
> >
> > I added,
> >
> > "export SOAK_DURATION=2m"
> >
> > to local.config and ran xfs/566, but that setting does not look working.
> > The test case rusn more than a half an hour...
>
> Huh, that's /very/ strange. In the absence of a SOAK_DURATION, the test
> should only run itself for 30 seconds. From common/fuzzy,
> _scratch_xfs_stress_scrub does this to set the end-time:
>
> if [ -n "$SOAK_DURATION" ]; then
> end="$((start + SOAK_DURATION))"
> else
> end="$((start + (30 * TIME_FACTOR) ))"
> fi
>
> and then __stress_scrub_fsx_loop does:
>
> while __stress_scrub_running "$end" "$runningfile"; do
> # Need to recheck running conditions if we cleared anything
> __stress_scrub_clean_scratch && continue
> duration=$(___stress_scrub_duration "$end" "$remount_period")
> ___scrub_run_fsx $duration $d_args &
>
> which should be sufficient to exit the fsx loop. Then we go back to
> _scratch_xfs_stress_scrub and:
>
> # Wait until the designated end time or fsstress dies, then kill all of
> # our background processes.
> while __stress_scrub_running "$end" "$runningfile"; do
> sleep 1
> done
> _scratch_xfs_stress_scrub_cleanup
>
> which just waits for fsx and scrub to exit. If you start this test and
> wait about 45 seconds or so, can you send me the ps output so I can try
> to figure out which component(s) aren't stopping in time?
Please find the ps output [1]. It shows a xfs_scrub command is taking time.
I did some investigation, and found the xfs_scrub command is started
by the _scratch_scrub() call in _scratch_xfs_stress_scrub(). This xfs_scrub
command starts before the 'end="$((start + SOAK_DURATION))"' calculation.
P.S. I found that "export SOAK_DURATION=2m" causes the bash error
"value too great for base". I think it should be
"export SOAK_DURATION=120", but this does not look important here.
[1]
$ ps axuw | grep xfs
root 625 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfsalloc]
root 626 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs_mru_cache]
root 627 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-buf/sdc3]
root 628 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-conv/sdc3]
root 629 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-reclaim/sdc3]
root 630 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-blockgc/sdc3]
root 631 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-inodegc/sdc3]
root 632 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-log/sdc3]
root 633 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-cil/sdc3]
root 634 0.0 0.0 0 0 ? S May19 1:07 [xfsaild/sdc3]
root 880 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-buf/sdc2]
root 881 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-conv/sdc2]
root 882 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-reclaim/sdc2]
root 883 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-blockgc/sdc2]
root 885 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-inodegc/sdc2]
root 887 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-log/sdc2]
root 888 0.0 0.0 0 0 ? I< May19 0:00 [kworker/R-xfs-cil/sdc2]
root 889 0.0 0.0 0 0 ? S May19 0:00 [xfsaild/sdc2]
root 1143452 0.0 0.0 0 0 ? I< May20 0:00 [kworker/14:2H-xfs-log/dm-0]
root 1143455 0.0 0.0 0 0 ? I< May20 0:03 [kworker/1:0H-xfs-log/sdc3]
root 1144000 0.0 0.0 0 0 ? I< May20 0:00 [kworker/12:2H-xfs-log/dm-0]
root 1147483 0.0 0.0 0 0 ? I< May20 0:00 [kworker/15:0H-xfs-log/dm-0]
root 1149262 0.0 0.0 0 0 ? I< May20 0:00 [kworker/0:1H-xfs-log/dm-0]
root 1149405 0.0 0.0 0 0 ? I< May20 0:00 [kworker/11:2H-xfs-log/dm-0]
root 1150253 0.0 0.0 0 0 ? I< May20 0:00 [kworker/4:2H-xfs-log/dm-0]
root 1655712 0.0 0.0 0 0 ? I< May21 0:01 [kworker/5:0H-xfs-log/sdb]
root 1669211 0.0 0.0 0 0 ? I 05:37 0:00 [kworker/1:1-xfs-buf/sdc3]
root 1674988 0.0 0.0 20816 9188 pts/0 S+ 09:36 0:00 sudo ./check xfs/566
root 1674991 0.0 0.0 20816 2940 pts/1 Ss 09:36 0:00 sudo ./check xfs/566
root 1674992 0.1 0.0 11464 7612 pts/1 S+ 09:36 0:00 /bin/bash ./check xfs/566
root 1675518 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-buf/sda]
root 1675519 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-conv/sda]
root 1675520 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-reclaim/sda]
root 1675521 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-blockgc/sda]
root 1675522 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-inodegc/sda]
root 1675523 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-log/sda]
root 1675524 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-cil/sda]
root 1675525 0.0 0.0 0 0 ? S 09:39 0:00 [xfsaild/sda]
root 1675526 0.0 0.0 0 0 ? S 09:39 0:00 [xfs-zone-gc/sda]
root 1675633 0.1 0.0 9180 8128 pts/1 S+ 09:39 0:00 /bin/bash /home/kts/kernel-test-suite/src/xfstests/tests/xfs/566
root 1675876 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-buf/sdb]
root 1675877 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-conv/sdb]
root 1675878 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-reclaim/sdb]
root 1675879 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-blockgc/sdb]
root 1675880 0.0 0.0 0 0 ? I< 09:39 0:00 [kworker/R-xfs-inodegc/sdb]
root 1675888 0.0 0.0 0 0 ? I< 09:40 0:00 [kworker/R-xfs-log/sdb]
root 1675889 0.0 0.0 0 0 ? I< 09:40 0:00 [kworker/R-xfs-cil/sdb]
root 1675890 0.0 0.0 0 0 ? S 09:40 0:00 [xfsaild/sdb]
root 1675891 0.0 0.0 0 0 ? S 09:40 0:00 [xfs-zone-gc/sdb]
root 1675933 195 0.1 171768 36296 pts/1 Sl+ 09:40 16:46 /usr/local/sbin/xfs_scrub -d -T -v -k /var/kts/scratch
kts 1676000 50.0 0.0 6544 2388 pts/3 S+ 09:48 0:00 grep --color=auto xfs
^ permalink raw reply [flat|nested] 5+ messages in thread