[PATCH] kvm tools: Fix 'kill -3' hangs

[PATCH] kvm tools: Fix 'kill -3' hangs

[Pekka Enberg]

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);
@@ -332,6 +345,7 @@ int kvm_cmd_run(int argc, const char **argv, const char *prefix)
 
 	signal(SIGALRM, handle_sigalrm);
 	signal(SIGQUIT, handle_sigquit);
+	signal(SIGUSR1, handle_sigusr1);
 
 	while (argc != 0) {
 		argc = parse_options(argc, argv, options, run_usage,
-- 
1.7.0.4

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

[Ingo Molnar]

* 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>
---
diff --git a/tools/kvm/include/kvm/mutex.h b/tools/kvm/include/kvm/mutex.h
index 006ade3..bd765c4 100644
--- a/tools/kvm/include/kvm/mutex.h
+++ b/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)
diff --git a/tools/kvm/kvm-cpu.c b/tools/kvm/kvm-cpu.c
index d7febb3..a05ee5a 100644
--- a/tools/kvm/kvm-cpu.c
+++ b/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);
 }
 
diff --git a/tools/kvm/kvm-run.c b/tools/kvm/kvm-run.c
index 58e2977..221435d 100644
--- a/tools/kvm/kvm-run.c
+++ b/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,6 +128,12 @@ 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;
@@ -134,9 +141,13 @@ static void handle_sigusr1(int sig)
 	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)

[PATCH] kvm tools: Dump vCPUs in order

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

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

There's one bug remaining that my patch does not address: the vCPUs are not 
printed in order:

# vCPU #0's dump:
# vCPU #2's dump:
# vCPU #24's dump:
# vCPU #5's dump:
# vCPU #39's dump:
# vCPU #38's dump:
# vCPU #51's dump:
# vCPU #11's dump:
# vCPU #10's dump:
# vCPU #12's dump:

This is undesirable as the order of printout is highly random, so successive 
dumps are difficult to compare.

The patch below serializes the signalling itself. (this is on top of the 
previous patch)

The patch also tweaks the vCPU printout line a bit so that it does not start 
with '#', which is discarded if such messages are pasted into Git commit 
messages.

Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/tools/kvm/kvm-run.c b/tools/kvm/kvm-run.c
index 221435d..00c70c7 100644
--- a/tools/kvm/kvm-run.c
+++ b/tools/kvm/kvm-run.c
@@ -25,6 +25,7 @@
 #include <kvm/term.h>
 #include <kvm/ioport.h>
 #include <kvm/threadpool.h>
+#include <kvm/barrier.h>
 
 /* header files for gitish interface  */
 #include <kvm/kvm-run.h>
@@ -132,7 +133,7 @@ static const struct option options[] = {
  * Serialize debug printout so that the output of multiple vcpus does not
  * get mixed up:
  */
-static DEFINE_MUTEX(printout_mutex);
+static int printout_done;
 
 static void handle_sigusr1(int sig)
 {
@@ -141,13 +142,13 @@ static void handle_sigusr1(int sig)
 	if (!cpu)
 		return;
 
-	mutex_lock(&printout_mutex);
-	printf("\n#\n# vCPU #%ld's dump:\n#\n", cpu->cpu_id);
+	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);
+	printout_done = 1;
+	mb();
 }
 
 static void handle_sigquit(int sig)
@@ -160,7 +161,15 @@ static void handle_sigquit(int sig)
 		if (!cpu)
 			continue;
 
+		printout_done = 0;
 		pthread_kill(cpu->thread, SIGUSR1);
+		/*
+		 * Wait for the vCPU to dump state before signalling
+		 * the next thread. Since this is debug code it does
+		 * not matter that we are burning CPU time a bit:
+		 */
+		while (!printout_done)
+			mb();
 	}
 
 	serial8250__inject_sysrq(kvm);