Re: [PATCH] x86: apic: add APIC Timer periodic/oneshot mode latency test

["Radim Krčmář" <rkrcmar@redhat.com>]

2016-10-17 16:28+0800, Wanpeng Li:
> From: Wanpeng Li <wanpeng.li@hotmail.com>
> 
> Add APIC Timer periodic/oneshot mode latency test.
> 
> Cc: Paolo Bonzini <pbonzini@redhat.com>
> Cc: Radim Krčmář <rkrcmar@redhat.com>
> Signed-off-by: Wanpeng Li <wanpeng.li@hotmail.com>
> ---
>  x86/Makefile.x86_64      |   1 +
>  x86/apic_timer_latency.c | 125 +++++++++++++++++++++++++++++++++++++++++++++++
>  x86/unittests.cfg        |   6 +++
>  3 files changed, 132 insertions(+)
>  create mode 100644 x86/apic_timer_latency.c
> 
> diff --git a/x86/Makefile.x86_64 b/x86/Makefile.x86_64
> index e166911..c9eda46 100644
> --- a/x86/Makefile.x86_64
> +++ b/x86/Makefile.x86_64
> @@ -14,6 +14,7 @@ tests = $(TEST_DIR)/access.flat $(TEST_DIR)/apic.flat \
>  tests += $(TEST_DIR)/svm.flat
>  tests += $(TEST_DIR)/vmx.flat
>  tests += $(TEST_DIR)/tscdeadline_latency.flat
> +tests += $(TEST_DIR)/apic_timer_latency.flat
>  
>  include $(TEST_DIR)/Makefile.common
>  
> diff --git a/x86/apic_timer_latency.c b/x86/apic_timer_latency.c
> new file mode 100644
> index 0000000..4dd285f
> --- /dev/null
> +++ b/x86/apic_timer_latency.c
> @@ -0,0 +1,125 @@
> +/*
> + * qemu command line | grep latency | cut -f 2 -d ":" > latency
> + *
> + * In octave:
> + * load latency
> + * min(latency)
> + * max(latency)
> + * mean(latency)
> + * hist(latency, 50)
> + */
> +
> +/*
> + * for host tracing of breakmax option:
> + *
> + * # cd /sys/kernel/debug/tracing/
> + * # echo x86-tsc > trace_clock
> + * # echo "kvm_exit kvm_entry kvm_msr" > set_event
> + * # echo "sched_switch $extratracepoints" >> set_event
> + * # echo apic_timer_fn > set_ftrace_filter
> + * # echo "function" > current_tracer
> + */
> +
> +#include "libcflat.h"
> +#include "apic.h"
> +#include "vm.h"
> +#include "smp.h"
> +#include "desc.h"
> +#include "isr.h"
> +#include "msr.h"
> +
> +static void test_lapic_existence(void)
> +{
> +    u32 lvr;
> +
> +    lvr = apic_read(APIC_LVR);
> +    printf("apic version: %x\n", lvr);
> +    report("apic existence", (u16)lvr == 0x14);
> +}
> +
> +static int tdt_count;
> +u64 exptime;
> +int delta;
> +int mode;
> +#define TABLE_SIZE 100000
> +u64 table[TABLE_SIZE];
> +volatile int table_idx;
> +volatile int hitmax = 0;
> +int breakmax = 0;
> +#define APIC_LVT_TIMER_ONE_SHOT  (0)
> +#define APIC_LVT_TIMER_VECTOR (0xee)
> +
> +static void apic_timer_isr(isr_regs_t *regs)
> +{
> +    u64 now = rdtsc();
> +    ++tdt_count;
> +
> +    if (table_idx < TABLE_SIZE && tdt_count > 1)
> +        table[table_idx++] = now - exptime;
> +
> +    if (breakmax && tdt_count > 1 && (now - exptime) > breakmax) {
> +        hitmax = 1;
> +        apic_write(APIC_EOI, 0);
> +        return;
> +    }
> +
> +    exptime = now+delta;

Two problems on this line:

1) with periodic timer, the delta is added to last expiration time, not
   to now().
   What you are measuring now is the stability of the period -- very
   important as well, but if we used now() only once, you could also
   measure the latency.

2) delta is in nanoseconds while exptime is in cycles.  Type error.

> +
> +    if (mode == APIC_LVT_TIMER_ONE_SHOT)
> +        /* Set "Initial Counter Register", which starts the timer */
> +        apic_write(APIC_TMICT, delta);

This is not deadline, so it would be better to read now() for exptime
right before the apic_write, so as little time as possible passes in
between.

> +
> +    apic_write(APIC_EOI, 0);
> +}
> +
> +static void test_apic_timer(int mode)
> +{
> +    handle_irq(APIC_LVT_TIMER_VECTOR, apic_timer_isr);
> +    irq_enable();
> +
> +	/* Periodic mode */
> +    apic_write(APIC_LVTT, mode | APIC_LVT_TIMER_VECTOR);
> +    /* Divider == 1 */
> +    apic_write(APIC_TDCR, 0x0000000b);
> +    apic_write(APIC_TMICT, delta);
> +}
> +
> +int main(int argc, char **argv)
> +{
> +    int i, size;
> +    u64 count = 0;
> +
> +    setup_vm();
> +    smp_init();
> +    setup_idt();
> +
> +    test_lapic_existence();
> +
> +    mask_pic_interrupts();
> +
> +    mode = argc <= 1 ? APIC_LVT_TIMER_PERIODIC : atol(argv[1]);
> +    delta = argc <= 2 ? 0x100000 : atol(argv[2]);
> +    size = argc <= 3 ? TABLE_SIZE : atol(argv[3]);
> +    breakmax = argc <= 4 ? 0 : atol(argv[4]);
> +    printf("breakmax=%d\n", breakmax);
> +    if (mode == APIC_LVT_TIMER_PERIODIC)
> +        printf("APIC Timer Periodic Mode\n");
> +    else if (mode == APIC_LVT_TIMER_ONE_SHOT)
> +        printf("APIC Timer Oneshot Mode\n");
> +    test_apic_timer(mode);
> +    irq_enable();
> +
> +    do {
> +        asm volatile("hlt");

We'll want to have two modes here -- testing the vmx preemption timer,
which requires that the guest runs (I use "pause" here) and the test for
hrtimer, where "hlt" is optimal.

> +    } while (!hitmax && table_idx < size);
> +
> +    for (i = 0; i < table_idx; i++) {
> +        if (hitmax && i == table_idx-1)
> +            printf("hit max: %d < ", breakmax);
> +        count += table[i];
> +        printf("latency: %" PRId64 "\n", table[i]);
> +    }
> +
> +    printf("average latency = %lu\n", count/size);
> +    return report_summary();
> +}
> diff --git a/x86/unittests.cfg b/x86/unittests.cfg
> @@ -32,6 +32,12 @@ extra_params = -cpu qemu64,+x2apic,+tsc-deadline
>  arch = x86_64
>  timeout = 30
>  
> +[apic_timer_latency]
> +file = apic_timer_latency.flat
> +smp = 1
> +arch = x86_64
> +timeout = 30

Please drop the test from x86/unittests.cfg.  Is not useful without
looking at the average latency, like tscdeadline_latency, so we don't
want to run it with ./run_tests.sh.

(And it takes way over 30 seconds for me.)

Thanks.