[kvm-unit-tests PATCH v1 0/2] s390x: Add exit time test

[kvm-unit-tests PATCH v1 0/2] s390x: Add exit time test

[Nico Boehr]

Sometimes, it is useful to measure the exit time of certain instructions
to e.g. identify performance regressions in instructions emulated by the
hypervisor.

This series adds a test which executes some instructions and measures
their execution time. Since their execution time depends a lot on the
environment at hand, all tests are reported as PASS currently.

The point of this series is not so much the instructions which have been
chosen here (but your ideas are welcome), but rather the general
question whether it makes sense to have a test like this in
kvm-unit-tests.

Nico Boehr (2):
  lib/s390x: time: add wrapper for stckf
  s390x: add exittime tests

 lib/s390x/asm/time.h |   9 ++
 s390x/Makefile       |   1 +
 s390x/exittime.c     | 258 +++++++++++++++++++++++++++++++++++++++++++
 s390x/unittests.cfg  |   4 +
 4 files changed, 272 insertions(+)
 create mode 100644 s390x/exittime.c

-- 
2.36.1

[kvm-unit-tests PATCH v1 1/2] lib/s390x: time: add wrapper for stckf

[Nico Boehr]

Upcoming changes will do performance measurements of instructions. Since
stck is designed to return unique values even on concurrent calls, it is
unsuited for performance measurements. stckf should be used in this
case.

Hence, add a nice wrapper for stckf to the time library.

Signed-off-by: Nico Boehr <nrb@linux.ibm.com>
---
 lib/s390x/asm/time.h | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/lib/s390x/asm/time.h b/lib/s390x/asm/time.h
index 7652a151e87a..d7c2bcb4f306 100644
--- a/lib/s390x/asm/time.h
+++ b/lib/s390x/asm/time.h
@@ -14,6 +14,15 @@
 #define STCK_SHIFT_US	(63 - 51)
 #define STCK_MAX	((1UL << 52) - 1)
 
+static inline uint64_t get_clock_fast(void)
+{
+	uint64_t clk;
+
+	asm volatile(" stckf %0 " : : "Q"(clk) : "memory");
+
+	return clk;
+}
+
 static inline uint64_t get_clock_us(void)
 {
 	uint64_t clk;
-- 
2.36.1

Re: [kvm-unit-tests PATCH v1 1/2] lib/s390x: time: add wrapper for stckf

[Thomas Huth]

On 30/08/2022 13.56, Nico Boehr wrote:
> Upcoming changes will do performance measurements of instructions. Since
> stck is designed to return unique values even on concurrent calls, it is
> unsuited for performance measurements. stckf should be used in this
> case.
> 
> Hence, add a nice wrapper for stckf to the time library.
> 
> Signed-off-by: Nico Boehr <nrb@linux.ibm.com>
> ---
>   lib/s390x/asm/time.h | 9 +++++++++
>   1 file changed, 9 insertions(+)
> 
> diff --git a/lib/s390x/asm/time.h b/lib/s390x/asm/time.h
> index 7652a151e87a..d7c2bcb4f306 100644
> --- a/lib/s390x/asm/time.h
> +++ b/lib/s390x/asm/time.h
> @@ -14,6 +14,15 @@
>   #define STCK_SHIFT_US	(63 - 51)
>   #define STCK_MAX	((1UL << 52) - 1)
>   
> +static inline uint64_t get_clock_fast(void)
> +{
> +	uint64_t clk;
> +
> +	asm volatile(" stckf %0 " : : "Q"(clk) : "memory");
> +
> +	return clk;
> +}

Using clk as input parameter together with memory clobbing sounds like a bad 
solution to me here. The Linux kernel properly uses it as output parameter 
instead:

static inline unsigned long get_tod_clock_fast(void)
{
         unsigned long clk;

         asm volatile("stckf %0" : "=Q" (clk) : : "cc");
         return clk;
}

(see arch/s390/include/asm/timex.h in the kernel sources)

As you can see, also the "cc" should be in the clobber list here.

  Thomas

Re: [kvm-unit-tests PATCH v1 1/2] lib/s390x: time: add wrapper for stckf

[Nico Boehr]

Quoting Thomas Huth (2022-08-30 14:27:30)
[...]
> > diff --git a/lib/s390x/asm/time.h b/lib/s390x/asm/time.h
> > index 7652a151e87a..d7c2bcb4f306 100644
> > --- a/lib/s390x/asm/time.h
> > +++ b/lib/s390x/asm/time.h
> > @@ -14,6 +14,15 @@
> >   #define STCK_SHIFT_US       (63 - 51)
> >   #define STCK_MAX    ((1UL << 52) - 1)
> >   
> > +static inline uint64_t get_clock_fast(void)
> > +{
> > +     uint64_t clk;
> > +
> > +     asm volatile(" stckf %0 " : : "Q"(clk) : "memory");
> > +
> > +     return clk;
> > +}
> 
> Using clk as input parameter together with memory clobbing sounds like a bad 
> solution to me here. The Linux kernel properly uses it as output parameter 
> instead:
> 
> static inline unsigned long get_tod_clock_fast(void)
> {
>          unsigned long clk;
> 
>          asm volatile("stckf %0" : "=Q" (clk) : : "cc");
>          return clk;
> }

Yes, thanks, it is a better solution. get_clock_us() also does it this way, so while at it let's fix that, too...

[kvm-unit-tests PATCH v1 2/2] s390x: add exittime tests

[Nico Boehr]

Add a test to measure the execution time of several instructions. This
can be helpful in finding performance regressions in hypervisor code.

All tests are currently reported as PASS, since the baseline for their
execution time depends on the respective environment and since needs to
be determined on a case-by-case basis.

Signed-off-by: Nico Boehr <nrb@linux.ibm.com>
---
 s390x/Makefile      |   1 +
 s390x/exittime.c    | 258 ++++++++++++++++++++++++++++++++++++++++++++
 s390x/unittests.cfg |   4 +
 3 files changed, 263 insertions(+)
 create mode 100644 s390x/exittime.c

diff --git a/s390x/Makefile b/s390x/Makefile
index efd5e0c13102..5dcac244767f 100644
--- a/s390x/Makefile
+++ b/s390x/Makefile
@@ -34,6 +34,7 @@ tests += $(TEST_DIR)/migration.elf
 tests += $(TEST_DIR)/pv-attest.elf
 tests += $(TEST_DIR)/migration-cmm.elf
 tests += $(TEST_DIR)/migration-skey.elf
+tests += $(TEST_DIR)/exittime.elf
 
 pv-tests += $(TEST_DIR)/pv-diags.elf
 
diff --git a/s390x/exittime.c b/s390x/exittime.c
new file mode 100644
index 000000000000..dc8329116b77
--- /dev/null
+++ b/s390x/exittime.c
@@ -0,0 +1,258 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Measure run time of various instructions. Can be used to find runtime
+ * regressions of instructions which cause exits.
+ *
+ * Copyright IBM Corp. 2022
+ *
+ * Authors:
+ *  Nico Boehr <nrb@linux.ibm.com>
+ */
+#include <libcflat.h>
+#include <smp.h>
+#include <sclp.h>
+#include <asm/time.h>
+#include <asm/sigp.h>
+#include <asm/interrupt.h>
+#include <asm/page.h>
+
+char pagebuf[PAGE_SIZE] __attribute__((__aligned__(PAGE_SIZE)));
+
+static void test_sigp_sense_running(long destcpu)
+{
+	smp_sigp(destcpu, SIGP_SENSE_RUNNING, 0, NULL);
+}
+
+static void test_nop(long ignore)
+{
+	asm volatile("nop" : : : "memory");
+}
+
+static void test_diag9c(long destcpu)
+{
+	asm volatile("diag %[destcpu],0,0x9c"
+		:
+		: [destcpu] "d" (destcpu)
+		:
+	);
+}
+
+static long setup_get_this_cpuaddr(long ignore)
+{
+	return stap();
+}
+
+static void test_diag44(long ignore)
+{
+	asm volatile("diag 0,0,0x44" : : : );
+}
+
+static void test_stnsm(long ignore)
+{
+	int out;
+
+	asm volatile(
+		"stnsm %[out],0xff"
+		: [out] "=Q" (out)
+		:
+		: "memory"
+	);
+}
+
+static void test_stosm(long ignore)
+{
+	int out;
+
+	asm volatile(
+		"stosm %[out],0"
+		: [out] "=Q" (out)
+		:
+		: "memory"
+	);
+}
+
+static long setup_ssm(long ignore)
+{
+	long system_mask = 0;
+
+	asm volatile(
+		"stosm %[system_mask],0"
+		: [system_mask] "=Q" (system_mask)
+		:
+		: "memory"
+	);
+
+	return system_mask;
+}
+
+static void test_ssm(long old_system_mask)
+{
+	asm volatile(
+		"ssm %[old_system_mask]"
+		:
+		: [old_system_mask] "Q" (old_system_mask)
+		:
+	);
+}
+
+static long setup_lctl4(long ignore)
+{
+	long ctl4_orig = 0;
+
+	asm volatile(
+		"stctg 4,4,%[ctl4_orig]"
+		: [ctl4_orig] "=S" (ctl4_orig)
+		:
+		: "memory"
+	);
+
+	return ctl4_orig;
+}
+
+static void test_lctl4(long ctl4_orig)
+{
+	asm volatile(
+		"lctlg 4,4,%[ctl4_orig]"
+		:
+		: [ctl4_orig] "S" (ctl4_orig)
+		:
+	);
+}
+
+static void test_stpx(long ignore)
+{
+	unsigned int prefix;
+
+	asm volatile(
+		"stpx %[prefix]"
+		: [prefix] "=S" (prefix)
+		:
+		: "memory"
+	);
+}
+
+static void test_stfl(long ignore)
+{
+	asm volatile(
+		"stfl 0" : : : "memory"
+	);
+}
+
+static void test_epsw(long ignore)
+{
+	long r1, r2;
+
+	asm volatile(
+		"epsw %[r1], %[r2]"
+		: [r1] "=d" (r1), [r2] "=d" (r2)
+		:
+		:
+	);
+}
+
+static void test_illegal(long ignore)
+{
+	expect_pgm_int();
+	asm volatile(
+		".word 0"
+		:
+		:
+		:
+	);
+	clear_pgm_int();
+}
+
+static long setup_servc(long arg)
+{
+	memset(pagebuf, 0, PAGE_SIZE);
+	return arg;
+}
+
+static void test_servc(long ignore)
+{
+	SCCB *sccb = (SCCB*) pagebuf;
+	sccb->h.length = 8;
+	servc(0, (unsigned long) sccb);
+}
+
+static void test_stsi(long fc)
+{
+	stsi(pagebuf, fc, 2, 2);
+}
+
+struct test {
+	char name[100];
+	/*
+	 * When non-null, will be called once before running the test loop.
+	 * Its return value will be given as argument to testfunc.
+	 */
+	long (*setupfunc)(long arg);
+	void (*testfunc)(long arg);
+	long arg;
+	long iters;
+} const exittime_tests[] = {
+	{"nop",                   NULL,                   test_nop,                0, 200000 },
+	{"sigp sense running(0)", NULL,                   test_sigp_sense_running, 0, 20000 },
+	{"sigp sense running(1)", NULL,                   test_sigp_sense_running, 1, 20000 },
+	{"diag9c(self)",          setup_get_this_cpuaddr, test_diag9c,             0, 2000 },
+	{"diag9c(0)",             NULL,                   test_diag9c,             0, 2000 },
+	{"diag9c(1)",             NULL,                   test_diag9c,             1, 2000 },
+	{"diag44",                NULL,                   test_diag44,             0, 2000 },
+	{"stnsm",                 NULL,                   test_stnsm,              0, 200000 },
+	{"stosm",                 NULL,                   test_stosm,              0, 200000 },
+	{"ssm",                   setup_ssm,              test_ssm,                0, 200000 },
+	{"lctl4",                 setup_lctl4,            test_lctl4,              0, 20000 },
+	{"stpx",                  NULL,                   test_stpx,               0, 2000 },
+	{"stfl",                  NULL,                   test_stfl,               0, 2000 },
+	{"epsw",                  NULL,                   test_epsw,               0, 20000 },
+	{"illegal",               NULL,                   test_illegal,            0, 2000 },
+	{"servc",                 setup_servc,            test_servc,              0, 2000 },
+	{"stsi122",               NULL,                   test_stsi,               1, 200 },
+	{"stsi222",               NULL,                   test_stsi,               2, 200 },
+	{"stsi322",               NULL,                   test_stsi,               3, 200 },
+};
+
+static uint64_t tod_to_us(uint64_t tod)
+{
+	return tod >> STCK_SHIFT_US;
+}
+
+int main(void)
+{
+	int i, j, k, testfunc_arg;
+	const int outer_iters = 100;
+	struct test const *current_test;
+	uint64_t start, end, elapsed, worst, best, total;
+
+	report_prefix_push("exittime");
+	report_pass("reporting total/best/worst of %d outer iterations", outer_iters);
+
+	for (i = 0; i < ARRAY_SIZE(exittime_tests); i++) {
+		current_test = &exittime_tests[i];
+		total = 0;
+		worst = 0;
+		best = -1;
+		report_prefix_pushf("%s", current_test->name);
+
+		testfunc_arg = current_test->arg;
+		if (current_test->setupfunc) {
+			testfunc_arg = current_test->setupfunc(testfunc_arg);
+		}
+
+		for (j = 0; j < outer_iters; j++) {
+			start = get_clock_fast();
+			for (k = 0; k < current_test->iters; k++)
+				current_test->testfunc(testfunc_arg);
+			end = get_clock_fast();
+			elapsed = end - start;
+			best = MIN(best, elapsed);
+			worst = MAX(worst, elapsed);
+			total += elapsed;
+		}
+		report_pass("iters/total/best/worst %lu/%lu/%lu/%lu us", current_test->iters, tod_to_us(total), tod_to_us(best), tod_to_us(worst));
+		report_prefix_pop();
+	}
+
+	report_prefix_pop();
+	return report_summary();
+}
diff --git a/s390x/unittests.cfg b/s390x/unittests.cfg
index f7b1fc3dbca1..c11d1d987c82 100644
--- a/s390x/unittests.cfg
+++ b/s390x/unittests.cfg
@@ -185,3 +185,7 @@ groups = migration
 [migration-skey]
 file = migration-skey.elf
 groups = migration
+
+[exittime]
+file = exittime.elf
+smp = 2
-- 
2.36.1

Re: [kvm-unit-tests PATCH v1 2/2] s390x: add exittime tests

[Thomas Huth]

On 30/08/2022 13.56, Nico Boehr wrote:
> Add a test to measure the execution time of several instructions. This
> can be helpful in finding performance regressions in hypervisor code.
> 
> All tests are currently reported as PASS, since the baseline for their
> execution time depends on the respective environment and since needs to
> be determined on a case-by-case basis.
> 
> Signed-off-by: Nico Boehr <nrb@linux.ibm.com>
> ---
>   s390x/Makefile      |   1 +
>   s390x/exittime.c    | 258 ++++++++++++++++++++++++++++++++++++++++++++
>   s390x/unittests.cfg |   4 +
>   3 files changed, 263 insertions(+)
>   create mode 100644 s390x/exittime.c
> 
> diff --git a/s390x/Makefile b/s390x/Makefile
> index efd5e0c13102..5dcac244767f 100644
> --- a/s390x/Makefile
> +++ b/s390x/Makefile
> @@ -34,6 +34,7 @@ tests += $(TEST_DIR)/migration.elf
>   tests += $(TEST_DIR)/pv-attest.elf
>   tests += $(TEST_DIR)/migration-cmm.elf
>   tests += $(TEST_DIR)/migration-skey.elf
> +tests += $(TEST_DIR)/exittime.elf
>   
>   pv-tests += $(TEST_DIR)/pv-diags.elf
>   
> diff --git a/s390x/exittime.c b/s390x/exittime.c
> new file mode 100644
> index 000000000000..dc8329116b77
> --- /dev/null
> +++ b/s390x/exittime.c
> @@ -0,0 +1,258 @@
> +/* SPDX-License-Identifier: GPL-2.0-only */
> +/*
> + * Measure run time of various instructions. Can be used to find runtime
> + * regressions of instructions which cause exits.
> + *
> + * Copyright IBM Corp. 2022
> + *
> + * Authors:
> + *  Nico Boehr <nrb@linux.ibm.com>
> + */
> +#include <libcflat.h>
> +#include <smp.h>
> +#include <sclp.h>
> +#include <asm/time.h>
> +#include <asm/sigp.h>
> +#include <asm/interrupt.h>
> +#include <asm/page.h>
> +
> +char pagebuf[PAGE_SIZE] __attribute__((__aligned__(PAGE_SIZE)));
> +
> +static void test_sigp_sense_running(long destcpu)
> +{
> +	smp_sigp(destcpu, SIGP_SENSE_RUNNING, 0, NULL);
> +}
> +
> +static void test_nop(long ignore)
> +{
> +	asm volatile("nop" : : : "memory");
> +}

What's the purpose of testing "nop"? ... it does not trap to the 
hypervisor... ? Is it just for reference? Then a comment might be helpful here.

> +static void test_diag9c(long destcpu)
> +{
> +	asm volatile("diag %[destcpu],0,0x9c"
> +		:
> +		: [destcpu] "d" (destcpu)
> +		:
> +	);
> +}
> +
> +static long setup_get_this_cpuaddr(long ignore)
> +{
> +	return stap();
> +}
> +
> +static void test_diag44(long ignore)
> +{
> +	asm volatile("diag 0,0,0x44" : : : );

Drop the " : : : " please.

> +}
> +
> +static void test_stnsm(long ignore)
> +{
> +	int out;
> +
> +	asm volatile(
> +		"stnsm %[out],0xff"
> +		: [out] "=Q" (out)
> +		:
> +		: "memory"

I don't think you need the "memory" clobber here, do you?

> +	);
> +}
> +
> +static void test_stosm(long ignore)
> +{
> +	int out;
> +
> +	asm volatile(
> +		"stosm %[out],0"
> +		: [out] "=Q" (out)
> +		:
> +		: "memory"

dito

> +	);
> +}
> +
> +static long setup_ssm(long ignore)
> +{
> +	long system_mask = 0;
> +
> +	asm volatile(
> +		"stosm %[system_mask],0"
> +		: [system_mask] "=Q" (system_mask)
> +		:
> +		: "memory"
> +	);
> +
> +	return system_mask;
> +}
> +
> +static void test_ssm(long old_system_mask)
> +{
> +	asm volatile(
> +		"ssm %[old_system_mask]"
> +		:
> +		: [old_system_mask] "Q" (old_system_mask)
> +		:
> +	);
> +}
> +
> +static long setup_lctl4(long ignore)
> +{
> +	long ctl4_orig = 0;
> +
> +	asm volatile(
> +		"stctg 4,4,%[ctl4_orig]"
> +		: [ctl4_orig] "=S" (ctl4_orig)
> +		:
> +		: "memory"
> +	);
> +
> +	return ctl4_orig;
> +}
> +
> +static void test_lctl4(long ctl4_orig)
> +{
> +	asm volatile(
> +		"lctlg 4,4,%[ctl4_orig]"
> +		:
> +		: [ctl4_orig] "S" (ctl4_orig)
> +		:
> +	);
> +}
> +
> +static void test_stpx(long ignore)
> +{
> +	unsigned int prefix;
> +
> +	asm volatile(
> +		"stpx %[prefix]"
> +		: [prefix] "=S" (prefix)

STPX seems to have only a short displacement, so it should have "=Q" instead 
of "=S" ?

> +		:
> +		: "memory"
> +	);
> +}
> +
> +static void test_stfl(long ignore)
> +{
> +	asm volatile(
> +		"stfl 0" : : : "memory"
> +	);
> +}
> +
> +static void test_epsw(long ignore)
> +{
> +	long r1, r2;
> +
> +	asm volatile(
> +		"epsw %[r1], %[r2]"
> +		: [r1] "=d" (r1), [r2] "=d" (r2)
> +		:
> +		:
> +	);
> +}
> +
> +static void test_illegal(long ignore)
> +{
> +	expect_pgm_int();
> +	asm volatile(
> +		".word 0"
> +		:
> +		:
> +		:
> +	);
> +	clear_pgm_int();
> +}
> +
> +static long setup_servc(long arg)
> +{
> +	memset(pagebuf, 0, PAGE_SIZE);
> +	return arg;
> +}
> +
> +static void test_servc(long ignore)
> +{
> +	SCCB *sccb = (SCCB*) pagebuf;
> +	sccb->h.length = 8;
> +	servc(0, (unsigned long) sccb);
> +}
> +
> +static void test_stsi(long fc)
> +{
> +	stsi(pagebuf, fc, 2, 2);
> +}
> +
> +struct test {
> +	char name[100];

"const char *name" instead of using an array here, please. Otherwise this 
wastes a lot of space in the binary.

...
> diff --git a/s390x/unittests.cfg b/s390x/unittests.cfg
> index f7b1fc3dbca1..c11d1d987c82 100644
> --- a/s390x/unittests.cfg
> +++ b/s390x/unittests.cfg
> @@ -185,3 +185,7 @@ groups = migration
>   [migration-skey]
>   file = migration-skey.elf
>   groups = migration
> +
> +[exittime]
> +file = exittime.elf
> +smp = 2

I wonder whether we should execute this test by default, since nothing can 
fail here? I assume this is rather something that you want to run manually?

  Thomas

Re: [kvm-unit-tests PATCH v1 2/2] s390x: add exittime tests

[Nico Boehr]

Quoting Thomas Huth (2022-08-30 14:52:14)
> I wonder whether we should execute this test by default, since nothing can 
> fail here? I assume this is rather something that you want to run manually?

This could be one idea.

My idea was to run it even if it can't fail since the execution times are printed in log files. Collecting them may be interesting to establish a baseline for later measurements. It also is what x86 does with their vmexit tests. In addition, running them doesn't hurt and makes sure the tests don't suddenly break.

I will address your other comments in an upcoming iteration, thank you.

Re: [kvm-unit-tests PATCH v1 2/2] s390x: add exittime tests

[Nico Boehr]

Quoting Thomas Huth (2022-08-30 14:52:14)
> > diff --git a/s390x/exittime.c b/s390x/exittime.c
> > new file mode 100644
[...]
> > +static void test_nop(long ignore)
> > +{
> > +     asm volatile("nop" : : : "memory");
> > +}
> 
> What's the purpose of testing "nop"? ... it does not trap to the 
> hypervisor... ? Is it just for reference? Then a comment might be helpful here.

Yes, the idea is to have some reference for a non-trapping instruction. Added a comment.

[...]
> > +static void test_diag44(long ignore)
> > +{
> > +     asm volatile("diag 0,0,0x44" : : : );
> 
> Drop the " : : : " please.

OK

> > +static void test_stnsm(long ignore)
> > +{
> > +     int out;
> > +
> > +     asm volatile(
> > +             "stnsm %[out],0xff"
> > +             : [out] "=Q" (out)
> > +             :
> > +             : "memory"
> 
> I don't think you need the "memory" clobber here, do you?

Uhm, yes, right. Good thing we have reviews. :-)

[...]
> > +static void test_stpx(long ignore)
> > +{
> > +     unsigned int prefix;
> > +
> > +     asm volatile(
> > +             "stpx %[prefix]"
> > +             : [prefix] "=S" (prefix)
> 
> STPX seems to have only a short displacement, so it should have "=Q" instead 
> of "=S" ?

Yes, right, fixed. Also the memory clobber is unneeded. I think I will do through all the clobbers and constraint once more, seems like I messed up a bit there.

[...]
> > +struct test {
> > +     char name[100];
> 
> "const char *name" instead of using an array here, please. Otherwise this 
> wastes a lot of space in the binary.

Makes sense, thanks.