tests/qemu-iotests/check | 101 ++++++++++++++++++++++++++------------- 1 file changed, 68 insertions(+), 33 deletions(-)
This attempts to clean-up the output to better match the output of the
rest of the QEMU check system when called with -pretty. This includes:
- formatting as " TEST iotest: nnn"
- calculating time diff at the end
- only dumping config on failure (when -pretty enabled)
The existing output is mostly preserved although the dumping of the
old time at the start "Ns ..." was removed to keep the logic simple.
The timestamp mode can still be used to see which tests are "hanging".
Signed-off-by: Alex Bennée <alex.bennee@linaro.org>
Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org>
---
v3
- revert echo to printf
- add _report_test_start
---
tests/qemu-iotests/check | 101 ++++++++++++++++++++++++++-------------
1 file changed, 68 insertions(+), 33 deletions(-)
diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check
index 922c5d1d3d3..ac481f905bf 100755
--- a/tests/qemu-iotests/check
+++ b/tests/qemu-iotests/check
@@ -27,6 +27,7 @@ bad=""
notrun=""
casenotrun=""
interrupt=true
+pretty=false
# by default don't output timestamps
timestamp=${TIMESTAMP:=false}
@@ -88,6 +89,22 @@ _full_platform_details()
echo "$os/$platform $host $kernel"
}
+_full_env_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
+}
+
# $1 = prog to look for
set_prog_path()
{
@@ -256,6 +273,7 @@ other options
-o options -o options to pass to qemu-img create/convert
-T output timestamps
-c mode cache mode
+ -pretty pretty print output for make check
testlist options
-g group[,group...] include tests from these groups
@@ -403,7 +421,10 @@ testlist options
command -v xxdiff >/dev/null 2>&1 && diff=xxdiff
fi
;;
-
+ -pretty) # pretty print output
+ pretty=true
+ xpand=false
+ ;;
-n) # show me, don't do it
showme=true
xpand=false
@@ -704,23 +725,30 @@ END { if (NR > 0) {
trap "_wrapup; exit \$status" 0 1 2 3 15
+# Report the test start and results, optionally pretty printing for make
+# args: $seq
+_report_test_start()
+{
+ if $pretty; then
+ printf " TEST iotest: %s" "$1"
+ else
+ printf "%s" "$1"
+ fi
+}
+# args: output
+_report_test_result()
+{
+ printf "%s\n" "$1"
+}
+
[ -f $TIMESTAMP_FILE ] || touch $TIMESTAMP_FILE
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
+if ! $pretty; then
+ _full_env_details
+fi
seq="check"
@@ -728,8 +756,11 @@ seq="check"
for seq in $list
do
- err=false
- printf %s "$seq"
+ _report_test_start $seq
+ err=false # error flag
+ reason="" # reason for error
+ results="" # results for non-error/skip
+
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 +769,6 @@ do
if $showme
then
- echo
continue
elif [ -f expunged ] && $expunge && egrep "^$seq([ ]|\$)" expunged >/dev/null
then
@@ -753,17 +783,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 && _timestamp
if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then
run_command="$PYTHON $seq"
@@ -786,21 +810,19 @@ do
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 -- "
- cat $seq.notrun
- notrun="$notrun $seq"
+ # overwrites timestamp output
+ results="[not run] $(cat $seq.notrun)"
else
if [ $sts -ne 0 ]
then
- printf %s " [failed, exit status $sts]"
+ reason=$(printf %s "[failed, exit status $sts]")
err=true
fi
@@ -821,22 +843,29 @@ 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
+ results="${results}${thistime}s (last ${lasttime}s)"
+ else
+ results="${results}${thistime}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 +881,15 @@ do
#
if $err
then
+ _report_test_result " FAILED $reason"
+ if $pretty; then
+ _full_env_details
+ fi
bad="$bad $seq"
n_bad=$(expr $n_bad + 1)
quick=false
+ else
+ _report_test_result " $results"
fi
[ -f $seq.notrun ] || try=$(expr $try + 1)
--
2.20.1
On 10/05/2019 12.29, Alex Bennée wrote: > This attempts to clean-up the output to better match the output of the > rest of the QEMU check system when called with -pretty. This includes: > > - formatting as " TEST iotest: nnn" > - calculating time diff at the end > - only dumping config on failure (when -pretty enabled) > > The existing output is mostly preserved although the dumping of the > old time at the start "Ns ..." was removed to keep the logic simple. > The timestamp mode can still be used to see which tests are "hanging". > > Signed-off-by: Alex Bennée <alex.bennee@linaro.org> > Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org> > > --- > v3 > - revert echo to printf > - add _report_test_start > --- > tests/qemu-iotests/check | 101 ++++++++++++++++++++++++++------------- > 1 file changed, 68 insertions(+), 33 deletions(-) > > diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check > index 922c5d1d3d3..ac481f905bf 100755 > --- a/tests/qemu-iotests/check > +++ b/tests/qemu-iotests/check > @@ -27,6 +27,7 @@ bad="" > notrun="" > casenotrun="" > interrupt=true > +pretty=false > > # by default don't output timestamps > timestamp=${TIMESTAMP:=false} > @@ -88,6 +89,22 @@ _full_platform_details() > echo "$os/$platform $host $kernel" > } > > +_full_env_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 > +} > + > # $1 = prog to look for > set_prog_path() > { > @@ -256,6 +273,7 @@ other options > -o options -o options to pass to qemu-img create/convert > -T output timestamps > -c mode cache mode > + -pretty pretty print output for make check "pretty" is likely just a matter of taste ... so maybe this should be named differently instead? "--makecheck" ? Or "--one-shot" ? > testlist options > -g group[,group...] include tests from these groups > @@ -403,7 +421,10 @@ testlist options > command -v xxdiff >/dev/null 2>&1 && diff=xxdiff > fi > ;; > - > + -pretty) # pretty print output > + pretty=true > + xpand=false > + ;; > -n) # show me, don't do it > showme=true > xpand=false > @@ -704,23 +725,30 @@ END { if (NR > 0) { > > trap "_wrapup; exit \$status" 0 1 2 3 15 > > +# Report the test start and results, optionally pretty printing for make > +# args: $seq > +_report_test_start() > +{ > + if $pretty; then > + printf " TEST iotest: %s" "$1" Could you maybe change the "iotest:" into "iotest-$IMGFMT:" ? ... so that when you run "make check SPEED=slow" you also see which kind of format is currently under test? And this currently also does not play very nicely when running "make -j8 check" in parallel: [...] TEST iotest: 001 TEST check-qtest-alpha: tests/qmp-test TEST check-qtest-alpha: tests/qmp-cmd-test TEST check-qtest-aarch64: tests/boot-serial-test TEST check-qtest-aarch64: tests/migration-test TEST check-qtest-arm: tests/tmp105-test TEST check-unit: tests/check-qnum TEST check-unit: tests/check-qstring TEST check-unit: tests/check-qlist TEST check-unit: tests/check-qnull 2s (last 2s) TEST iotest: 002 TEST check-qtest-arm: tests/pca9552-test TEST check-unit: tests/check-qobject TEST check-qtest-cris: tests/qmp-test [...] I think the "make check" mode should only print out one time for each test, preferable at the end, like the other tests (like qtests) are doing it...? Thomas
Thomas Huth <thuth@redhat.com> writes: > On 10/05/2019 12.29, Alex Bennée wrote: >> This attempts to clean-up the output to better match the output of the >> rest of the QEMU check system when called with -pretty. This includes: >> >> - formatting as " TEST iotest: nnn" >> - calculating time diff at the end >> - only dumping config on failure (when -pretty enabled) >> >> The existing output is mostly preserved although the dumping of the >> old time at the start "Ns ..." was removed to keep the logic simple. >> The timestamp mode can still be used to see which tests are "hanging". >> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org> >> Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org> >> >> --- >> v3 >> - revert echo to printf >> - add _report_test_start >> --- >> tests/qemu-iotests/check | 101 ++++++++++++++++++++++++++------------- >> 1 file changed, 68 insertions(+), 33 deletions(-) >> >> diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check >> index 922c5d1d3d3..ac481f905bf 100755 >> --- a/tests/qemu-iotests/check >> +++ b/tests/qemu-iotests/check >> @@ -27,6 +27,7 @@ bad="" >> notrun="" >> casenotrun="" >> interrupt=true >> +pretty=false >> >> # by default don't output timestamps >> timestamp=${TIMESTAMP:=false} >> @@ -88,6 +89,22 @@ _full_platform_details() >> echo "$os/$platform $host $kernel" >> } >> >> +_full_env_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 >> +} >> + >> # $1 = prog to look for >> set_prog_path() >> { >> @@ -256,6 +273,7 @@ other options >> -o options -o options to pass to qemu-img create/convert >> -T output timestamps >> -c mode cache mode >> + -pretty pretty print output for make check > > "pretty" is likely just a matter of taste ... so maybe this should be > named differently instead? "--makecheck" ? Or "--one-shot" ? > >> testlist options >> -g group[,group...] include tests from these groups >> @@ -403,7 +421,10 @@ testlist options >> command -v xxdiff >/dev/null 2>&1 && diff=xxdiff >> fi >> ;; >> - >> + -pretty) # pretty print output >> + pretty=true >> + xpand=false >> + ;; >> -n) # show me, don't do it >> showme=true >> xpand=false >> @@ -704,23 +725,30 @@ END { if (NR > 0) { >> >> trap "_wrapup; exit \$status" 0 1 2 3 15 >> >> +# Report the test start and results, optionally pretty printing for make >> +# args: $seq >> +_report_test_start() >> +{ >> + if $pretty; then >> + printf " TEST iotest: %s" "$1" > > Could you maybe change the "iotest:" into "iotest-$IMGFMT:" ? ... so > that when you run "make check SPEED=slow" you also see which kind of > format is currently under test? Sure I can do that. > > And this currently also does not play very nicely when running "make -j8 > check" in parallel: > > [...] > TEST iotest: 001 TEST check-qtest-alpha: tests/qmp-test > TEST check-qtest-alpha: tests/qmp-cmd-test > TEST check-qtest-aarch64: tests/boot-serial-test > TEST check-qtest-aarch64: tests/migration-test > TEST check-qtest-arm: tests/tmp105-test > TEST check-unit: tests/check-qnum > TEST check-unit: tests/check-qstring > TEST check-unit: tests/check-qlist > TEST check-unit: tests/check-qnull > 2s (last 2s) > TEST iotest: 002 TEST check-qtest-arm: tests/pca9552-test > TEST check-unit: tests/check-qobject > TEST check-qtest-cris: tests/qmp-test > [...] > > I think the "make check" mode should only print out one time for each > test, preferable at the end, like the other tests (like qtests) are > doing it...? *sigh* and this is of course why deferred everything to the end in the last revision. Should we just assume the -pretty/-make whatever is incompatible with -T for the timestamp mode? > > Thomas -- Alex Bennée
On 10/05/2019 13.10, Alex Bennée wrote: > > Thomas Huth <thuth@redhat.com> writes: > >> On 10/05/2019 12.29, Alex Bennée wrote: >>> This attempts to clean-up the output to better match the output of the >>> rest of the QEMU check system when called with -pretty. This includes: >>> >>> - formatting as " TEST iotest: nnn" >>> - calculating time diff at the end >>> - only dumping config on failure (when -pretty enabled) >>> >>> The existing output is mostly preserved although the dumping of the >>> old time at the start "Ns ..." was removed to keep the logic simple. >>> The timestamp mode can still be used to see which tests are "hanging". >>> >>> Signed-off-by: Alex Bennée <alex.bennee@linaro.org> >>> Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org> >>> >>> --- >>> v3 >>> - revert echo to printf >>> - add _report_test_start >>> --- >>> tests/qemu-iotests/check | 101 ++++++++++++++++++++++++++------------- >>> 1 file changed, 68 insertions(+), 33 deletions(-) >>> >>> diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check >>> index 922c5d1d3d3..ac481f905bf 100755 >>> --- a/tests/qemu-iotests/check >>> +++ b/tests/qemu-iotests/check >>> @@ -27,6 +27,7 @@ bad="" >>> notrun="" >>> casenotrun="" >>> interrupt=true >>> +pretty=false >>> >>> # by default don't output timestamps >>> timestamp=${TIMESTAMP:=false} >>> @@ -88,6 +89,22 @@ _full_platform_details() >>> echo "$os/$platform $host $kernel" >>> } >>> >>> +_full_env_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 >>> +} >>> + >>> # $1 = prog to look for >>> set_prog_path() >>> { >>> @@ -256,6 +273,7 @@ other options >>> -o options -o options to pass to qemu-img create/convert >>> -T output timestamps >>> -c mode cache mode >>> + -pretty pretty print output for make check >> >> "pretty" is likely just a matter of taste ... so maybe this should be >> named differently instead? "--makecheck" ? Or "--one-shot" ? >> >>> testlist options >>> -g group[,group...] include tests from these groups >>> @@ -403,7 +421,10 @@ testlist options >>> command -v xxdiff >/dev/null 2>&1 && diff=xxdiff >>> fi >>> ;; >>> - >>> + -pretty) # pretty print output >>> + pretty=true >>> + xpand=false >>> + ;; >>> -n) # show me, don't do it >>> showme=true >>> xpand=false >>> @@ -704,23 +725,30 @@ END { if (NR > 0) { >>> >>> trap "_wrapup; exit \$status" 0 1 2 3 15 >>> >>> +# Report the test start and results, optionally pretty printing for make >>> +# args: $seq >>> +_report_test_start() >>> +{ >>> + if $pretty; then >>> + printf " TEST iotest: %s" "$1" >> >> Could you maybe change the "iotest:" into "iotest-$IMGFMT:" ? ... so >> that when you run "make check SPEED=slow" you also see which kind of >> format is currently under test? > > Sure I can do that. > >> >> And this currently also does not play very nicely when running "make -j8 >> check" in parallel: >> >> [...] >> TEST iotest: 001 TEST check-qtest-alpha: tests/qmp-test >> TEST check-qtest-alpha: tests/qmp-cmd-test >> TEST check-qtest-aarch64: tests/boot-serial-test >> TEST check-qtest-aarch64: tests/migration-test >> TEST check-qtest-arm: tests/tmp105-test >> TEST check-unit: tests/check-qnum >> TEST check-unit: tests/check-qstring >> TEST check-unit: tests/check-qlist >> TEST check-unit: tests/check-qnull >> 2s (last 2s) >> TEST iotest: 002 TEST check-qtest-arm: tests/pca9552-test >> TEST check-unit: tests/check-qobject >> TEST check-qtest-cris: tests/qmp-test >> [...] >> >> I think the "make check" mode should only print out one time for each >> test, preferable at the end, like the other tests (like qtests) are >> doing it...? > > *sigh* and this is of course why deferred everything to the end in the > last revision. Should we just assume the -pretty/-make whatever is > incompatible with -T for the timestamp mode? Fine for me. ... and maybe that's one more reason to call the parameter rather "-makecheck" or so instead, so that it is clear that this mode is not to be mixed with other parameters that influence the output. Thomas
On 10/05/2019 12.48, Thomas Huth wrote: [...] > > I think the "make check" mode should only print out one time for each > test, preferable at the end, like the other tests (like qtests) are > doing it...? s/preferable at the end/preferably at the beginning/ ... I think the makefile rules for the other tests are printing out " TEST xyz" *before* the test is started. And the iotests "check" script should do the same. Thomas
Thomas Huth <thuth@redhat.com> writes: > On 10/05/2019 12.48, Thomas Huth wrote: > [...] >> >> I think the "make check" mode should only print out one time for each >> test, preferable at the end, like the other tests (like qtests) are >> doing it...? > > s/preferable at the end/preferably at the beginning/ > > ... I think the makefile rules for the other tests are printing out > " TEST xyz" *before* the test is started. And the iotests "check" > script should do the same. That mean dropping the execution time (and previous execution time and possible failure). We could just duplicate on failure modes so you get: TEST iotest: 007 TEST iotest: 007 [not run] not suitable for this image format: raw when there is something other than a passed test to report. > > Thomas -- Alex Bennée
Am 10.05.2019 um 12:29 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 when called with -pretty. This includes: > > - formatting as " TEST iotest: nnn" > - calculating time diff at the end > - only dumping config on failure (when -pretty enabled) > > The existing output is mostly preserved although the dumping of the > old time at the start "Ns ..." was removed to keep the logic simple. > The timestamp mode can still be used to see which tests are "hanging". > > Signed-off-by: Alex Bennée <alex.bennee@linaro.org> > Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org> I played with it a bit more and ended up with the following patch to be applied on top. Maybe you like some parts of it. I'm now printing an \r at the end of the line that is printed at the start of the test case. Normally that will be overwritten by the result line which contains the same information again, but if you're running multiple tests in parallel, it will be overwritten by something else - which I think isn't a big problem because at the end, the result line will still appear somewhere. I fixed some bugs, too, like the "not run" list being broken. Kevin diff --git a/tests/qemu-iotests/check b/tests/qemu-iotests/check index 4cfe2362f5..463ff82854 100755 --- a/tests/qemu-iotests/check +++ b/tests/qemu-iotests/check @@ -27,7 +27,7 @@ bad="" notrun="" casenotrun="" interrupt=true -pretty=false +make_check=false # by default don't output timestamps timestamp=${TIMESTAMP:=false} @@ -274,7 +274,7 @@ other options -o options -o options to pass to qemu-img create/convert -T output timestamps -c mode cache mode - -pretty pretty print output for make check + -make-check print short output for make check testlist options -g group[,group...] include tests from these groups @@ -422,8 +422,8 @@ testlist options command -v xxdiff >/dev/null 2>&1 && diff=xxdiff fi ;; - -pretty) # pretty print output - pretty=true + -make-check) # output for make check + make_check=true xpand=false ;; -n) # show me, don't do it @@ -643,12 +643,6 @@ _wallclock() date "+%H %M %S" | awk '{ print $1*3600 + $2*60 + $3 }' } -_timestamp() -{ - now=$(date "+%T") - printf %s " [$now]" -} - _wrapup() { if $showme @@ -671,11 +665,10 @@ END { if (NR > 0) { if [ -f $tmp.expunged ] then - notrun=$(wc -l <$tmp.expunged | sed -e 's/ *//g') - try=$(expr $try - $notrun) list=$(echo "$list" | sed -f $tmp.expunged) fi + echo echo "" >>check.log date >>check.log echo $list | fmt | sed -e 's/^/ /' >>check.log @@ -714,20 +707,48 @@ END { if (NR > 0) { trap "_wrapup; exit \$status" 0 1 2 3 15 -# Report the test start and results, optionally pretty printing for make -# args: $seq +# Report the test start and results, optionally short format for make check +# args: $seq, $starttime, $lasttime _report_test_start() { - if $pretty; then - printf " TEST iotest: %s" "$1" - else - printf "%s" "$1" + if $make_check; then + printf " TEST iotest: %s\r" "$1" + return fi + + if [ -n "$3" ]; then + local lasttime=" (last: $3s)" + fi + printf "%-8s %-10s [%s] %4s%-14s\r" "$1" "..." "$2" "..." "$lasttime" } -# args: output + +# args: $seq, $starttime, $lasttime, $thistime, $status, details _report_test_result() { - printf "%s\n" "$1" + local status lasttime thistime + + if $make_check; then + if [ -n "$5" ] && [ "$5" != "pass" ]; then + status=" [$5]" + fi + printf " TEST iotest: %s%s\n" "$1" "$status" + return + fi + + if [ -n "$3" ]; then + lasttime=" (last: $3s)" + fi + if [ -n "$4" ]; then + thistime=" $4s" + fi + case "$5" in + "pass") status=$(printf "\e[32m%-10s\e[0m" "$5") ;; + "fail") status=$(printf "\e[1m\e[31m%-10s\e[0m" "$5") ;; + "not run") status=$(printf "\e[33m%-10s\e[0m" "$5") ;; + *) status=$(printf "%-10s" "$5") ;; + esac + + printf "%-8s %s [%s] [%s] %4s%-14s %s\n" "$1" "$status" "$2" "$(date '+%T')" "$thistime" "$lasttime" "$6" } [ -f $TIMESTAMP_FILE ] || touch $TIMESTAMP_FILE @@ -735,7 +756,7 @@ _report_test_result() FULL_IMGFMT_DETAILS=$(_full_imgfmt_details) FULL_HOST_DETAILS=$(_full_platform_details) -if ! $pretty; then +if ! $make_check; then _full_env_details fi @@ -745,10 +766,10 @@ seq="check" for seq in $list do - _report_test_start $seq - err=false # error flag - reason="" # reason for error - results="" # results for non-error/skip + err=false # error flag + printdiff=false # show diff to reference output? + status="" # test result summary + results="" # test result details if [ -n "$TESTS_REMAINING_LOG" ] ; then sed -e "s/$seq//" -e 's/ / /' -e 's/^ *//' $TESTS_REMAINING_LOG > $TESTS_REMAINING_LOG.tmp @@ -756,17 +777,23 @@ do sync fi + lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE) + starttime=$(date "+%T") + _report_test_start $seq $starttime $lasttime + if $showme then - continue + status="not run" elif [ -f expunged ] && $expunge && egrep "^$seq([ ]|\$)" expunged >/dev/null then - echo " - expunged" + status="not run" + results="expunged" rm -f $seq.out.bad echo "/^$seq\$/d" >>$tmp.expunged elif [ ! -f "$source_iotests/$seq" ] then - echo " - no such test?" + status="not run" + results="no such test?" echo "/^$seq\$/d" >>$tmp.expunged else # really going to try and run this one @@ -776,7 +803,6 @@ do rm -f $seq.casenotrun start=$(_wallclock) - $timestamp && _timestamp if [ "$(head -n 1 "$source_iotests/$seq")" == "#!/usr/bin/env python" ]; then run_command="$PYTHON $seq" @@ -794,24 +820,26 @@ do $run_command >$tmp.out 2>&1) fi sts=$? - $timestamp && _timestamp stop=$(_wallclock) if [ -f core ] then mv core $seq.core - reason="[dumped core] $seq.core" + status="fail" + results="[dumped core] $seq.core" err=true fi if [ -f $seq.notrun ] then # overwrites timestamp output - results="[not run] $(cat $seq.notrun)" + status="not run" + results="$(cat $seq.notrun)" else if [ $sts -ne 0 ] then - reason=$(printf %s "[failed, exit status $sts]") + status="fail" + results=$(printf %s "[failed, exit status $sts]") err=true fi @@ -830,31 +858,24 @@ do [ -f "$source_iotests/$seq.out.nocache" ] && reference="$source_iotests/$seq.out.nocache" fi + thistime=$(expr $stop - $start) if [ ! -f "$reference" ] then - reason="- no qualified output" + status="fail" + results="no qualified output" err=true else if diff -w "$reference" $tmp.out >/dev/null 2>&1 then - if $err - then - : - else - lasttime=$(sed -n -e "/^$seq /s/.* //p" <$TIMESTAMP_FILE) - thistime=$(expr $stop - $start) + if ! $err; then + status="pass" echo "$seq $thistime" >>$tmp.time - - if [ "X$lasttime" != X ]; then - results="${results}${thistime}s (last ${lasttime}s)" - else - results="${results}${thistime}s" - fi fi else mv $tmp.out $seq.out.bad - $diff -w "$reference" "$PWD"/$seq.out.bad - reason="- output mismatch (see $seq.out.bad)" + status="fail" + results="output mismatch (see $seq.out.bad)" + printdiff=true err=true fi fi @@ -868,19 +889,28 @@ do # come here for each test, except when $showme is true # - if $err - then - _report_test_result " FAILED $reason" - if $pretty; then - _full_env_details - fi - bad="$bad $seq" - n_bad=$(expr $n_bad + 1) - quick=false - else - _report_test_result " $results" - fi - [ -f $seq.notrun ] || try=$(expr $try + 1) + _report_test_result $seq "$starttime" "$lasttime" "$thistime" "$status" "$results" + + case "$status" in + "pass") + try=$(expr $try + 1) + ;; + "fail") + try=$(expr $try + 1) + if $make_check; then + _full_env_details + fi + if $printdiff; then + $diff -w "$reference" "$PWD"/$seq.out.bad + fi + bad="$bad $seq" + n_bad=$(expr $n_bad + 1) + quick=false + ;; + "not run") + notrun="$notrun $seq" + ;; + esac seq="after_$seq" done
Kevin Wolf <kwolf@redhat.com> writes: > Am 10.05.2019 um 12:29 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 when called with -pretty. This includes: >> >> - formatting as " TEST iotest: nnn" >> - calculating time diff at the end >> - only dumping config on failure (when -pretty enabled) >> >> The existing output is mostly preserved although the dumping of the >> old time at the start "Ns ..." was removed to keep the logic simple. >> The timestamp mode can still be used to see which tests are "hanging". >> >> Signed-off-by: Alex Bennée <alex.bennee@linaro.org> >> Message-Id: <20190503143904.31211-1-alex.bennee@linaro.org> > > I played with it a bit more and ended up with the following patch to be > applied on top. Maybe you like some parts of it. > > I'm now printing an \r at the end of the line that is printed at the > start of the test case. Normally that will be overwritten by the result > line which contains the same information again, but if you're running > multiple tests in parallel, it will be overwritten by something else - > which I think isn't a big problem because at the end, the result line > will still appear somewhere. > > I fixed some bugs, too, like the "not run" list being broken. Thanks, I've merged those changes in with a few minor tweaks for the makecheck version (single phase output, dropped the defunct -T option). I'll send out testing/next shortly. -- Alex Bennée
© 2016 - 2024 Red Hat, Inc.