[Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

This attempts to clean-up the output to better match the output of the
rest of the QEMU check system. This includes:

  - formatting as "  TEST    iotest: nnn"
  - calculating time diff at the end
  - only dumping config on failure

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
 1 file changed, 34 insertions(+), 37 deletions(-)

diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
index 922c5d1d3d..2ffc14113e 100755
--- a/tests/qemu-iotests/check
+++ b/tests/qemu-iotests/check
@@ -633,12 +633,6 @@ _wallclock()
     date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }'
 }
 
-_timestamp()
-{
-    now=$(date "+%T")
-    printf %s " [$now]"
-}
-
 _wrapup()
 {
     if $showme
@@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
 FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
 FULL_HOST_DETAILS=$(_full_platform_details)
 
-cat <<EOF
-QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
-QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
-QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
-QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
-IMGFMT        -- $FULL_IMGFMT_DETAILS
-IMGPROTO      -- $IMGPROTO
-PLATFORM      -- $FULL_HOST_DETAILS
-TEST_DIR      -- $TEST_DIR
-SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
-
-EOF
-
 seq="check"
 
 [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
@@ -729,7 +710,9 @@ seq="check"
 for seq in $list
 do
     err=false
-    printf %s "$seq"
+    reason=""
+    times=""
+
     if [ -n "$TESTS_REMAINING_LOG" ] ; then
         sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
         mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
@@ -738,7 +721,7 @@ do
 
     if $showme
     then
-        echo
+        echo "  TEST    iotest: $seq (not actually run)"
         continue
     elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
     then
@@ -753,17 +736,11 @@ do
         # really going to try and run this one
         #
         rm -f $seq.out.bad
-        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
-        if [ "X$lasttime" != X ]; then
-                printf %s " ${lasttime}s ..."
-        else
-                printf "        "        # prettier output with timestamps.
-        fi
         rm -f core $seq.notrun
         rm -f $seq.casenotrun
 
         start=$(_wallclock)
-        $timestamp && printf %s "        [$(date "+%T")]"
+        $timestamp && times="[$(date "+%T")]"
 
         if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
             run_command="$PYTHON $seq"
@@ -781,26 +758,26 @@ do
                     $run_command >$tmp.out 2>&1)
         fi
         sts=$?
-        $timestamp && _timestamp
+        $timestamp && times="$times -> [$(date "+%T")]"
         stop=$(_wallclock)
 
         if [ -f core ]
         then
-            printf " [dumped core]"
             mv core $seq.core
+            reason="dumped core $seq.core"
             err=true
         fi
 
         if [ -f $seq.notrun ]
         then
-            $timestamp || printf " [not run] "
-            $timestamp && echo " [not run]" && printf %s "        $seq -- "
+            $timestamp || reason="[not run]"
+            $timestamp && reason="[not run] $seq -- "
             cat $seq.notrun
             notrun="$notrun $seq"
         else
             if [ $sts -ne 0 ]
             then
-                printf %s " [failed, exit status $sts]"
+                reason=$(printf %s "[failed, exit status $sts]")
                 err=true
             fi
 
@@ -821,22 +798,27 @@ do
 
             if [ ! -f "$reference" ]
             then
-                echo " - no qualified output"
+                reason=" - no qualified output"
                 err=true
             else
                 if diff -w "$reference" $tmp.out >/dev/null 2>&1
                 then
-                    echo ""
                     if $err
                     then
                         :
                     else
-                        echo "$seq $(expr $stop - $start)" >>$tmp.time
+                        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
+                        thistime=$(expr $stop - $start)
+                        echo "$seq $thistime" >>$tmp.time
+
+                        if [ "X$lasttime" != X ]; then
+                            times="$times ${thistime}s (last ${lasttime}s)"
+                        fi
                     fi
                 else
-                    echo " - output mismatch (see $seq.out.bad)"
                     mv $tmp.out $seq.out.bad
                     $diff -w "$reference" "$PWD"/$seq.out.bad
+                    reason=" - output mismatch (see $seq.out.bad)"
                     err=true
                 fi
             fi
@@ -852,9 +834,24 @@ do
     #
     if $err
     then
+        echo "  TEST    iotest: $seq FAILED $reason"
+        cat <<EOF
+QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
+QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
+QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
+QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
+IMGFMT        -- $FULL_IMGFMT_DETAILS
+IMGPROTO      -- $IMGPROTO
+PLATFORM      -- $FULL_HOST_DETAILS
+TEST_DIR      -- $TEST_DIR
+SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
+
+EOF
         bad="$bad $seq"
         n_bad=$(expr $n_bad + 1)
         quick=false
+    else
+        echo "  TEST    iotest: $seq $times"
     fi
     [ -f $seq.notrun ] || try=$(expr $try + 1)
 
-- 
2.20.1

[Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

This attempts to clean-up the output to better match the output of the
rest of the QEMU check system. This includes:

  - formatting as "  TEST    iotest: nnn"
  - calculating time diff at the end
  - only dumping config on failure

Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
---
 tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
 1 file changed, 34 insertions(+), 37 deletions(-)

diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
index 922c5d1d3d..2ffc14113e 100755
--- a/tests/qemu-iotests/check
+++ b/tests/qemu-iotests/check
@@ -633,12 +633,6 @@ _wallclock()
     date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }'
 }
 
-_timestamp()
-{
-    now=$(date "+%T")
-    printf %s " [$now]"
-}
-
 _wrapup()
 {
     if $showme
@@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
 FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
 FULL_HOST_DETAILS=$(_full_platform_details)
 
-cat <<EOF
-QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
-QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
-QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
-QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
-IMGFMT        -- $FULL_IMGFMT_DETAILS
-IMGPROTO      -- $IMGPROTO
-PLATFORM      -- $FULL_HOST_DETAILS
-TEST_DIR      -- $TEST_DIR
-SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
-
-EOF
-
 seq="check"
 
 [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
@@ -729,7 +710,9 @@ seq="check"
 for seq in $list
 do
     err=false
-    printf %s "$seq"
+    reason=""
+    times=""
+
     if [ -n "$TESTS_REMAINING_LOG" ] ; then
         sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
         mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
@@ -738,7 +721,7 @@ do
 
     if $showme
     then
-        echo
+        echo "  TEST    iotest: $seq (not actually run)"
         continue
     elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
     then
@@ -753,17 +736,11 @@ do
         # really going to try and run this one
         #
         rm -f $seq.out.bad
-        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
-        if [ "X$lasttime" != X ]; then
-                printf %s " ${lasttime}s ..."
-        else
-                printf "        "        # prettier output with timestamps.
-        fi
         rm -f core $seq.notrun
         rm -f $seq.casenotrun
 
         start=$(_wallclock)
-        $timestamp && printf %s "        [$(date "+%T")]"
+        $timestamp && times="[$(date "+%T")]"
 
         if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
             run_command="$PYTHON $seq"
@@ -781,26 +758,26 @@ do
                     $run_command >$tmp.out 2>&1)
         fi
         sts=$?
-        $timestamp && _timestamp
+        $timestamp && times="$times -> [$(date "+%T")]"
         stop=$(_wallclock)
 
         if [ -f core ]
         then
-            printf " [dumped core]"
             mv core $seq.core
+            reason="dumped core $seq.core"
             err=true
         fi
 
         if [ -f $seq.notrun ]
         then
-            $timestamp || printf " [not run] "
-            $timestamp && echo " [not run]" && printf %s "        $seq -- "
+            $timestamp || reason="[not run]"
+            $timestamp && reason="[not run] $seq -- "
             cat $seq.notrun
             notrun="$notrun $seq"
         else
             if [ $sts -ne 0 ]
             then
-                printf %s " [failed, exit status $sts]"
+                reason=$(printf %s "[failed, exit status $sts]")
                 err=true
             fi
 
@@ -821,22 +798,27 @@ do
 
             if [ ! -f "$reference" ]
             then
-                echo " - no qualified output"
+                reason=" - no qualified output"
                 err=true
             else
                 if diff -w "$reference" $tmp.out >/dev/null 2>&1
                 then
-                    echo ""
                     if $err
                     then
                         :
                     else
-                        echo "$seq $(expr $stop - $start)" >>$tmp.time
+                        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
+                        thistime=$(expr $stop - $start)
+                        echo "$seq $thistime" >>$tmp.time
+
+                        if [ "X$lasttime" != X ]; then
+                            times="$times ${thistime}s (last ${lasttime}s)"
+                        fi
                     fi
                 else
-                    echo " - output mismatch (see $seq.out.bad)"
                     mv $tmp.out $seq.out.bad
                     $diff -w "$reference" "$PWD"/$seq.out.bad
+                    reason=" - output mismatch (see $seq.out.bad)"
                     err=true
                 fi
             fi
@@ -852,9 +834,24 @@ do
     #
     if $err
     then
+        echo "  TEST    iotest: $seq FAILED $reason"
+        cat <<EOF
+QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
+QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
+QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
+QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
+IMGFMT        -- $FULL_IMGFMT_DETAILS
+IMGPROTO      -- $IMGPROTO
+PLATFORM      -- $FULL_HOST_DETAILS
+TEST_DIR      -- $TEST_DIR
+SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
+
+EOF
         bad="$bad $seq"
         n_bad=$(expr $n_bad + 1)
         quick=false
+    else
+        echo "  TEST    iotest: $seq $times"
     fi
     [ -f $seq.notrun ] || try=$(expr $try + 1)
 
-- 
2.20.1

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 16.39, Alex Bennée wrote:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>  1 file changed, 34 insertions(+), 37 deletions(-)

Thanks for tackling this! The output now looks nicer indeed if you run
"make check-qtest check-block -j8". However, if you add a "V=1" at the
end of the command line, the outputs look quite different again...

That's why I thought that having a TAP mode for the check script could
be a good idea, too. Then we could pipe the output through the
tap-driver.pl script, too, so we get uniform output for all tests...?

 Thomas

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 16.39, Alex Bennée wrote:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>  1 file changed, 34 insertions(+), 37 deletions(-)

Thanks for tackling this! The output now looks nicer indeed if you run
"make check-qtest check-block -j8". However, if you add a "V=1" at the
end of the command line, the outputs look quite different again...

That's why I thought that having a TAP mode for the check script could
be a good idea, too. Then we could pipe the output through the
tap-driver.pl script, too, so we get uniform output for all tests...?

 Thomas

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 03/05/2019 16.39, Alex Bennée wrote:
>> This attempts to clean-up the output to better match the output of the
>> rest of the QEMU check system. This includes:
>>
>>   - formatting as "  TEST    iotest: nnn"
>>   - calculating time diff at the end
>>   - only dumping config on failure
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>  1 file changed, 34 insertions(+), 37 deletions(-)
>
> Thanks for tackling this! The output now looks nicer indeed if you run
> "make check-qtest check-block -j8". However, if you add a "V=1" at the
> end of the command line, the outputs look quite different again...
>
> That's why I thought that having a TAP mode for the check script could
> be a good idea, too. Then we could pipe the output through the
> tap-driver.pl script, too, so we get uniform output for all tests...?

That would probably be a cleaner approach. What would be even better is
somehow expanding the list of tests at make time so you could run your
tests in parallel.

I did wonder how useful the timing stuff was to developers.

>
>  Thomas


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 03/05/2019 16.39, Alex Bennée wrote:
>> This attempts to clean-up the output to better match the output of the
>> rest of the QEMU check system. This includes:
>>
>>   - formatting as "  TEST    iotest: nnn"
>>   - calculating time diff at the end
>>   - only dumping config on failure
>>
>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>> ---
>>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>  1 file changed, 34 insertions(+), 37 deletions(-)
>
> Thanks for tackling this! The output now looks nicer indeed if you run
> "make check-qtest check-block -j8". However, if you add a "V=1" at the
> end of the command line, the outputs look quite different again...
>
> That's why I thought that having a TAP mode for the check script could
> be a good idea, too. Then we could pipe the output through the
> tap-driver.pl script, too, so we get uniform output for all tests...?

That would probably be a cleaner approach. What would be even better is
somehow expanding the list of tests at make time so you could run your
tests in parallel.

I did wonder how useful the timing stuff was to developers.

>
>  Thomas


--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 18.15, Alex Bennée wrote:
> 
> Thomas Huth <thuth@redhat.com> writes:
> 
>> On 03/05/2019 16.39, Alex Bennée wrote:
>>> This attempts to clean-up the output to better match the output of the
>>> rest of the QEMU check system. This includes:
>>>
>>>   - formatting as "  TEST    iotest: nnn"
>>>   - calculating time diff at the end
>>>   - only dumping config on failure
>>>
>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>> ---
>>>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>  1 file changed, 34 insertions(+), 37 deletions(-)
>>
>> Thanks for tackling this! The output now looks nicer indeed if you run
>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>> end of the command line, the outputs look quite different again...
>>
>> That's why I thought that having a TAP mode for the check script could
>> be a good idea, too. Then we could pipe the output through the
>> tap-driver.pl script, too, so we get uniform output for all tests...?
> 
> That would probably be a cleaner approach. What would be even better is
> somehow expanding the list of tests at make time so you could run your
> tests in parallel.

I agree that this might be the ultimate solution ... but I'm not sure
whether the iotests are really ready for being run in parallel yet, so
it will likely take quite some while 'till we are at that point. With
that in mind (and thus also not sure yet whether my TAP idea is really
the right approach), your patch is certainly a good interim solution
which we should try to get merged, too, when my "make check" series gets
accepted?

> I did wonder how useful the timing stuff was to developers.

Yes, me too ... maybe the block layer folks can comment on that one...?

 Thomas

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 18.15, Alex Bennée wrote:
> 
> Thomas Huth <thuth@redhat.com> writes:
> 
>> On 03/05/2019 16.39, Alex Bennée wrote:
>>> This attempts to clean-up the output to better match the output of the
>>> rest of the QEMU check system. This includes:
>>>
>>>   - formatting as "  TEST    iotest: nnn"
>>>   - calculating time diff at the end
>>>   - only dumping config on failure
>>>
>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>> ---
>>>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>  1 file changed, 34 insertions(+), 37 deletions(-)
>>
>> Thanks for tackling this! The output now looks nicer indeed if you run
>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>> end of the command line, the outputs look quite different again...
>>
>> That's why I thought that having a TAP mode for the check script could
>> be a good idea, too. Then we could pipe the output through the
>> tap-driver.pl script, too, so we get uniform output for all tests...?
> 
> That would probably be a cleaner approach. What would be even better is
> somehow expanding the list of tests at make time so you could run your
> tests in parallel.

I agree that this might be the ultimate solution ... but I'm not sure
whether the iotests are really ready for being run in parallel yet, so
it will likely take quite some while 'till we are at that point. With
that in mind (and thus also not sure yet whether my TAP idea is really
the right approach), your patch is certainly a good interim solution
which we should try to get merged, too, when my "make check" series gets
accepted?

> I did wonder how useful the timing stuff was to developers.

Yes, me too ... maybe the block layer folks can comment on that one...?

 Thomas

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 16.39, Alex Bennée wrote:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>  1 file changed, 34 insertions(+), 37 deletions(-)
> 
> diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
> index 922c5d1d3d..2ffc14113e 100755
> --- a/tests/qemu-iotests/check
> +++ b/tests/qemu-iotests/check
> @@ -633,12 +633,6 @@ _wallclock()
>      date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }'
>  }
>  
> -_timestamp()
> -{
> -    now=$(date "+%T")
> -    printf %s " [$now]"
> -}
> -
>  _wrapup()
>  {
>      if $showme
> @@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
>  FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
>  FULL_HOST_DETAILS=$(_full_platform_details)
>  
> -cat <<EOF
> -QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> -QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> -QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> -QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> -IMGFMT        -- $FULL_IMGFMT_DETAILS
> -IMGPROTO      -- $IMGPROTO
> -PLATFORM      -- $FULL_HOST_DETAILS
> -TEST_DIR      -- $TEST_DIR
> -SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> -
> -EOF

Maybe turn it into a function instead, so that it could also always be
printed when the script is run with the "-v" parameter?

>  seq="check"
>  
>  [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
> @@ -729,7 +710,9 @@ seq="check"
>  for seq in $list
>  do
>      err=false
> -    printf %s "$seq"
> +    reason=""
> +    times=""
> +
>      if [ -n "$TESTS_REMAINING_LOG" ] ; then
>          sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
>          mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
> @@ -738,7 +721,7 @@ do
>  
>      if $showme
>      then
> -        echo
> +        echo "  TEST    iotest: $seq (not actually run)"

I wonder whether some other scripts depend on the output of "check -n"
... in that case, it make sense to only print the numbers, without the
additional strings here.

>          continue
>      elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
>      then
> @@ -753,17 +736,11 @@ do
>          # really going to try and run this one
>          #
>          rm -f $seq.out.bad
> -        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> -        if [ "X$lasttime" != X ]; then
> -                printf %s " ${lasttime}s ..."
> -        else
> -                printf "        "        # prettier output with timestamps.
> -        fi
>          rm -f core $seq.notrun
>          rm -f $seq.casenotrun
>  
>          start=$(_wallclock)
> -        $timestamp && printf %s "        [$(date "+%T")]"
> +        $timestamp && times="[$(date "+%T")]"
>  
>          if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
>              run_command="$PYTHON $seq"
> @@ -781,26 +758,26 @@ do
>                      $run_command >$tmp.out 2>&1)
>          fi
>          sts=$?
> -        $timestamp && _timestamp
> +        $timestamp && times="$times -> [$(date "+%T")]"
>          stop=$(_wallclock)
>  
>          if [ -f core ]
>          then
> -            printf " [dumped core]"
>              mv core $seq.core
> +            reason="dumped core $seq.core"
>              err=true
>          fi
>  
>          if [ -f $seq.notrun ]
>          then
> -            $timestamp || printf " [not run] "
> -            $timestamp && echo " [not run]" && printf %s "        $seq -- "
> +            $timestamp || reason="[not run]"
> +            $timestamp && reason="[not run] $seq -- "
>              cat $seq.notrun
>              notrun="$notrun $seq"
>          else
>              if [ $sts -ne 0 ]
>              then
> -                printf %s " [failed, exit status $sts]"
> +                reason=$(printf %s "[failed, exit status $sts]")
>                  err=true
>              fi
>  
> @@ -821,22 +798,27 @@ do
>  
>              if [ ! -f "$reference" ]
>              then
> -                echo " - no qualified output"
> +                reason=" - no qualified output"
>                  err=true
>              else
>                  if diff -w "$reference" $tmp.out >/dev/null 2>&1
>                  then
> -                    echo ""
>                      if $err
>                      then
>                          :
>                      else
> -                        echo "$seq $(expr $stop - $start)" >>$tmp.time
> +                        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> +                        thistime=$(expr $stop - $start)
> +                        echo "$seq $thistime" >>$tmp.time
> +
> +                        if [ "X$lasttime" != X ]; then
> +                            times="$times ${thistime}s (last ${lasttime}s)"
> +                        fi
>                      fi
>                  else
> -                    echo " - output mismatch (see $seq.out.bad)"
>                      mv $tmp.out $seq.out.bad
>                      $diff -w "$reference" "$PWD"/$seq.out.bad
> +                    reason=" - output mismatch (see $seq.out.bad)"
>                      err=true
>                  fi
>              fi
> @@ -852,9 +834,24 @@ do
>      #
>      if $err
>      then
> +        echo "  TEST    iotest: $seq FAILED $reason"
> +        cat <<EOF
> +QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> +QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> +QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> +QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> +IMGFMT        -- $FULL_IMGFMT_DETAILS
> +IMGPROTO      -- $IMGPROTO
> +PLATFORM      -- $FULL_HOST_DETAILS
> +TEST_DIR      -- $TEST_DIR
> +SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> +
> +EOF
>          bad="$bad $seq"
>          n_bad=$(expr $n_bad + 1)
>          quick=false
> +    else
> +        echo "  TEST    iotest: $seq $times"
>      fi
>      [ -f $seq.notrun ] || try=$(expr $try + 1)

Output is much nicer indeed (especially when this is running in parallel
with the other tests), thus:

Tested-by: Thomas Huth <thuth@redhat.com>

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Thomas Huth]

On 03/05/2019 16.39, Alex Bennée wrote:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
> ---
>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>  1 file changed, 34 insertions(+), 37 deletions(-)
> 
> diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
> index 922c5d1d3d..2ffc14113e 100755
> --- a/tests/qemu-iotests/check
> +++ b/tests/qemu-iotests/check
> @@ -633,12 +633,6 @@ _wallclock()
>      date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }'
>  }
>  
> -_timestamp()
> -{
> -    now=$(date "+%T")
> -    printf %s " [$now]"
> -}
> -
>  _wrapup()
>  {
>      if $showme
> @@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
>  FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
>  FULL_HOST_DETAILS=$(_full_platform_details)
>  
> -cat <<EOF
> -QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> -QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> -QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> -QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> -IMGFMT        -- $FULL_IMGFMT_DETAILS
> -IMGPROTO      -- $IMGPROTO
> -PLATFORM      -- $FULL_HOST_DETAILS
> -TEST_DIR      -- $TEST_DIR
> -SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> -
> -EOF

Maybe turn it into a function instead, so that it could also always be
printed when the script is run with the "-v" parameter?

>  seq="check"
>  
>  [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
> @@ -729,7 +710,9 @@ seq="check"
>  for seq in $list
>  do
>      err=false
> -    printf %s "$seq"
> +    reason=""
> +    times=""
> +
>      if [ -n "$TESTS_REMAINING_LOG" ] ; then
>          sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
>          mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
> @@ -738,7 +721,7 @@ do
>  
>      if $showme
>      then
> -        echo
> +        echo "  TEST    iotest: $seq (not actually run)"

I wonder whether some other scripts depend on the output of "check -n"
... in that case, it make sense to only print the numbers, without the
additional strings here.

>          continue
>      elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
>      then
> @@ -753,17 +736,11 @@ do
>          # really going to try and run this one
>          #
>          rm -f $seq.out.bad
> -        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> -        if [ "X$lasttime" != X ]; then
> -                printf %s " ${lasttime}s ..."
> -        else
> -                printf "        "        # prettier output with timestamps.
> -        fi
>          rm -f core $seq.notrun
>          rm -f $seq.casenotrun
>  
>          start=$(_wallclock)
> -        $timestamp && printf %s "        [$(date "+%T")]"
> +        $timestamp && times="[$(date "+%T")]"
>  
>          if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
>              run_command="$PYTHON $seq"
> @@ -781,26 +758,26 @@ do
>                      $run_command >$tmp.out 2>&1)
>          fi
>          sts=$?
> -        $timestamp && _timestamp
> +        $timestamp && times="$times -> [$(date "+%T")]"
>          stop=$(_wallclock)
>  
>          if [ -f core ]
>          then
> -            printf " [dumped core]"
>              mv core $seq.core
> +            reason="dumped core $seq.core"
>              err=true
>          fi
>  
>          if [ -f $seq.notrun ]
>          then
> -            $timestamp || printf " [not run] "
> -            $timestamp && echo " [not run]" && printf %s "        $seq -- "
> +            $timestamp || reason="[not run]"
> +            $timestamp && reason="[not run] $seq -- "
>              cat $seq.notrun
>              notrun="$notrun $seq"
>          else
>              if [ $sts -ne 0 ]
>              then
> -                printf %s " [failed, exit status $sts]"
> +                reason=$(printf %s "[failed, exit status $sts]")
>                  err=true
>              fi
>  
> @@ -821,22 +798,27 @@ do
>  
>              if [ ! -f "$reference" ]
>              then
> -                echo " - no qualified output"
> +                reason=" - no qualified output"
>                  err=true
>              else
>                  if diff -w "$reference" $tmp.out >/dev/null 2>&1
>                  then
> -                    echo ""
>                      if $err
>                      then
>                          :
>                      else
> -                        echo "$seq $(expr $stop - $start)" >>$tmp.time
> +                        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> +                        thistime=$(expr $stop - $start)
> +                        echo "$seq $thistime" >>$tmp.time
> +
> +                        if [ "X$lasttime" != X ]; then
> +                            times="$times ${thistime}s (last ${lasttime}s)"
> +                        fi
>                      fi
>                  else
> -                    echo " - output mismatch (see $seq.out.bad)"
>                      mv $tmp.out $seq.out.bad
>                      $diff -w "$reference" "$PWD"/$seq.out.bad
> +                    reason=" - output mismatch (see $seq.out.bad)"
>                      err=true
>                  fi
>              fi
> @@ -852,9 +834,24 @@ do
>      #
>      if $err
>      then
> +        echo "  TEST    iotest: $seq FAILED $reason"
> +        cat <<EOF
> +QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> +QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> +QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> +QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> +IMGFMT        -- $FULL_IMGFMT_DETAILS
> +IMGPROTO      -- $IMGPROTO
> +PLATFORM      -- $FULL_HOST_DETAILS
> +TEST_DIR      -- $TEST_DIR
> +SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> +
> +EOF
>          bad="$bad $seq"
>          n_bad=$(expr $n_bad + 1)
>          quick=false
> +    else
> +        echo "  TEST    iotest: $seq $times"
>      fi
>      [ -f $seq.notrun ] || try=$(expr $try + 1)

Output is much nicer indeed (especially when this is running in parallel
with the other tests), thus:

Tested-by: Thomas Huth <thuth@redhat.com>

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Vladimir Sementsov-Ogievskiy]

05.05.2019 18:54, Thomas Huth wrote:
> On 03/05/2019 18.15, Alex Bennée wrote:
>>
>> Thomas Huth <thuth@redhat.com> writes:
>>
>>> On 03/05/2019 16.39, Alex Bennée wrote:
>>>> This attempts to clean-up the output to better match the output of the
>>>> rest of the QEMU check system. This includes:
>>>>
>>>>    - formatting as "  TEST    iotest: nnn"
>>>>    - calculating time diff at the end
>>>>    - only dumping config on failure
>>>>
>>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>>> ---
>>>>   tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>>   1 file changed, 34 insertions(+), 37 deletions(-)
>>>
>>> Thanks for tackling this! The output now looks nicer indeed if you run
>>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>>> end of the command line, the outputs look quite different again...
>>>
>>> That's why I thought that having a TAP mode for the check script could
>>> be a good idea, too. Then we could pipe the output through the
>>> tap-driver.pl script, too, so we get uniform output for all tests...?
>>
>> That would probably be a cleaner approach. What would be even better is
>> somehow expanding the list of tests at make time so you could run your
>> tests in parallel.
> 
> I agree that this might be the ultimate solution ... but I'm not sure
> whether the iotests are really ready for being run in parallel yet, so
> it will likely take quite some while 'till we are at that point. With
> that in mind (and thus also not sure yet whether my TAP idea is really
> the right approach), your patch is certainly a good interim solution
> which we should try to get merged, too, when my "make check" series gets
> accepted?
> 
>> I did wonder how useful the timing stuff was to developers.
> 
> Yes, me too ... maybe the block layer folks can comment on that one...?
> 
>   Thomas
> 

Hi!

It was useful to not miss performance degradation (1) and
to understand that test hangs (2) (if you know that it should
finish in 1 second, but 10 seconds already passed, the test
most probably hangs)

Run tests with your patch:

first run:
# check -qcow2 -T
   TEST    iotest: 001 [20:00:30] -> [20:00:31]
   TEST    iotest: 002 [20:00:31] -> [20:00:33]
   TEST    iotest: 003 [20:00:33] -> [20:00:34]
   TEST    iotest: 004 [20:00:34] -> [20:00:35]
   TEST    iotest: 005 [20:00:35] -> [20:00:36]
   TEST    iotest: 007 [20:00:36] -> [20:00:39]


second run:
# check -qcow2 -T
   TEST    iotest: 001 [20:00:41] -> [20:00:43] 2s (last 1s)
   TEST    iotest: 002 [20:00:43] -> [20:00:44] 1s (last 2s)
   TEST    iotest: 003 [20:00:44] -> [20:00:46] 2s (last 1s)
   TEST    iotest: 004 [20:00:46] -> [20:00:46] 0s (last 1s)
   TEST    iotest: 005 [20:00:46] -> [20:00:47] 1s (last 1s)
   TEST    iotest: 007 [20:00:47] -> [20:00:50] 3s (last 3s)
   TEST    iotest: 008 [20:00:50] -> [20:00:51]
   TEST    iotest: 009 [20:00:51] -> [20:00:51]
   TEST    iotest: 010 [20:00:51] -> [20:00:51]


So, in first run delta was not calculated and on second - calculated.
Could you calculate delta in all cases, to make first run look like
# check -qcow2 -T
   TEST    iotest: 001 [20:00:30] -> [20:00:31] 1s
   TEST    iotest: 002 [20:00:31] -> [20:00:33] 2s
   TEST    iotest: 003 [20:00:33] -> [20:00:34] 1s
   TEST    iotest: 004 [20:00:34] -> [20:00:35] 1s
   TEST    iotest: 005 [20:00:35] -> [20:00:36] 1s
   TEST    iotest: 007 [20:00:36] -> [20:00:39] 3s


-- 
Best regards,
Vladimir

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 1355 bytes --]

On 5/5/19 10:54 AM, Thomas Huth wrote:

>>> That's why I thought that having a TAP mode for the check script could
>>> be a good idea, too. Then we could pipe the output through the
>>> tap-driver.pl script, too, so we get uniform output for all tests...?
>>
>> That would probably be a cleaner approach. What would be even better is
>> somehow expanding the list of tests at make time so you could run your
>> tests in parallel.
> 
> I agree that this might be the ultimate solution ... but I'm not sure
> whether the iotests are really ready for being run in parallel yet,

No, they are not. Jeff Cody had a patch series that converted
qemu-iotests/check to run every test in its own subdirectory instead of
in a shared spot, which we would have to revive first.

> 
>> I did wonder how useful the timing stuff was to developers.
> 
> Yes, me too ... maybe the block layer folks can comment on that one...?

I like it; it gives me an idea of how long a test is expected to run
(some are definitely longer than others), and whether the 'quick' tag is
appropriate. But I will not necessarily be heartbroken if you can't
preserve it while making the test output easier to consume by other tooling.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> writes:

> 05.05.2019 18:54, Thomas Huth wrote:
>> On 03/05/2019 18.15, Alex Bennée wrote:
>>>
>>> Thomas Huth <thuth@redhat.com> writes:
>>>
>>>> On 03/05/2019 16.39, Alex Bennée wrote:
>>>>> This attempts to clean-up the output to better match the output of the
>>>>> rest of the QEMU check system. This includes:
>>>>>
>>>>>    - formatting as "  TEST    iotest: nnn"
>>>>>    - calculating time diff at the end
>>>>>    - only dumping config on failure
>>>>>
>>>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>>>> ---
>>>>>   tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>>>   1 file changed, 34 insertions(+), 37 deletions(-)
>>>>
>>>> Thanks for tackling this! The output now looks nicer indeed if you run
>>>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>>>> end of the command line, the outputs look quite different again...
>>>>
>>>> That's why I thought that having a TAP mode for the check script could
>>>> be a good idea, too. Then we could pipe the output through the
>>>> tap-driver.pl script, too, so we get uniform output for all tests...?
>>>
>>> That would probably be a cleaner approach. What would be even better is
>>> somehow expanding the list of tests at make time so you could run your
>>> tests in parallel.
>>
>> I agree that this might be the ultimate solution ... but I'm not sure
>> whether the iotests are really ready for being run in parallel yet, so
>> it will likely take quite some while 'till we are at that point. With
>> that in mind (and thus also not sure yet whether my TAP idea is really
>> the right approach), your patch is certainly a good interim solution
>> which we should try to get merged, too, when my "make check" series gets
>> accepted?
>>
>>> I did wonder how useful the timing stuff was to developers.
>>
>> Yes, me too ... maybe the block layer folks can comment on that one...?
>>
>>   Thomas
>>
>
> Hi!
>
> It was useful to not miss performance degradation (1) and
> to understand that test hangs (2) (if you know that it should
> finish in 1 second, but 10 seconds already passed, the test
> most probably hangs)
>
> Run tests with your patch:
>
> first run:
> # check -qcow2 -T
>    TEST    iotest: 001 [20:00:30] -> [20:00:31]
>    TEST    iotest: 002 [20:00:31] -> [20:00:33]
>    TEST    iotest: 003 [20:00:33] -> [20:00:34]
>    TEST    iotest: 004 [20:00:34] -> [20:00:35]
>    TEST    iotest: 005 [20:00:35] -> [20:00:36]
>    TEST    iotest: 007 [20:00:36] -> [20:00:39]
>
>
> second run:
> # check -qcow2 -T
>    TEST    iotest: 001 [20:00:41] -> [20:00:43] 2s (last 1s)
>    TEST    iotest: 002 [20:00:43] -> [20:00:44] 1s (last 2s)
>    TEST    iotest: 003 [20:00:44] -> [20:00:46] 2s (last 1s)
>    TEST    iotest: 004 [20:00:46] -> [20:00:46] 0s (last 1s)
>    TEST    iotest: 005 [20:00:46] -> [20:00:47] 1s (last 1s)
>    TEST    iotest: 007 [20:00:47] -> [20:00:50] 3s (last 3s)
>    TEST    iotest: 008 [20:00:50] -> [20:00:51]
>    TEST    iotest: 009 [20:00:51] -> [20:00:51]
>    TEST    iotest: 010 [20:00:51] -> [20:00:51]
>
>
> So, in first run delta was not calculated and on second - calculated.
> Could you calculate delta in all cases, to make first run look like
> # check -qcow2 -T
>    TEST    iotest: 001 [20:00:30] -> [20:00:31] 1s
>    TEST    iotest: 002 [20:00:31] -> [20:00:33] 2s
>    TEST    iotest: 003 [20:00:33] -> [20:00:34] 1s
>    TEST    iotest: 004 [20:00:34] -> [20:00:35] 1s
>    TEST    iotest: 005 [20:00:35] -> [20:00:36] 1s
>    TEST    iotest: 007 [20:00:36] -> [20:00:39] 3s

Sure that seems easy enough.

--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Alex Bennée]

Thomas Huth <thuth@redhat.com> writes:

> On 03/05/2019 18.15, Alex Bennée wrote:
>>
>> Thomas Huth <thuth@redhat.com> writes:
>>
>>> On 03/05/2019 16.39, Alex Bennée wrote:
>>>> This attempts to clean-up the output to better match the output of the
>>>> rest of the QEMU check system. This includes:
>>>>
>>>>   - formatting as "  TEST    iotest: nnn"
>>>>   - calculating time diff at the end
>>>>   - only dumping config on failure
>>>>
>>>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
>>>> ---
>>>>  tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>>  1 file changed, 34 insertions(+), 37 deletions(-)
>>>
>>> Thanks for tackling this! The output now looks nicer indeed if you run
>>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>>> end of the command line, the outputs look quite different again...
>>>
>>> That's why I thought that having a TAP mode for the check script could
>>> be a good idea, too. Then we could pipe the output through the
>>> tap-driver.pl script, too, so we get uniform output for all tests...?
>>
>> That would probably be a cleaner approach. What would be even better is
>> somehow expanding the list of tests at make time so you could run your
>> tests in parallel.
>
> I agree that this might be the ultimate solution ... but I'm not sure
> whether the iotests are really ready for being run in parallel yet, so
> it will likely take quite some while 'till we are at that point. With
> that in mind (and thus also not sure yet whether my TAP idea is really
> the right approach), your patch is certainly a good interim solution
> which we should try to get merged, too, when my "make check" series gets
> accepted?

I'm happy to take your series through my testing/next tree if the block
developers are happy with the hack-ups I've made to the test script to
make it fit in. There are a few comments which I can roll in and I'll
get testing/next posted tomorrow for final review.

--
Alex Bennée

Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Kevin Wolf]

Am 03.05.2019 um 16:39 hat Alex Bennée geschrieben:
> This attempts to clean-up the output to better match the output of the
> rest of the QEMU check system. This includes:
> 
>   - formatting as "  TEST    iotest: nnn"
>   - calculating time diff at the end
>   - only dumping config on failure
> 
> Signed-off-by: Alex Bennée <alex.bennee@linaro.org>

Hm... I see that this makes the output more consistent with other tests,
which is nice when it's run in the context of make check. I also think
the more consistent new output is uglier than the old output format.

I wonder whether we should have two modes - one that blends in with make
check, and another one that is provides nice and possibly more complete
output when the script is run manually.

> @@ -709,19 +703,6 @@ trap "_wrapup; exit \$status" 0 1 2 3 15
>  FULL_IMGFMT_DETAILS=$(_full_imgfmt_details)
>  FULL_HOST_DETAILS=$(_full_platform_details)
>  
> -cat <<EOF
> -QEMU          -- "$QEMU_PROG" $QEMU_OPTIONS
> -QEMU_IMG      -- "$QEMU_IMG_PROG" $QEMU_IMG_OPTIONS
> -QEMU_IO       -- "$QEMU_IO_PROG" $QEMU_IO_OPTIONS
> -QEMU_NBD      -- "$QEMU_NBD_PROG" $QEMU_NBD_OPTIONS
> -IMGFMT        -- $FULL_IMGFMT_DETAILS
> -IMGPROTO      -- $IMGPROTO
> -PLATFORM      -- $FULL_HOST_DETAILS
> -TEST_DIR      -- $TEST_DIR
> -SOCKET_SCM_HELPER -- $SOCKET_SCM_HELPER
> -
> -EOF

At the first sight, I have two things that I like to see improved at
least in the manual mode:

* The output above is now produced for each failing case when multiple
  tests are failing. I don't usually want to have my scroll buffer
  filled with tons of these, but I just want to see as many diffs as
  possible with as little scrolling as possible.

  If we have two modes, we can unconditionally display it at the start
  (like before this patch) in manual mode and completely disable it in
  make check mode. (It's rare that I need this information, and if make
  check fails, I should be trivially able to re-run it manually.)

* I'd like to see the currently running test with its start time and
  expected duration before it has finished. When running tests in the
  background, I often look at this information to check whether what's
  running is just a long-running test case or whether it hangs.

> -
>  seq="check"
>  
>  [ -n "$TESTS_REMAINING_LOG" ] && echo $list > $TESTS_REMAINING_LOG
> @@ -729,7 +710,9 @@ seq="check"
>  for seq in $list
>  do
>      err=false
> -    printf %s "$seq"
> +    reason=""
> +    times=""
> +
>      if [ -n "$TESTS_REMAINING_LOG" ] ; then
>          sed -e "s/$seq//" -e 's/  / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp
>          mv $TESTS_REMAINING_LOG.tmp $TESTS_REMAINING_LOG
> @@ -738,7 +721,7 @@ do
>  
>      if $showme
>      then
> -        echo
> +        echo "  TEST    iotest: $seq (not actually run)"
>          continue
>      elif [ -f expunged ] && $expunge && egrep "^$seq([         ]|\$)" expunged >/dev/null
>      then
> @@ -753,17 +736,11 @@ do
>          # really going to try and run this one
>          #
>          rm -f $seq.out.bad
> -        lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE)
> -        if [ "X$lasttime" != X ]; then
> -                printf %s " ${lasttime}s ..."
> -        else
> -                printf "        "        # prettier output with timestamps.
> -        fi
>          rm -f core $seq.notrun
>          rm -f $seq.casenotrun
>  
>          start=$(_wallclock)
> -        $timestamp && printf %s "        [$(date "+%T")]"
> +        $timestamp && times="[$(date "+%T")]"
>  
>          if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
>              run_command="$PYTHON $seq"
> @@ -781,26 +758,26 @@ do
>                      $run_command >$tmp.out 2>&1)
>          fi
>          sts=$?
> -        $timestamp && _timestamp
> +        $timestamp && times="$times -> [$(date "+%T")]"
>          stop=$(_wallclock)
>  
>          if [ -f core ]
>          then
> -            printf " [dumped core]"
>              mv core $seq.core
> +            reason="dumped core $seq.core"
>              err=true
>          fi
>  
>          if [ -f $seq.notrun ]
>          then
> -            $timestamp || printf " [not run] "
> -            $timestamp && echo " [not run]" && printf %s "        $seq -- "
> +            $timestamp || reason="[not run]"
> +            $timestamp && reason="[not run] $seq -- "

I don't see this reason turn up in the output anywhere. It gets printed
only for failures, but "not run" is not a failure. So all I get is
something like this:

$ ./check -T -raw 001-010
006 - unknown test, ignored
  TEST    iotest: 001 [09:48:38] -> [09:48:39] 1s (last 1s)
  TEST    iotest: 002 [09:48:39] -> [09:48:40] 1s (last 1s)
  TEST    iotest: 003 [09:48:40] -> [09:48:40] 0s (last 1s)
  TEST    iotest: 004 [09:48:40] -> [09:48:41] 1s (last 0s)
  TEST    iotest: 005 [09:48:41] -> [09:48:41] 0s (last 0s)
not suitable for this image format: raw
  TEST    iotest: 007 [09:48:41] -> [09:48:41]
  TEST    iotest: 008 [09:48:41] -> [09:48:41] 0s (last 1s)
  TEST    iotest: 009 [09:48:41] -> [09:48:42] 1s (last 0s)
  TEST    iotest: 010 [09:48:42] -> [09:48:42] 0s (last 0s)
Not run: 007
Passed all 8 tests

Note that the "not suitable for this image format: raw" comes _before_
the test that it refers to, without including the test number. If I
didn't know that 007 was the skipped test, I would interpret it as
belonging to test 005.

The indentation for the message that we had previously felt nicer, too,
but maybe only for manual mode because none of make check is nice like
that? Actually, is there any reason for make check to even print that
message for skipped tests? It only tests a subset of tests anyway, and
we'll still get the "Not run" list at the end.

Kevin