perf kvm: more bug fixes and cleanups

PATCH In review David Ahern 2 participants 8 messages Jul 10, 2012 – Jul 11, 2012 perf events

lore

Share & tools

lore

David Ahern

author

2012-07-10 21:48 UTC #0 lore raw

cover perf kvm: more bug fixes and cleanups

Ingo:

Please consider applying the following patches while Arnaldo is on vacaction. They apply to tip/perf/urgent. Arguably on the 3rd one really should go into 3.5. The first, second and fourth patches should cleanly to tip/perf/core. Hopefully the fourth patch walks an rbtree correctly.

David Ahern (4):
perf kvm: set name for VM process in guest machine
perf kvm: guest userspace samples should not be lumped with host uspace perf kvm: limit repetitive guestmount message to once
perf kvm: fix bug resolving guest kernel syms

 tools/perf/util/map.c     |   44 ++++++++++++++++++++++++++++++++++++++++++--
 tools/perf/util/map.h     |    1 +
 tools/perf/util/session.c |    5 ++++-
 3 files changed, 47 insertions(+), 3 deletions(-)

Signature · 1 line

1.7.10.1

David Ahern

author

2012-07-10 21:48 UTC #1 lore raw

PATCH 1/4 perf kvm: set name for VM process in guest machine

COMM events are generated in the context of a guest machine, so the thread name is never set for the VMM process. For example, the qemu-kvm name applies to the process in the host machine. Samples for guest mode are currently displayed as:

    99.67%     :5671  [unknown]         [g] 0xffffffff81366b41

where 5671 is the pid of the VMM. With this patch the samples in guest mode are shown as:

    18.43%  [guest/5671]  [unknown]           [g] 0xffffffff810d68b7

Signed-off-by David Ahern <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Jiri Olsa <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Peter Zijlstra <[email protected]>

---
 tools/perf/util/map.c |   17 ++++++++++++++++-
 1 file changed, 16 insertions(+), 1 deletion(-)

tools/perf/util/map.c +16 -1

index a1f4e36..8668569 100644
@@ -7,6 +7,7 @@
 #include <stdio.h>
 #include <unistd.h>
 #include "map.h"
+#include "thread.h"
 
 const char *map_type__name[MAP__NR_TYPES] = {
 	[MAP__FUNCTION] = "Functions",

@@ -585,7 +586,21 @@ int machine__init(struct machine *self, const char *root_dir, pid_t pid)
 	self->kmaps.machine = self;
 	self->pid	    = pid;
 	self->root_dir      = strdup(root_dir);
-	return self->root_dir == NULL ? -ENOMEM : 0;
+	if (self->root_dir == NULL)
+		return -ENOMEM;
+
+	if (pid != HOST_KERNEL_ID) {
+		struct thread *thread = machine__findnew_thread(self, pid);
+		char comm[64];
+
+		if (thread == NULL)
+			return -ENOMEM;
+
+		snprintf(comm, sizeof(comm), "[guest/%d]", pid);
+		thread__set_comm(thread, comm);
+	}
+
+	return 0;
 }
 
 static void dsos__delete(struct list_head *self)

Signature · 1 line

1.7.10.1

David Ahern

author

2012-07-10 21:48 UTC #2 lore raw

PATCH 2/4 perf kvm: guest userspace samples should not be lumped with host uspace

In reply to David Ahern

e.g., perf kvm --host --guest report -i perf.data --stdio -D shows:

1 599127912065356 0x143b8 [0x48]: PERF_RECORD_SAMPLE(IP, 5): 5671/5676: 0x7fdf95a061c0 period: 1 addr: 0 ... chain: nr:2
..... 0: ffffffffffffff80
..... 1: fffffffffffffe00
... thread: qemu-kvm:5671
...... dso: <not found>

(IP, 5) means sample in guest userspace. Those samples should not be lumped into the VMM's host thread. i.e, the report output:

    56.86%  qemu-kvm  [unknown]         [u] 0x00007fdf95a061c0

With this patch the output emphasizes it is a guest userspace hit:

    56.86%  [guest/5671]  [unknown]         [u] 0x00007fdf95a061c0

Looking at 3 VMs (2 64-bit, 1 32-bit) with each running a CPU bound process (openssl speed), perf report currently shows:

93.84% 117726 qemu-kvm [unknown] [u] 0x00007fd7dcaea8e5

which is wrong. With this patch you get:

  31.50%   39258   [guest/18772]  [unknown]   [u] 0x00007fd7dcaea8e5
  31.50%   39236   [guest/11230]  [unknown]   [u] 0x0000000000a57340
  30.84%   39232   [guest/18395]  [unknown]   [u] 0x00007f66f641e107

Signed-off-by David Ahern <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Jiri Olsa <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Peter Zijlstra <[email protected]>

---
 tools/perf/util/session.c |    4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

tools/perf/util/session.c +3 -1

index 56142d0..7c31623 100644
@@ -918,7 +918,9 @@ static struct machine *
 {
 	const u8 cpumode = event->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;
 
-	if (cpumode == PERF_RECORD_MISC_GUEST_KERNEL && perf_guest) {
+	if (perf_guest &&
+	    ((cpumode == PERF_RECORD_MISC_GUEST_KERNEL) ||
+	     (cpumode == PERF_RECORD_MISC_GUEST_USER))) {
 		u32 pid;
 
 		if (event->header.type == PERF_RECORD_MMAP)

Signature · 1 line

1.7.10.1

David Ahern

author

2012-07-10 21:48 UTC #3 lore raw

PATCH 3/4 perf kvm: limit repetitive guestmount message to once

In reply to David Ahern

After 7ed97ad use of the guestmount option without a subdir for each VM generates an error message for *each* sample related to that VM. Once is enough.

Signed-off-by David Ahern <[email protected]>

---
 tools/perf/util/map.c |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

tools/perf/util/map.c +2 -1

index 8668569..641377e 100644
@@ -8,6 +8,7 @@
 #include <unistd.h>
 #include "map.h"
 #include "thread.h"
+#include "asm/bug.h"
 
 const char *map_type__name[MAP__NR_TYPES] = {
 	[MAP__FUNCTION] = "Functions",

@@ -695,7 +696,7 @@ struct machine *machines__findnew(struct rb_root *self, pid_t pid)
 	    (symbol_conf.guestmount)) {
 		sprintf(path, "%s/%d", symbol_conf.guestmount, pid);
 		if (access(path, R_OK)) {
-			pr_err("Can't access file %s\n", path);
+			WARN_ONCE(1, "Can't access file %s\n", path);
 			machine = NULL;
 			goto out;
 		}

Signature · 1 line

1.7.10.1

David Ahern

author

2012-07-10 21:48 UTC #4 lore raw

PATCH 4/4 perf kvm: fix bug resolving guest kernel syms

In reply to David Ahern

Guest kernel symbols are not resolved despite passing the information needed to resolve them. e.g.,

perf kvm --guest --guestmount=/tmp/guest-mount record -a -- sleep 1 perf kvm --guest --guestmount=/tmp/guest-mount report --stdio

    36.55%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
    33.19%  [guest/10474]  [unknown]         [g] 0x00000000c0116e00
    30.26%  [guest/11094]  [unknown]         [g] 0xffffffff8100a288

    43.69%  [guest/10474]  [unknown]         [g] 0x00000000c0103d90
    37.38%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
    12.24%  [guest/11094]  [unknown]         [g] 0xffffffff810aa91d
     6.69%  [guest/11094]  [unknown]         [u] 0x00007fa784d721c3

which is just pathetic.

After a maddening 2 days sifting through perf minutia I found it -- id_hdr_size is not initialized for guest machines. This shows up on the report side as random garbage for the cpu and timestamp, e.g.,

29816 7310572949125804849 0x1ac0 [0x50]: PERF_RECORD_MMAP ...

that messes up the sample sorting such that synthesized guest maps are processed last.

With this patch you get a much more helpful report:

  12.11%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] irqtime_account_process_tick
  10.58%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] run_timer_softirq
   6.95%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] printk_needs_cpu
   6.50%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] do_timer
   6.45%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] idle_balance
   4.90%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] native_read_tsc

...

Signed-off-by David Ahern <[email protected]>

Cc Arnaldo Carvalho de Melo <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Jiri Olsa <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Peter Zijlstra <[email protected]>

---
 tools/perf/util/map.c     |   24 ++++++++++++++++++++++++
 tools/perf/util/map.h     |    1 +
 tools/perf/util/session.c |    1 +
 3 files changed, 26 insertions(+)

tools/perf/util/map.c +24 -0

index 641377e..da3411b 100644
@@ -730,3 +730,27 @@ char *machine__mmap_name(struct machine *self, char *bf, size_t size)
 
 	return bf;
 }
+
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size)
+{
+	struct rb_node *p;
+	struct machine *machine;
+
+    p = self->rb_node;
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_next(p);
+	}
+
+    p = self->rb_node;
+    if (p)
+        p = rb_prev(p);
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_prev(p);
+	}
+
+	return;
+}

tools/perf/util/map.h +1 -0

index 81371ba..7159b3c 100644
@@ -151,6 +151,7 @@ struct machine *machines__add(struct rb_root *self, pid_t pid,
 struct machine *machines__find_host(struct rb_root *self);
 struct machine *machines__find(struct rb_root *self, pid_t pid);
 struct machine *machines__findnew(struct rb_root *self, pid_t pid);
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size);
 char *machine__mmap_name(struct machine *self, char *bf, size_t size);
 int machine__init(struct machine *self, const char *root_dir, pid_t pid);
 void machine__exit(struct machine *self);

tools/perf/util/session.c +1 -0

index 7c31623..fcf9498 100644
@@ -86,6 +86,7 @@ void perf_session__update_sample_type(struct perf_session *self)
 	self->sample_id_all = perf_evlist__sample_id_all(self->evlist);
 	self->id_hdr_size = perf_evlist__id_hdr_size(self->evlist);
 	self->host_machine.id_hdr_size = self->id_hdr_size;
+    machines__set_id_hdr_size(&self->machines, self->id_hdr_size);
 }
 
 int perf_session__create_kernel_maps(struct perf_session *self)

Signature · 1 line

1.7.10.1

Namhyung Kim

maintainer

2012-07-11 00:58 UTC #5 lore raw

Re: [PATCH 4/4] perf kvm: fix bug resolving guest kernel syms

Hi, David

Quoted 60 lines · David Ahern

Guest kernel symbols are not resolved despite passing the information needed to resolve them. e.g.,
perf kvm --guest --guestmount=/tmp/guest-mount record -a -- sleep 1 perf kvm --guest --guestmount=/tmp/guest-mount report --stdio
    36.55%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
    33.19%  [guest/10474]  [unknown]         [g] 0x00000000c0116e00
    30.26%  [guest/11094]  [unknown]         [g] 0xffffffff8100a288
    43.69%  [guest/10474]  [unknown]         [g] 0x00000000c0103d90
    37.38%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
    12.24%  [guest/11094]  [unknown]         [g] 0xffffffff810aa91d
     6.69%  [guest/11094]  [unknown]         [u] 0x00007fa784d721c3
which is just pathetic.
After a maddening 2 days sifting through perf minutia I found it -- id_hdr_size is not initialized for guest machines. This shows up on the report side as random garbage for the cpu and timestamp, e.g.,
29816 7310572949125804849 0x1ac0 [0x50]: PERF_RECORD_MMAP ...
that messes up the sample sorting such that synthesized guest maps are processed last.
With this patch you get a much more helpful report:
  12.11%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] irqtime_account_process_tick
  10.58%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] run_timer_softirq
   6.95%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] printk_needs_cpu
   6.50%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] do_timer
   6.45%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] idle_balance
   4.90%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] native_read_tsc
...
Signed-off-by David Ahern <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
---
 tools/perf/util/map.c     |   24 ++++++++++++++++++++++++
 tools/perf/util/map.h     |    1 +
 tools/perf/util/session.c |    1 +
 3 files changed, 26 insertions(+)
tools/perf/util/map.c +3 -0
index 641377e..da3411b 100644
@@ -730,3 +730,27 @@ char *machine__mmap_name(struct machine *self, char *bf, size_t size)
 
 	return bf;
 }
+
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size)
+{

tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 745

Quoted 10 lines

tools/perf/util/map.c +10 -0

+	struct rb_node *p;
+	struct machine *machine;
+
+    p = self->rb_node;
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_next(p);
+	}
+

Looks like white-space damaged. :(

The loop itself looks fine, or you might use this form:

	for (p = rb_first(self); p; p = rb_next(p))

Is there a something like rb_for_each_entry() ?

tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 754

Quoted 9 lines

tools/perf/util/map.c +9 -0

+    p = self->rb_node;
+    if (p)
+        p = rb_prev(p);
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_prev(p);
+	}
+

I don't see why this second loop is necessary?

Thanks,
Namhyung

Quoted 26 lines

tools/perf/util/map.c +2 -0

+	return;
+}

tools/perf/util/map.h +1 -0

index 81371ba..7159b3c 100644
@@ -151,6 +151,7 @@ struct machine *machines__add(struct rb_root *self, pid_t pid,
 struct machine *machines__find_host(struct rb_root *self);
 struct machine *machines__find(struct rb_root *self, pid_t pid);
 struct machine *machines__findnew(struct rb_root *self, pid_t pid);
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size);
 char *machine__mmap_name(struct machine *self, char *bf, size_t size);
 int machine__init(struct machine *self, const char *root_dir, pid_t pid);
 void machine__exit(struct machine *self);

tools/perf/util/session.c +1 -0

index 7c31623..fcf9498 100644
@@ -86,6 +86,7 @@ void perf_session__update_sample_type(struct perf_session *self)
 	self->sample_id_all = perf_evlist__sample_id_all(self->evlist);
 	self->id_hdr_size = perf_evlist__id_hdr_size(self->evlist);
 	self->host_machine.id_hdr_size = self->id_hdr_size;
+    machines__set_id_hdr_size(&self->machines, self->id_hdr_size);
 }
 
 int perf_session__create_kernel_maps(struct perf_session *self)

David Ahern

author

2012-07-11 02:23 UTC #6 lore raw

Re: [PATCH 4/4] perf kvm: fix bug resolving guest kernel syms

Quoted 67 lines · Namhyung Kim

Hi, David
Quoted 64 lines · David Ahern
Guest kernel symbols are not resolved despite passing the information needed to resolve them. e.g.,
perf kvm --guest --guestmount=/tmp/guest-mount record -a -- sleep 1 perf kvm --guest --guestmount=/tmp/guest-mount report --stdio
     36.55%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
     33.19%  [guest/10474]  [unknown]         [g] 0x00000000c0116e00
     30.26%  [guest/11094]  [unknown]         [g] 0xffffffff8100a288
     43.69%  [guest/10474]  [unknown]         [g] 0x00000000c0103d90
     37.38%  [guest/11399]  [unknown]         [g] 0xffffffff81600bc8
     12.24%  [guest/11094]  [unknown]         [g] 0xffffffff810aa91d
      6.69%  [guest/11094]  [unknown]         [u] 0x00007fa784d721c3
which is just pathetic.
After a maddening 2 days sifting through perf minutia I found it -- id_hdr_size is not initialized for guest machines. This shows up on the report side as random garbage for the cpu and timestamp, e.g.,
29816 7310572949125804849 0x1ac0 [0x50]: PERF_RECORD_MMAP ...
that messes up the sample sorting such that synthesized guest maps are processed last.
With this patch you get a much more helpful report:
   12.11%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] irqtime_account_process_tick
   10.58%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] run_timer_softirq
    6.95%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] printk_needs_cpu
    6.50%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] do_timer
    6.45%  [guest/11399]  [guest.kernel.kallsyms.11399]  [g] idle_balance
    4.90%  [guest/11094]  [guest.kernel.kallsyms.11094]  [g] native_read_tsc
...
Signed-off-by David Ahern <[email protected]>
Cc Arnaldo Carvalho de Melo <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Jiri Olsa <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Peter Zijlstra <[email protected]>
---
  tools/perf/util/map.c     |   24 ++++++++++++++++++++++++
  tools/perf/util/map.h     |    1 +
  tools/perf/util/session.c |    1 +
  3 files changed, 26 insertions(+)
tools/perf/util/map.c +7 -0
index 641377e..da3411b 100644
@@ -730,3 +730,27 @@ char *machine__mmap_name(struct machine *self, char *bf, size_t size)
 
  	return bf;
  }
+
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size)
+{
+	struct rb_node *p;
+	struct machine *machine;
+
+    p = self->rb_node;

Quoted 8 lines

tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 745
Quoted 6 lines
tools/perf/util/map.c +6 -0
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_next(p);
+	}
+
Looks like white-space damaged. :(

bleah, something on my dev server converted tabs to spaces. Will fix.

Quoted 4 lines

The loop itself looks fine, or you might use this form:
	for (p = rb_first(self); p; p = rb_next(p))

Doesn't work - I still see machines not updated.

Quoted 3 lines

Is there a something like rb_for_each_entry() ?

Didn't see one.

Quoted 13 lines

tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 754
Quoted 11 lines
tools/perf/util/map.c +9 -0
+    p = self->rb_node;
+    if (p)
+        p = rb_prev(p);
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_prev(p);
+	}
+
I don't see why this second loop is necessary?

To get the left half of the tree I believe. First loop walks the root and all of the leaves to the right; this loop walks all of the leaves to the left.

David

Namhyung Kim

maintainer

2012-07-11 02:34 UTC #7 lore raw

Re: [PATCH 4/4] perf kvm: fix bug resolving guest kernel syms

Quoted 54 lines · David Ahern

Quoted 16 lines · Namhyung Kim
Quoted 15 lines · David Ahern
tools/perf/util/map.c +7 -0
index 641377e..da3411b 100644
@@ -730,3 +730,27 @@ char *machine__mmap_name(struct machine *self, char *bf, size_t size)
 
  	return bf;
  }
+
+void machines__set_id_hdr_size(struct rb_root *self, u16 id_hdr_size)
+{
+	struct rb_node *p;
+	struct machine *machine;
+
+    p = self->rb_node;
Quoted 8 lines
tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 745
Quoted 6 lines
tools/perf/util/map.c +6 -0
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_next(p);
+	}
+
Looks like white-space damaged. :(
bleah, something on my dev server converted tabs to spaces. Will fix.
Quoted 4 lines
The loop itself looks fine, or you might use this form:
	for (p = rb_first(self); p; p = rb_next(p))
Doesn't work - I still see machines not updated.
Quoted 3 lines
Is there a something like rb_for_each_entry() ?
Didn't see one.
Quoted 13 lines
tools/perf/util/map.c char *machine__mmap_name(struct machine *self, char *bf, size_t size) · line 754
Quoted 11 lines
tools/perf/util/map.c +9 -0
+    p = self->rb_node;
+    if (p)
+        p = rb_prev(p);
+	while (p != NULL) {
+		machine = rb_entry(p, struct machine, rb_node);
+		machine->id_hdr_size = id_hdr_size;
+        p = rb_prev(p);
+	}
+
I don't see why this second loop is necessary?

Quoted 4 lines

To get the left half of the tree I believe. First loop walks the root and all of the leaves to the right; this loop walks all of the leaves to the left.

Oh, I overlooked the initial setting. So you divided tree-traversal to left and right part. It seems very odd to me. AFAIK a traversal from rb_first through rb_next shouldn't miss any node in the tree.

Thanks,
Namhyung