diff mbox series

[3/8] generic/192: fix spurious timeout

Message ID 170899915261.896550.17109752514258402651.stgit@frogsfrogsfrogs (mailing list archive)
State New
Headers show
Series [1/8] generic/604: try to make race occur reliably | expand

Commit Message

Darrick J. Wong Feb. 27, 2024, 2:01 a.m. UTC
From: Darrick J. Wong <djwong@kernel.org>

I have a theory that when the nfs server that hosts the root fs for my
testing VMs gets backed up, it can take a while for path resolution and
loading of echo, cat, or tee to finish.  That delays the test enough to
result in:

Comments

Zorro Lang Feb. 27, 2024, 4:23 a.m. UTC | #1
On Mon, Feb 26, 2024 at 06:01:19PM -0800, Darrick J. Wong wrote:
> From: Darrick J. Wong <djwong@kernel.org>
> 
> I have a theory that when the nfs server that hosts the root fs for my
> testing VMs gets backed up, it can take a while for path resolution and
> loading of echo, cat, or tee to finish.  That delays the test enough to
> result in:
> 
> --- /tmp/fstests/tests/generic/192.out	2023-11-29 15:40:52.715517458 -0800
> +++ /var/tmp/fstests/generic/192.out.bad	2023-12-15 21:28:02.860000000 -0800
> @@ -1,5 +1,6 @@
>  QA output created by 192
>  sleep for 5 seconds
>  test
> -delta1 is in range
> +delta1 has value of 12
> +delta1 is NOT in range 5 .. 7
>  delta2 is in range



> 
> Therefore, invoke all these utilities with --help before the critical
> section to make sure they're all in memory.
> 
> Signed-off-by: Darrick J. Wong <djwong@kernel.org>
> ---

This patch makes sense to me,
Reviewed-by: Zorro Lang <zlang@redhat.com>

Just better to give 1 or 2 whitespaces to diff output message (especially the
lines with "+") in commit log :) I always need to change that manually before
merge the patch :-D

Thanks,
Zorro

>  tests/generic/192 |   16 +++++++++++++---
>  1 file changed, 13 insertions(+), 3 deletions(-)
> 
> 
> diff --git a/tests/generic/192 b/tests/generic/192
> index 0d3cd03b4b..2825486635 100755
> --- a/tests/generic/192
> +++ b/tests/generic/192
> @@ -29,17 +29,27 @@ delay=5
>  testfile=$TEST_DIR/testfile
>  rm -f $testfile
>  
> +# Preload every binary used between sampling time1 and time2 so that loading
> +# them has minimal overhead even if the root fs is hosted over a slow network.
> +# Also don't put pipe and tee creation in that critical section.
> +for i in echo stat sleep cat; do
> +	$i --help &>/dev/null
> +done
> +
>  echo test >$testfile
> -time1=`_access_time $testfile | tee -a $seqres.full`
> +time1=`_access_time $testfile`
> +echo $time1 >> $seqres.full
>  
>  echo "sleep for $delay seconds"
>  sleep $delay # sleep to allow time to move on for access
>  cat $testfile
> -time2=`_access_time $testfile | tee -a $seqres.full`
> +time2=`_access_time $testfile`
> +echo $time2 >> $seqres.full
>  
>  cd /
>  _test_cycle_mount
> -time3=`_access_time $testfile | tee -a $seqres.full`
> +time3=`_access_time $testfile`
> +echo $time3 >> $seqres.full
>  
>  delta1=`expr $time2 - $time1`
>  delta2=`expr $time3 - $time1`
>
Darrick J. Wong Feb. 27, 2024, 4:29 a.m. UTC | #2
On Tue, Feb 27, 2024 at 12:23:46PM +0800, Zorro Lang wrote:
> On Mon, Feb 26, 2024 at 06:01:19PM -0800, Darrick J. Wong wrote:
> > From: Darrick J. Wong <djwong@kernel.org>
> > 
> > I have a theory that when the nfs server that hosts the root fs for my
> > testing VMs gets backed up, it can take a while for path resolution and
> > loading of echo, cat, or tee to finish.  That delays the test enough to
> > result in:
> > 
> > --- /tmp/fstests/tests/generic/192.out	2023-11-29 15:40:52.715517458 -0800
> > +++ /var/tmp/fstests/generic/192.out.bad	2023-12-15 21:28:02.860000000 -0800
> > @@ -1,5 +1,6 @@
> >  QA output created by 192
> >  sleep for 5 seconds
> >  test
> > -delta1 is in range
> > +delta1 has value of 12
> > +delta1 is NOT in range 5 .. 7
> >  delta2 is in range
> 
> 
> 
> > 
> > Therefore, invoke all these utilities with --help before the critical
> > section to make sure they're all in memory.
> > 
> > Signed-off-by: Darrick J. Wong <djwong@kernel.org>
> > ---
> 
> This patch makes sense to me,
> Reviewed-by: Zorro Lang <zlang@redhat.com>
> 
> Just better to give 1 or 2 whitespaces to diff output message (especially the
> lines with "+") in commit log :) I always need to change that manually before
> merge the patch :-D

Oh, you mean indenting the diff output in the commit message?

Yeah, I'll try to remember that from now on:

I have a theory that when the nfs server that hosts the root fs for my
testing VMs gets backed up, it can take a while for path resolution and
loading of echo, cat, or tee to finish.  That delays the test enough to
result in:

  --- /tmp/fstests/tests/generic/192.out	2023-11-29 15:40:52.715517458 -0800
  +++ /var/tmp/fstests/generic/192.out.bad	2023-12-15 21:28:02.860000000 -0800
  @@ -1,5 +1,6 @@
   QA output created by 192
   sleep for 5 seconds
   test
  -delta1 is in range
  +delta1 has value of 12
  +delta1 is NOT in range 5 .. 7
   delta2 is in range

Therefore, invoke all these utilities with --help before the critical
section to make sure they're all in memory.

Signed-off-by: Darrick J. Wong <djwong@kernel.org>

--D

> Thanks,
> Zorro
> 
> >  tests/generic/192 |   16 +++++++++++++---
> >  1 file changed, 13 insertions(+), 3 deletions(-)
> > 
> > 
> > diff --git a/tests/generic/192 b/tests/generic/192
> > index 0d3cd03b4b..2825486635 100755
> > --- a/tests/generic/192
> > +++ b/tests/generic/192
> > @@ -29,17 +29,27 @@ delay=5
> >  testfile=$TEST_DIR/testfile
> >  rm -f $testfile
> >  
> > +# Preload every binary used between sampling time1 and time2 so that loading
> > +# them has minimal overhead even if the root fs is hosted over a slow network.
> > +# Also don't put pipe and tee creation in that critical section.
> > +for i in echo stat sleep cat; do
> > +	$i --help &>/dev/null
> > +done
> > +
> >  echo test >$testfile
> > -time1=`_access_time $testfile | tee -a $seqres.full`
> > +time1=`_access_time $testfile`
> > +echo $time1 >> $seqres.full
> >  
> >  echo "sleep for $delay seconds"
> >  sleep $delay # sleep to allow time to move on for access
> >  cat $testfile
> > -time2=`_access_time $testfile | tee -a $seqres.full`
> > +time2=`_access_time $testfile`
> > +echo $time2 >> $seqres.full
> >  
> >  cd /
> >  _test_cycle_mount
> > -time3=`_access_time $testfile | tee -a $seqres.full`
> > +time3=`_access_time $testfile`
> > +echo $time3 >> $seqres.full
> >  
> >  delta1=`expr $time2 - $time1`
> >  delta2=`expr $time3 - $time1`
> > 
> 
>
Christoph Hellwig Feb. 27, 2024, 2:53 p.m. UTC | #3
On Mon, Feb 26, 2024 at 06:01:19PM -0800, Darrick J. Wong wrote:
> From: Darrick J. Wong <djwong@kernel.org>
> 
> I have a theory that when the nfs server that hosts the root fs for my
> testing VMs gets backed up, it can take a while for path resolution and
> loading of echo, cat, or tee to finish.  That delays the test enough to
> result in:

Heh, I've seen these warnings quite a lot in the past, but not recently.

The change looks good to me, though:

Reviewed-by: Christoph Hellwig <hch@lst.de>
diff mbox series

Patch

--- /tmp/fstests/tests/generic/192.out	2023-11-29 15:40:52.715517458 -0800
+++ /var/tmp/fstests/generic/192.out.bad	2023-12-15 21:28:02.860000000 -0800
@@ -1,5 +1,6 @@ 
 QA output created by 192
 sleep for 5 seconds
 test
-delta1 is in range
+delta1 has value of 12
+delta1 is NOT in range 5 .. 7
 delta2 is in range

Therefore, invoke all these utilities with --help before the critical
section to make sure they're all in memory.

Signed-off-by: Darrick J. Wong <djwong@kernel.org>
---
 tests/generic/192 |   16 +++++++++++++---
 1 file changed, 13 insertions(+), 3 deletions(-)


diff --git a/tests/generic/192 b/tests/generic/192
index 0d3cd03b4b..2825486635 100755
--- a/tests/generic/192
+++ b/tests/generic/192
@@ -29,17 +29,27 @@  delay=5
 testfile=$TEST_DIR/testfile
 rm -f $testfile
 
+# Preload every binary used between sampling time1 and time2 so that loading
+# them has minimal overhead even if the root fs is hosted over a slow network.
+# Also don't put pipe and tee creation in that critical section.
+for i in echo stat sleep cat; do
+	$i --help &>/dev/null
+done
+
 echo test >$testfile
-time1=`_access_time $testfile | tee -a $seqres.full`
+time1=`_access_time $testfile`
+echo $time1 >> $seqres.full
 
 echo "sleep for $delay seconds"
 sleep $delay # sleep to allow time to move on for access
 cat $testfile
-time2=`_access_time $testfile | tee -a $seqres.full`
+time2=`_access_time $testfile`
+echo $time2 >> $seqres.full
 
 cd /
 _test_cycle_mount
-time3=`_access_time $testfile | tee -a $seqres.full`
+time3=`_access_time $testfile`
+echo $time3 >> $seqres.full
 
 delta1=`expr $time2 - $time1`
 delta2=`expr $time3 - $time1`