[Qemu-devel] [kvm-unit-tests PATCH v2 0/2] run_tests: support concurrent test execution

[Qemu-devel] [kvm-unit-tests PATCH v2 0/2] run_tests: support concurrent test execution

[Peter Xu]

v2:
- patch 1: do per-test logging in all cases
- patch 2: throw away task.bash, instead, take Radim's suggestion to
  use jobs

run_tests.sh is getting slower. Maybe it's time to let it run faster.
An obvious issue is that, we were running the tests sequentially in
the past.

This series provides another new "-j" parameter. "-j 8" means we run
the tests on 8 task queues. That'll fasten the script a lot. A very
quick test of mine shows 3x speed boost with 8 task queues.

Please review, thanks.

Peter Xu (2):
  run_tests: put logs into per-test file
  run_tests: allow run tests in parallel

 Makefile               |  4 ++--
 run_tests.sh           | 26 ++++++++++++++++++--------
 scripts/functions.bash | 24 ++++++++++++++++++++++--
 scripts/global.bash    | 13 +++++++++++++
 4 files changed, 55 insertions(+), 12 deletions(-)
 create mode 100644 scripts/global.bash

-- 
2.7.4

[Qemu-devel] [kvm-unit-tests PATCH v2 1/2] run_tests: put logs into per-test file

[Peter Xu]

We were using test.log before to keep all the test logs. This patch
creates one log file per test case under logs/ directory with name
"TESTNAME.log".

A new file global.bash is added to store global informations.

Signed-off-by: Peter Xu <peterx@redhat.com>
---
 Makefile               |  4 ++--
 run_tests.sh           | 14 ++++++++------
 scripts/functions.bash | 11 +++++++++--
 scripts/global.bash    |  2 ++
 4 files changed, 21 insertions(+), 10 deletions(-)
 create mode 100644 scripts/global.bash

diff --git a/Makefile b/Makefile
index a32333b..f632c6c 100644
--- a/Makefile
+++ b/Makefile
@@ -94,9 +94,9 @@ libfdt_clean:
 	$(LIBFDT_objdir)/.*.d
 
 distclean: clean libfdt_clean
-	$(RM) lib/asm config.mak $(TEST_DIR)-run test.log msr.out cscope.* \
+	$(RM) lib/asm config.mak $(TEST_DIR)-run msr.out cscope.* \
 	      build-head
-	$(RM) -r tests
+	$(RM) -r tests logs
 
 cscope: cscope_dirs = lib lib/libfdt lib/linux $(TEST_DIR) $(ARCH_LIBDIRS) lib/asm-generic
 cscope:
diff --git a/run_tests.sh b/run_tests.sh
index 254129d..e1bb3a6 100755
--- a/run_tests.sh
+++ b/run_tests.sh
@@ -7,6 +7,7 @@ if [ ! -f config.mak ]; then
     exit 1
 fi
 source config.mak
+source scripts/global.bash
 source scripts/functions.bash
 
 function usage()
@@ -46,17 +47,18 @@ while getopts "g:hv" opt; do
     esac
 done
 
-RUNTIME_log_stderr () { cat >> test.log; }
+# RUNTIME_log_file will be configured later
+RUNTIME_log_stderr () { cat >> $RUNTIME_log_file; }
 RUNTIME_log_stdout () {
     if [ "$PRETTY_PRINT_STACKS" = "yes" ]; then
-        ./scripts/pretty_print_stacks.py $1 >> test.log
+        ./scripts/pretty_print_stacks.py $1 >> $RUNTIME_log_file
     else
-        cat >> test.log
+        cat >> $RUNTIME_log_file
     fi
 }
 
-
 config=$TEST_DIR/unittests.cfg
-rm -f test.log
-printf "BUILD_HEAD=$(cat build-head)\n\n" > test.log
+rm -rf $ut_log_dir
+mkdir $ut_log_dir
+printf "BUILD_HEAD=$(cat build-head)\n\n" > $ut_log_summary
 for_each_unittest $config run
diff --git a/scripts/functions.bash b/scripts/functions.bash
index ee9143c..d1d2e1c 100644
--- a/scripts/functions.bash
+++ b/scripts/functions.bash
@@ -1,3 +1,10 @@
+function run_task()
+{
+	local testname="$2"
+
+	RUNTIME_log_file="${ut_log_dir}/${testname}.log"
+	"$@"
+}
 
 function for_each_unittest()
 {
@@ -17,7 +24,7 @@ function for_each_unittest()
 
 	while read -u $fd line; do
 		if [[ "$line" =~ ^\[(.*)\]$ ]]; then
-			"$cmd" "$testname" "$groups" "$smp" "$kernel" "$opts" "$arch" "$check" "$accel" "$timeout"
+			run_task "$cmd" "$testname" "$groups" "$smp" "$kernel" "$opts" "$arch" "$check" "$accel" "$timeout"
 			testname=${BASH_REMATCH[1]}
 			smp=1
 			kernel=""
@@ -45,6 +52,6 @@ function for_each_unittest()
 			timeout=${BASH_REMATCH[1]}
 		fi
 	done
-	"$cmd" "$testname" "$groups" "$smp" "$kernel" "$opts" "$arch" "$check" "$accel" "$timeout"
+	run_task "$cmd" "$testname" "$groups" "$smp" "$kernel" "$opts" "$arch" "$check" "$accel" "$timeout"
 	exec {fd}<&-
 }
diff --git a/scripts/global.bash b/scripts/global.bash
new file mode 100644
index 0000000..77b0b29
--- /dev/null
+++ b/scripts/global.bash
@@ -0,0 +1,2 @@
+: ${ut_log_dir:=logs}
+: ${ut_log_summary:=${ut_log_dir}/SUMMARY}
-- 
2.7.4

[Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Peter Xu]

run_task.sh is getting slow. This patch is trying to make it faster by
running the tests concurrently.

We provide a new parameter "-j" for the run_tests.sh, which can be used
to specify how many run queues we want for the tests. Default queue
length is 1, which is the old behavior.

Quick test on my laptop (4 cores, 2 threads each) shows 3x speed boost:

   |-----------------+-----------|
   | command         | time used |
   |-----------------+-----------|
   | run_test.sh     | 75s       |
   | run_test.sh -j8 | 27s       |
   |-----------------+-----------|

Suggested-by: Radim Krčmář <rkrcmar@redhat.com>
Signed-off-by: Peter Xu <peterx@redhat.com>
---
 run_tests.sh           | 12 ++++++++++--
 scripts/functions.bash | 15 ++++++++++++++-
 scripts/global.bash    | 11 +++++++++++
 3 files changed, 35 insertions(+), 3 deletions(-)

diff --git a/run_tests.sh b/run_tests.sh
index e1bb3a6..a4fc895 100755
--- a/run_tests.sh
+++ b/run_tests.sh
@@ -14,10 +14,11 @@ function usage()
 {
 cat <<EOF
 
-Usage: $0 [-g group] [-h] [-v]
+Usage: $0 [-g group] [-h] [-v] [-j N]
 
     -g: Only execute tests in the given group
     -h: Output this help text
+    -j: Execute tests in parallel
     -v: Enables verbose mode
 
 Set the environment variable QEMU=/path/to/qemu-system-ARCH to
@@ -29,7 +30,7 @@ EOF
 RUNTIME_arch_run="./$TEST_DIR/run"
 source scripts/runtime.bash
 
-while getopts "g:hv" opt; do
+while getopts "g:hj:v" opt; do
     case $opt in
         g)
             only_group=$OPTARG
@@ -38,6 +39,13 @@ while getopts "g:hv" opt; do
             usage
             exit
             ;;
+        j)
+            ut_run_queues=$OPTARG
+            if ! is_number "$ut_run_queues"; then
+                echo "Invalid -j option: $ut_run_queues"
+                exit 1
+            fi
+            ;;
         v)
             verbose="yes"
             ;;
diff --git a/scripts/functions.bash b/scripts/functions.bash
index d1d2e1c..acb306b 100644
--- a/scripts/functions.bash
+++ b/scripts/functions.bash
@@ -1,9 +1,18 @@
+source scripts/global.bash
+
 function run_task()
 {
 	local testname="$2"
 
+	while [[ "$(jobs | wc -l)" == $ut_run_queues ]]; do
+		# wait for any background test to finish
+		wait -n
+	done
+
 	RUNTIME_log_file="${ut_log_dir}/${testname}.log"
-	"$@"
+
+	# start the testcase in the background
+	"$@" &
 }
 
 function for_each_unittest()
@@ -53,5 +62,9 @@ function for_each_unittest()
 		fi
 	done
 	run_task "$cmd" "$testname" "$groups" "$smp" "$kernel" "$opts" "$arch" "$check" "$accel" "$timeout"
+
+	# wait all task finish
+	wait
+
 	exec {fd}<&-
 }
diff --git a/scripts/global.bash b/scripts/global.bash
index 77b0b29..52095bd 100644
--- a/scripts/global.bash
+++ b/scripts/global.bash
@@ -1,2 +1,13 @@
 : ${ut_log_dir:=logs}
 : ${ut_log_summary:=${ut_log_dir}/SUMMARY}
+: ${ut_run_queues:=1}
+
+function ut_in_parallel()
+{
+    [[ $ut_run_queues != 1 ]]
+}
+
+function is_number()
+{
+    [[ "$1" =~ ^[0-9]+$ ]]
+}
-- 
2.7.4

Re: [Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Peter Xu]

On Tue, Jan 03, 2017 at 06:10:05PM +0800, Peter Xu wrote:

[...]

> diff --git a/scripts/global.bash b/scripts/global.bash
> index 77b0b29..52095bd 100644
> --- a/scripts/global.bash
> +++ b/scripts/global.bash
> @@ -1,2 +1,13 @@
>  : ${ut_log_dir:=logs}
>  : ${ut_log_summary:=${ut_log_dir}/SUMMARY}
> +: ${ut_run_queues:=1}
> +
> +function ut_in_parallel()
> +{
> +    [[ $ut_run_queues != 1 ]]
> +}
> +

This function is useless now. Should remove above five lines. Sorry.

-- peterx

Re: [Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Radim Krčmář]

2017-01-03 18:10+0800, Peter Xu:
> run_task.sh is getting slow. This patch is trying to make it faster by
> running the tests concurrently.
> 
> We provide a new parameter "-j" for the run_tests.sh, which can be used
> to specify how many run queues we want for the tests. Default queue
> length is 1, which is the old behavior.
> 
> Quick test on my laptop (4 cores, 2 threads each) shows 3x speed boost:
> 
>    |-----------------+-----------|
>    | command         | time used |
>    |-----------------+-----------|
>    | run_test.sh     | 75s       |
>    | run_test.sh -j8 | 27s       |
>    |-----------------+-----------|
> 
> Suggested-by: Radim Krčmář <rkrcmar@redhat.com>
> Signed-off-by: Peter Xu <peterx@redhat.com>
> ---
>  run_tests.sh           | 12 ++++++++++--
>  scripts/functions.bash | 15 ++++++++++++++-
>  scripts/global.bash    | 11 +++++++++++
>  3 files changed, 35 insertions(+), 3 deletions(-)

I like this diffstat a lot more, thanks :)

The script doesn't handle ^C well now (at least), which can be worked
around with

  trap exit SIGINT

but it would be nice to know if receiving signals in `wait` can't be
fixed.

Re: [Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Peter Xu]

On Wed, Jan 04, 2017 at 04:09:39PM +0100, Radim Krčmář wrote:
> 2017-01-03 18:10+0800, Peter Xu:
> > run_task.sh is getting slow. This patch is trying to make it faster by
> > running the tests concurrently.
> > 
> > We provide a new parameter "-j" for the run_tests.sh, which can be used
> > to specify how many run queues we want for the tests. Default queue
> > length is 1, which is the old behavior.
> > 
> > Quick test on my laptop (4 cores, 2 threads each) shows 3x speed boost:
> > 
> >    |-----------------+-----------|
> >    | command         | time used |
> >    |-----------------+-----------|
> >    | run_test.sh     | 75s       |
> >    | run_test.sh -j8 | 27s       |
> >    |-----------------+-----------|
> > 
> > Suggested-by: Radim Krčmář <rkrcmar@redhat.com>
> > Signed-off-by: Peter Xu <peterx@redhat.com>
> > ---
> >  run_tests.sh           | 12 ++++++++++--
> >  scripts/functions.bash | 15 ++++++++++++++-
> >  scripts/global.bash    | 11 +++++++++++
> >  3 files changed, 35 insertions(+), 3 deletions(-)
> 
> I like this diffstat a lot more, thanks :)
> 
> The script doesn't handle ^C well now (at least), which can be worked
> around with
> 
>   trap exit SIGINT
> 
> but it would be nice to know if receiving signals in `wait` can't be
> fixed.

When I send SIGINT to "run_tests.sh -j8", I see process hang dead. Not
sure whether you see the same thing:

#0  0x00007f7af2e1559a in waitpid () from /lib64/libc.so.6
#1  0x00005613edf8953e in waitchld.isra ()
#2  0x00005613edf8aae5 in wait_for ()
#3  0x00005613edf8b682 in wait_for_any_job ()
#4  0x00005613edfc7e64 in wait_builtin ()
#5  0x00005613edf616ea in execute_builtin.isra ()
#6  0x00005613edf623ee in execute_simple_command ()
#7  0x00005613edf79e77 in execute_command_internal ()
#8  0x00005613edf7b972 in execute_command ()
#9  0x00005613edf62aca in execute_while_or_until ()
#10 0x00005613edf7a156 in execute_command_internal ()
#11 0x00005613edf79d88 in execute_command_internal ()
...

If I change the "wait -n" into "wait" (this will work, but of course
slower since we'll wait for all subprocesses end before we start
another one), problem disappears. Not sure whether that means a "wait
-n" bug.

Anyway, IMHO squashing you suggestion of "trap exit SIGINT" at the
entry of for_each_unittest() is an acceptable solution - it works in
all cases.

Thanks,

-- peterx

Re: [Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Radim Krčmář]

2017-01-05 11:07+0800, Peter Xu:
> On Wed, Jan 04, 2017 at 04:09:39PM +0100, Radim Krčmář wrote:
>> 2017-01-03 18:10+0800, Peter Xu:
>> > run_task.sh is getting slow. This patch is trying to make it faster by
>> > running the tests concurrently.
>> > 
>> > We provide a new parameter "-j" for the run_tests.sh, which can be used
>> > to specify how many run queues we want for the tests. Default queue
>> > length is 1, which is the old behavior.
>> > 
>> > Quick test on my laptop (4 cores, 2 threads each) shows 3x speed boost:
>> > 
>> >    |-----------------+-----------|
>> >    | command         | time used |
>> >    |-----------------+-----------|
>> >    | run_test.sh     | 75s       |
>> >    | run_test.sh -j8 | 27s       |
>> >    |-----------------+-----------|
>> > 
>> > Suggested-by: Radim Krčmář <rkrcmar@redhat.com>
>> > Signed-off-by: Peter Xu <peterx@redhat.com>
>> > ---
>> >  run_tests.sh           | 12 ++++++++++--
>> >  scripts/functions.bash | 15 ++++++++++++++-
>> >  scripts/global.bash    | 11 +++++++++++
>> >  3 files changed, 35 insertions(+), 3 deletions(-)
>> 
>> I like this diffstat a lot more, thanks :)
>> 
>> The script doesn't handle ^C well now (at least), which can be worked
>> around with
>> 
>>   trap exit SIGINT
>> 
>> but it would be nice to know if receiving signals in `wait` can't be
>> fixed.
> 
> When I send SIGINT to "run_tests.sh -j8", I see process hang dead. Not
> sure whether you see the same thing:
> 
> #0  0x00007f7af2e1559a in waitpid () from /lib64/libc.so.6
> #1  0x00005613edf8953e in waitchld.isra ()
> #2  0x00005613edf8aae5 in wait_for ()
> #3  0x00005613edf8b682 in wait_for_any_job ()
> #4  0x00005613edfc7e64 in wait_builtin ()
> #5  0x00005613edf616ea in execute_builtin.isra ()
> #6  0x00005613edf623ee in execute_simple_command ()
> #7  0x00005613edf79e77 in execute_command_internal ()
> #8  0x00005613edf7b972 in execute_command ()
> #9  0x00005613edf62aca in execute_while_or_until ()
> #10 0x00005613edf7a156 in execute_command_internal ()
> #11 0x00005613edf79d88 in execute_command_internal ()
> ...

I do.  And sometimes, I also caught it in a signal handler:

  #0  0x00007f7461bcd637 in kill () at ../sysdeps/unix/syscall-template.S:84
  #1  0x00000000004476b9 in wait_sigint_handler (sig=<optimized out>) at jobs.c:2504
  #2  <signal handler called>
  #3  0x00007f7461c674ca in __GI___waitpid (pid=pid@entry=-1, stat_loc=stat_loc@entry=0x7ffdb49dfbd8, 
      options=options@entry=0) at ../sysdeps/unix/sysv/linux/waitpid.c:29
  #4  0x0000000000449cfb in waitchld (block=block@entry=1, wpid=-1) at jobs.c:3474
  #5  0x000000000044b2eb in wait_for (pid=pid@entry=-1) at jobs.c:2718
  #6  0x000000000044becd in wait_for_any_job () at jobs.c:3015
  #7  0x000000000048c38b in wait_builtin (list=0x0) at ./wait.def:154
  ...

> 
> If I change the "wait -n" into "wait" (this will work, but of course
> slower since we'll wait for all subprocesses end before we start
> another one), problem disappears.

Yeah, and just `wait` doesn't work with -j1 ... using `jobs -r` gets rid
of it.

>                                   Not sure whether that means a "wait
> -n" bug.

Most likely a bash bug:
 - doesn't happen if you SIGINT before the first job has finished
 - doesn't happen with normal wait

> Anyway, IMHO squashing you suggestion of "trap exit SIGINT" at the
> entry of for_each_unittest() is an acceptable solution - it works in
> all cases.

Seems like the best solution at this time ...
We actually want to "exit 130", as it would when using normal wait does,
and maybe it could be improved a bit by adding a wait:

  trap 'wait; exit 130' SIGINT

Re: [Qemu-devel] [kvm-unit-tests PATCH v2 2/2] run_tests: allow run tests in parallel

[Peter Xu]

On Thu, Jan 05, 2017 at 08:44:02PM +0100, Radim Krčmář wrote:

[...]

> > Anyway, IMHO squashing you suggestion of "trap exit SIGINT" at the
> > entry of for_each_unittest() is an acceptable solution - it works in
> > all cases.
> 
> Seems like the best solution at this time ...
> We actually want to "exit 130", as it would when using normal wait does,
> and maybe it could be improved a bit by adding a wait:
> 
>   trap 'wait; exit 130' SIGINT

Sounds better, thanks!

Will repost with this one.

-- peterx