kvm tools: Fix and improve the CPU register dump debug output code

* Pekka Enberg <penberg@kernel.org> wrote:

> Ingo Molnar reported that 'kill -3' didn't work on his machine:
>
>   * Ingo Molnar <mingo@elte.hu> wrote:
>
>   > This is really cumbersome to debug - is there some good way to get to the RIP
>   > that the guest is hanging in? If kvm would print that out to the host console
>   > (even if it's just the raw RIP initially) on a kill -3 that would help
>   > enormously.
>
>   Looks like the code should be doing that already - but the ioctl(KVM_GET_SREGS)
>   hangs:
>
>     [pid   748] ioctl(6, KVM_GET_SREGS
>
> Avi Kivity pointed out that it's not safe to call KVM_GET_SREGS (or other vcpu
> related ioctls) from other threads:
>
>   > is it not OK to call KVM_GET_SREGS from other threads than the one
>   > that's doing KVM_RUN?
>
>   From Documentation/kvm/api.txt:
>
>    - vcpu ioctls: These query and set attributes that control the operation
>      of a single virtual cpu.
>
>      Only run vcpu ioctls from the same thread that was used to create the
>      vcpu.
>
> Fix that up by using pthread_kill() to force the threads that are doing KVM_RUN
> to do the register dumps.
>
> Reported: Ingo Molnar <mingo@elte.hu>
> Cc: Asias He <asias.hejun@gmail.com>
> Cc: Avi Kivity <avi@redhat.com>
> Cc: Cyrill Gorcunov <gorcunov@gmail.com>
> Cc: Ingo Molnar <mingo@elte.hu>
> Cc: Prasad Joshi <prasadjoshi124@gmail.com>
> Cc: Sasha Levin <levinsasha928@gmail.com>
> Signed-off-by: Pekka Enberg <penberg@kernel.org>
> ---
>  tools/kvm/kvm-run.c |   20 +++++++++++++++++---
>  1 files changed, 17 insertions(+), 3 deletions(-)
>
> diff --git a/tools/kvm/kvm-run.c b/tools/kvm/kvm-run.c
> index eb50b6a..58e2977 100644
> --- a/tools/kvm/kvm-run.c
> +++ b/tools/kvm/kvm-run.c
> @@ -127,6 +127,18 @@ static const struct option options[] = {
>  	OPT_END()
>  };
>
> +static void handle_sigusr1(int sig)
> +{
> +	struct kvm_cpu *cpu = current_kvm_cpu;
> +
> +	if (!cpu)
> +		return;
> +
> +	kvm_cpu__show_registers(cpu);
> +	kvm_cpu__show_code(cpu);
> +	kvm_cpu__show_page_tables(cpu);
> +}
> +
>  static void handle_sigquit(int sig)
>  {
>  	int i;
> @@ -134,9 +146,10 @@ static void handle_sigquit(int sig)
>  	for (i = 0; i < nrcpus; i++) {
>  		struct kvm_cpu *cpu = kvm_cpus[i];
>
> -		kvm_cpu__show_registers(cpu);
> -		kvm_cpu__show_code(cpu);
> -		kvm_cpu__show_page_tables(cpu);
> +		if (!cpu)
> +			continue;
> +
> +		pthread_kill(cpu->thread, SIGUSR1);
>  	}
>
>  	serial8250__inject_sysrq(kvm);

i can see a couple of problems with the debug printout code, which currently
produces a stream of such dumps for each vcpu:

Registers:
 rip: 0000000000000000   rsp: 00000000000016ca flags: 0000000000010002
 rax: 0000000000000000   rbx: 0000000000000000   rcx: 0000000000000000
 rdx: 0000000000000000   rsi: 0000000000000000   rdi: 0000000000000000
 rbp: 0000000000008000   r8:  0000000000000000   r9:  0000000000000000
 r10: 0000000000000000   r11: 0000000000000000   r12: 0000000000000000
 r13: 0000000000000000   r14: 0000000000000000   r15: 0000000000000000
 cr0: 0000000060000010   cr2: 0000000000000070   cr3: 0000000000000000
 cr4: 0000000000000000   cr8: 0000000000000000
Segment registers:
 register  selector  base              limit     type  p dpl db s l g avl
 cs        f000      00000000000f0000  0000ffff  03    1 3   0  1 0 0 0
 ss        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 ds        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 es        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 fs        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 gs        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 tr        0000      0000000000000000  0000ffff  0b    1 0   0  0 0 0 0
 ldt       0000      0000000000000000  0000ffff  02    1 0   0  0 0 0 0
 gdt                 0000000000000000 0000ffff
 idt                 0000000000000000 0000ffff
 [ efer: 0000000000000000  apic base: 00000000fee00900  nmi: enabled ]
Interrupt bitmap:
 0000000000000000 0000000000000000 0000000000000000 0000000000000000
Code: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 <cf> eb 0d 90 90 90 90 90 90 90 90 90 90 90 90 90 f6 c4 0e 75 4b
Stack:
  0x000016ca: 00 00 00 00  00 00 00 00
  0x000016d2: 00 00 00 00  00 00 00 00
  0x000016da: 00 00 00 00  00 00 00 00
  0x000016e2: 00 00 00 00  00 00 00 00

The problems are:

 - This does not work very well on SMP with lots of vcpus, because the printing
   is unserialized, resulting in a jumbled mess of an output, all vcpus trying
   to print to the console at once, often mixing lines and characters randomly.

 - stdout from a signal handler must be flushed, otherwise lines can remain
   buffered if someone saves the output via 'tee' for example.

 - the dumps from the various CPUs are not distinguishable - they are just
   dumped after each other with no identification

 - the various printouts are rather hard to parse visually - it's not easy to see
   various properties "at a glance" because the dump is visually confusing.

The patch below addresses these concerns, serializes the output, tidies up the
printout, resulting in this new output:

#
# vCPU #0's dump:
#

 Registers:
 ----------
 rip: 0000000000000000   rsp: 00000000000008bc flags: 0000000000010002
 rax: 0000000000000000   rbx: 0000000000000000   rcx: 0000000000000000
 rdx: 0000000000000000   rsi: 0000000000000000   rdi: 0000000000000000
 rbp: 0000000000008000    r8: 0000000000000000    r9: 0000000000000000
 r10: 0000000000000000   r11: 0000000000000000   r12: 0000000000000000
 r13: 0000000000000000   r14: 0000000000000000   r15: 0000000000000000
 cr0: 0000000060000010   cr2: 0000000000000070   cr3: 0000000000000000
 cr4: 0000000000000000   cr8: 0000000000000000

 Segment registers:
 ------------------
 register  selector  base              limit     type  p dpl db s l g avl
 cs        f000      00000000000f0000  0000ffff  03    1 3   0  1 0 0 0
 ss        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 ds        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 es        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 fs        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 gs        1000      0000000000010000  0000ffff  03    1 3   0  1 0 0 0
 tr        0000      0000000000000000  0000ffff  0b    1 0   0  0 0 0 0
 ldt       0000      0000000000000000  0000ffff  02    1 0   0  0 0 0 0
 gdt                 0000000000000000  0000ffff
 idt                 0000000000000000  0000ffff

 APIC:
 -----
 efer: 0000000000000000  apic base: 00000000fee00900  nmi: enabled

 Interrupt bitmap:
 -----------------
 0000000000000000 0000000000000000 0000000000000000 0000000000000000

 Code:
 -----
 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 <cf> eb 0d 90 90 90 90 90 90 90 90 90 90 90 90 90 f6 c4 0e 75 4b

 Stack:
 ------
  0x000008bc: 00 00 00 00  00 00 00 00
  0x000008c4: 00 00 00 00  00 00 00 00
  0x000008cc: 00 00 00 00  00 00 00 00
  0x000008d4: 00 00 00 00  00 00 00 00

Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Pekka Enberg <penberg@kernel.org>

tools/kvm/include/kvm/mutex.h

@@ -5,6 +5,13 @@
 
 #include "kvm/util.h"
 
+/*
+ * Kernel-alike mutex API - to make it easier for kernel developers
+ * to write user-space code! :-)
+ */
+
+#define DEFINE_MUTEX(mutex) pthread_mutex_t mutex = PTHREAD_MUTEX_INITIALIZER
+
 static inline void mutex_lock(pthread_mutex_t *mutex)
 {
 	if (pthread_mutex_lock(mutex) != 0)

tools/kvm/kvm-cpu.c

@@ -200,7 +200,7 @@ void kvm_cpu__reset_vcpu(struct kvm_cpu *self)
 
 static void print_dtable(const char *name, struct kvm_dtable *dtable)
 {
-	printf(" %s                 %016llx %08hx\n",
+	printf(" %s                 %016llx  %08hx\n",
 		name, (u64) dtable->base, (u16) dtable->limit);
 }
 
@@ -238,11 +238,12 @@ void kvm_cpu__show_registers(struct kvm_cpu *self)
 	r10 = regs.r10; r11 = regs.r11; r12 = regs.r12;
 	r13 = regs.r13; r14 = regs.r14; r15 = regs.r15;
 
-	printf("Registers:\n");
+	printf("\n Registers:\n");
+	printf(  " ----------\n");
 	printf(" rip: %016lx   rsp: %016lx flags: %016lx\n", rip, rsp, rflags);
 	printf(" rax: %016lx   rbx: %016lx   rcx: %016lx\n", rax, rbx, rcx);
 	printf(" rdx: %016lx   rsi: %016lx   rdi: %016lx\n", rdx, rsi, rdi);
-	printf(" rbp: %016lx   r8:  %016lx   r9:  %016lx\n", rbp, r8,  r9);
+	printf(" rbp: %016lx    r8: %016lx    r9: %016lx\n", rbp, r8,  r9);
 	printf(" r10: %016lx   r11: %016lx   r12: %016lx\n", r10, r11, r12);
 	printf(" r13: %016lx   r14: %016lx   r15: %016lx\n", r13, r14, r15);
 
@@ -254,7 +255,8 @@ void kvm_cpu__show_registers(struct kvm_cpu *self)
 
 	printf(" cr0: %016lx   cr2: %016lx   cr3: %016lx\n", cr0, cr2, cr3);
 	printf(" cr4: %016lx   cr8: %016lx\n", cr4, cr8);
-	printf("Segment registers:\n");
+	printf("\n Segment registers:\n");
+	printf(  " ------------------\n");
 	printf(" register  selector  base              limit     type  p dpl db s l g avl\n");
 	print_segment("cs ", &sregs.cs);
 	print_segment("ss ", &sregs.ss);
@@ -266,13 +268,17 @@ void kvm_cpu__show_registers(struct kvm_cpu *self)
 	print_segment("ldt", &sregs.ldt);
 	print_dtable("gdt", &sregs.gdt);
 	print_dtable("idt", &sregs.idt);
-	printf(" [ efer: %016llx  apic base: %016llx  nmi: %s ]\n",
+
+	printf("\n APIC:\n");
+	printf(  " -----\n");
+	printf(" efer: %016llx  apic base: %016llx  nmi: %s\n",
 		(u64) sregs.efer, (u64) sregs.apic_base,
 		(self->kvm->nmi_disabled ? "disabled" : "enabled"));
-	printf("Interrupt bitmap:\n");
-	printf(" ");
+
+	printf("\n Interrupt bitmap:\n");
+	printf(  " -----------------\n");
 	for (i = 0; i < (KVM_NR_INTERRUPTS + 63) / 64; i++)
-		printf("%016llx ", (u64) sregs.interrupt_bitmap[i]);
+		printf(" %016llx", (u64) sregs.interrupt_bitmap[i]);
 	printf("\n");
 }
 
@@ -293,7 +299,8 @@ void kvm_cpu__show_code(struct kvm_cpu *self)
 
 	ip = guest_flat_to_host(self->kvm, ip_to_flat(self, self->regs.rip) - code_prologue);
 
-	printf("Code: ");
+	printf("\n Code:\n");
+	printf(  " -----\n");
 
 	for (i = 0; i < code_len; i++, ip++) {
 		if (!host_ptr_in_ram(self->kvm, ip))
@@ -302,14 +309,15 @@ void kvm_cpu__show_code(struct kvm_cpu *self)
 		c = *ip;
 
 		if (ip == guest_flat_to_host(self->kvm, ip_to_flat(self, self->regs.rip)))
-			printf("<%02x> ", c);
+			printf(" <%02x>", c);
 		else
-			printf("%02x ", c);
+			printf(" %02x", c);
 	}
 
 	printf("\n");
 
-	printf("Stack:\n");
+	printf("\n Stack:\n");
+	printf(  " ------\n");
 	kvm__dump_mem(self->kvm, self->regs.rsp, 32);
 }
 

tools/kvm/kvm-run.c

@@ -29,6 +29,7 @@
 /* header files for gitish interface  */
 #include <kvm/kvm-run.h>
 #include <kvm/parse-options.h>
+#include <kvm/mutex.h>
 
 #define DEFAULT_KVM_DEV		"/dev/kvm"
 #define DEFAULT_CONSOLE		"serial"
@@ -127,16 +128,26 @@ static const struct option options[] = {
 	OPT_END()
 };
 
+/*
+ * Serialize debug printout so that the output of multiple vcpus does not
+ * get mixed up:
+ */
+static DEFINE_MUTEX(printout_mutex);
+
 static void handle_sigusr1(int sig)
 {
 	struct kvm_cpu *cpu = current_kvm_cpu;
 
 	if (!cpu)
 		return;
 
+	mutex_lock(&printout_mutex);
+	printf("\n#\n# vCPU #%ld's dump:\n#\n", cpu->cpu_id);
 	kvm_cpu__show_registers(cpu);
 	kvm_cpu__show_code(cpu);
 	kvm_cpu__show_page_tables(cpu);
+	fflush(stdout);
+	mutex_unlock(&printout_mutex);
 }
 
 static void handle_sigquit(int sig)