Implement dwarf variable/type resolving for perf script

From: Andi Kleen <[email protected]>

Add a configurable node size to strlist, which allows users to store additional data in a str_node. Also add a new interface to add a new strlist node, and return the node, so additional data can be added.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/rblist.c  | 16 ++++++++++++++--
 tools/perf/util/rblist.h  |  2 ++
 tools/perf/util/strlist.c | 15 ++++++++++++++-
 tools/perf/util/strlist.h |  8 ++++++++
 4 files changed, 38 insertions(+), 3 deletions(-)

tools/perf/util/rblist.c +14 -2

index 0dfe27d99458..fa221e6b0932 100644
@@ -11,11 +11,13 @@
 
 #include "rblist.h"
 
-int rblist__add_node(struct rblist *rblist, const void *new_entry)
+int rblist__add_node_ptr(struct rblist *rblist, const void *new_entry,
+		       struct rb_node **nodep)
 {
 	struct rb_node **p = &rblist->entries.rb_node;
 	struct rb_node *parent = NULL, *new_node;
 
+	*nodep = NULL;
 	while (*p != NULL) {
 		int rc;
 

@@ -26,13 +28,16 @@ int rblist__add_node(struct rblist *rblist, const void *new_entry)
 			p = &(*p)->rb_left;
 		else if (rc < 0)
 			p = &(*p)->rb_right;
-		else
+		else {
+			*nodep = parent;
 			return -EEXIST;
+		}
 	}
 
 	new_node = rblist->node_new(rblist, new_entry);
 	if (new_node == NULL)
 		return -ENOMEM;
+	*nodep = new_node;
 
 	rb_link_node(new_node, parent, p);
 	rb_insert_color(new_node, &rblist->entries);

@@ -41,6 +46,13 @@ int rblist__add_node(struct rblist *rblist, const void *new_entry)
 	return 0;
 }
 
+int rblist__add_node(struct rblist *rblist, const void *new_entry)
+{
+	struct rb_node *nd;
+
+	return rblist__add_node_ptr(rblist, new_entry, &nd);
+}
+
 void rblist__remove_node(struct rblist *rblist, struct rb_node *rb_node)
 {
 	rb_erase(rb_node, &rblist->entries);

tools/perf/util/rblist.h +2 -0

index 4c8638a22571..2941e4295f63 100644
@@ -31,6 +31,8 @@ struct rblist {
 void rblist__init(struct rblist *rblist);
 void rblist__delete(struct rblist *rblist);
 int rblist__add_node(struct rblist *rblist, const void *new_entry);
+int rblist__add_node_ptr(struct rblist *rblist, const void *new_entry,
+			 struct rb_node **nodep);
 void rblist__remove_node(struct rblist *rblist, struct rb_node *rb_node);
 struct rb_node *rblist__find(struct rblist *rblist, const void *entry);
 struct rb_node *rblist__findnew(struct rblist *rblist, const void *entry);

tools/perf/util/strlist.c +1 -1

index 9de5434bb49e..68ef21c3797c 100644
@@ -18,7 +18,7 @@ struct rb_node *strlist__node_new(struct rblist *rblist, const void *entry)
 	const char *s = entry;
 	struct rb_node *rc = NULL;
 	struct strlist *strlist = container_of(rblist, struct strlist, rblist);
-	struct str_node *snode = malloc(sizeof(*snode));
+	struct str_node *snode = malloc(strlist->node_size);
 
 	if (snode != NULL) {
 		if (strlist->dupstr) {

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

+
 int strlist__load(struct strlist *slist, const char *filename)
 {
 	char entry[1024];

@@ -165,11 +173,15 @@ struct strlist *strlist__new(const char *list, const struct strlist_config *conf
 		bool dupstr = true;
 		bool file_only = false;

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

 		}
 
 		rblist__init(&slist->rblist);

@@ -179,6 +191,7 @@ struct strlist *strlist__new(const char *list, const struct strlist_config *conf
 
 		slist->dupstr	 = dupstr;
 		slist->file_only = file_only;
+		slist->node_size = node_size;
 
 		if (list && strlist__parse_list(slist, list, dirname) != 0)
 			goto out_error;

tools/perf/util/strlist.h +4 -0

index d58f1e08b170..fd407e11e124 100644
@@ -16,25 +16,33 @@ struct strlist {
 	struct rblist rblist;
 	bool	      dupstr;
 	bool	      file_only;
+	size_t	      node_size;
 };
 
 /*
  * @file_only: When dirname is present, only consider entries as filenames,
  *             that should not be added to the list if dirname/entry is not
  *             found
+ * @node_size: Allocate extra space after str_node which can be used for other
+ *	       data. This is the complete size including str_node
  */
 struct strlist_config {
 	bool dont_dupstr;
 	bool file_only;
 	const char *dirname;
+	size_t node_size;
 };
 

tools/perf/util/strlist.h +0 -0

 struct str_node *strlist__entry(const struct strlist *slist, unsigned int idx);
 struct str_node *strlist__find(struct strlist *slist, const char *entry);

Signature · 1 line

2.13.6

From: Andi Kleen <[email protected]>

Print the location, e.g. the register, for resolved variables with perf probe -V. This is useful for debugging, and manually making sense of disassembly. I also have some scripts which can make use of this information.

Before:

% perf probe -x ./tsrc/tstruct -V main+20
Available variables at main+20
@<main+20>
struct str* xp

After:

% perf probe -x ./tsrc/tstruct -V main+20
Available variables at main+20
@<main+20>
struct str* xp %ax

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/probe-finder.c | 5 +++++
 1 file changed, 5 insertions(+)

tools/perf/util/probe-finder.c +5 -0

index 0149428d453e..699f29d8a28e 100644
@@ -1369,6 +1369,7 @@ static int collect_variables_cb(Dwarf_Die *die_mem, void *data)
 	if (tag == DW_TAG_formal_parameter ||
 	    tag == DW_TAG_variable) {
 		struct probe_trace_arg ta;
+		struct probe_trace_arg_ref *ref;
 
 		memset(&ta, 0, sizeof(struct probe_trace_arg));
 		ret = convert_variable_location(die_mem, af->pf.addr,

@@ -1401,6 +1402,10 @@ static int collect_variables_cb(Dwarf_Die *die_mem, void *data)
 							die_mem, &buf);
 			}
 
+			strbuf_addf(&buf, "\t%s", ta.value);
+			for (ref = ta.ref; ref; ref = ref->next)
+				strbuf_addf(&buf, " off %ld", ref->offset);
+
 			pr_debug("Add new var: %s\n", buf.buf);
 			if (ret2 == 0) {
 				struct str_node *sn;

Signature · 1 line

2.13.6

From: Andi Kleen <[email protected]>

Add a extra quiet argument to the debug info open / probe finder code that allows perf script to make them quieter. Otherwise we may end up with too many error messages when lots of instructions fail debug info parsing.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/probe-event.c  |  4 ++--
 tools/perf/util/probe-finder.c | 19 ++++++++++++-------
 tools/perf/util/probe-finder.h |  5 ++++-
 3 files changed, 18 insertions(+), 10 deletions(-)

tools/perf/util/probe-event.c +2 -2

index b7aaf9b2294d..2f9469e862fb 100644
@@ -1071,12 +1071,12 @@ static int show_available_vars_at(struct debuginfo *dinfo,
 		return -EINVAL;
 	pr_debug("Searching variables at %s\n", buf);
 
-	ret = debuginfo__find_available_vars_at(dinfo, pev, &vls);
+	ret = debuginfo__find_available_vars_at(dinfo, pev, &vls, false);
 	if (!ret) {  /* Not found, retry with an alternative */
 		ret = get_alternative_probe_event(dinfo, pev, &tmp);
 		if (!ret) {
 			ret = debuginfo__find_available_vars_at(dinfo, pev,
-								&vls);
+								&vls, false);
 			/* Release the old probe_point */
 			clear_perf_probe_point(&tmp);
 		}

tools/perf/util/probe-finder.c +12 -7

index 699f29d8a28e..137b2fe71838 100644
@@ -685,12 +685,14 @@ static int call_probe_finder(Dwarf_Die *sc_die, struct probe_finder *pf)
 	if (!die_is_func_def(sc_die)) {
 		if (!die_find_realfunc(&pf->cu_die, pf->addr, &pf->sp_die)) {
 			if (die_find_tailfunc(&pf->cu_die, pf->addr, &pf->sp_die)) {
-				pr_warning("Ignoring tail call from %s\n",
+				if (!pf->quiet)
+					pr_warning("Ignoring tail call from %s\n",
 						dwarf_diename(&pf->sp_die));
 				return 0;
 			} else {
-				pr_warning("Failed to find probe point in any "
-					   "functions.\n");
+				if (!pf->quiet)
+					pr_warning("Failed to find probe point in any "
+						   "functions.\n");
 				return -ENOENT;
 			}
 		}

@@ -708,8 +710,9 @@ static int call_probe_finder(Dwarf_Die *sc_die, struct probe_finder *pf)
 		if ((dwarf_cfi_addrframe(pf->cfi_eh, pf->addr, &frame) != 0 &&
 		     (dwarf_cfi_addrframe(pf->cfi_dbg, pf->addr, &frame) != 0)) ||
 		    dwarf_frame_cfa(frame, &pf->fb_ops, &nops) != 0) {
-			pr_warning("Failed to get call frame on 0x%jx\n",
-				   (uintmax_t)pf->addr);
+			if (!pf->quiet)
+				pr_warning("Failed to get call frame on 0x%jx\n",
+					   (uintmax_t)pf->addr);
 			free(frame);
 			return -ENOENT;
 		}

@@ -1499,10 +1502,12 @@ static int add_available_vars(Dwarf_Die *sc_die, struct probe_finder *pf)
  */
 int debuginfo__find_available_vars_at(struct debuginfo *dbg,
 				      struct perf_probe_event *pev,
-				      struct variable_list **vls)
+				      struct variable_list **vls,
+				      bool be_quiet)
 {
 	struct available_var_finder af = {
-			.pf = {.pev = pev, .callback = add_available_vars},
+			.pf = {.pev = pev, .callback = add_available_vars,
+			       .quiet = be_quiet},
 			.mod = dbg->mod,
 			.max_vls = probe_conf.max_probes};
 	int ret;

tools/perf/util/probe-finder.h +4 -1

index 6368e95a5d16..abcb2262ea72 100644
@@ -57,7 +57,8 @@ int debuginfo__find_line_range(struct debuginfo *dbg, struct line_range *lr);
 /* Find available variables */
 int debuginfo__find_available_vars_at(struct debuginfo *dbg,
 				      struct perf_probe_event *pev,
-				      struct variable_list **vls);
+				      struct variable_list **vls,
+				      bool quiet);
 
 /* Find a src file from a DWARF tag path */
 int get_real_path(const char *raw_path, const char *comp_dir,

@@ -88,6 +89,8 @@ struct probe_finder {
 	unsigned int		machine;	/* Target machine arch */
 	struct perf_probe_arg	*pvar;		/* Current target variable */
 	struct probe_trace_arg	*tvar;		/* Current result variable */
+
+	bool			quiet;		/* Avoid warnings */
 };
 
 struct trace_event_finder {

Signature · 1 line

2.13.6

Quoted 6 lines · On Mon, 27 Nov 2017 16:23:15 -0800 Andi Kleen <[email protected]> wrote:

From: Andi Kleen <[email protected]>

Add a extra quiet argument to the debug info open / probe finder code that allows perf script to make them quieter. Otherwise we may end up with too many error messages when lots of instructions fail debug info parsing.

IMHO, this kind of simple suppress warning message would better be done with pr_* implementation (or its macro) since there maybe new message added or other function which has warning messages can be called in the future.

Quoted 10 lines · Masami Hiramatsu

Quoted 6 lines · On Mon, 27 Nov 2017 16:23:15 -0800 Andi Kleen <[email protected]> wrote:

From: Andi Kleen <[email protected]>

Add a extra quiet argument to the debug info open / probe finder code that allows perf script to make them quieter. Otherwise we may end up with too many error messages when lots of instructions fail debug info parsing.

Quoted 4 lines

IMHO, this kind of simple suppress warning message would better be done with pr_* implementation (or its macro) since there maybe new message added or other function which has warning messages can be called in the future.

Do you really mean adding a special pr_ / global just for this case?

Seems less clean to me, but I can do it.

-Andi

From: Andi Kleen <[email protected]>

Normally perf script debug info resolution doesn't print warnings, but allow -v to override that. Useful for finding out why things don't work.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/probe-event.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

tools/perf/util/probe-event.c +2 -2

index 4ef6ee967468..fb5031ac24a2 100644
@@ -482,7 +482,7 @@ static struct debuginfo *open_debuginfo(const char *module, struct nsinfo *nsi,
 					strcpy(reason, "(unknown)");
 			} else
 				dso__strerror_load(dso, reason, STRERR_BUFSIZE);
-			if (!silent)
+			if (!silent || verbose)
 				pr_err("Failed to find the path for %s: %s\n",
 					module ?: "kernel", reason);
 			return NULL;

@@ -491,7 +491,7 @@ static struct debuginfo *open_debuginfo(const char *module, struct nsinfo *nsi,
 	}
 	nsinfo__mountns_enter(nsi, &nsc);
 	ret = debuginfo__new(path);
-	if (!ret && !silent) {
+	if (!ret && (!silent || verbose)) {
 		pr_warning("The %s file has no debug information.\n", path);
 		if (!module || !strtailcmp(path, ".ko"))
 			pr_warning("Rebuild with CONFIG_DEBUG_INFO=y, ");

Signature · 1 line

2.13.6

From: Andi Kleen <[email protected]>

When tracing floating point code it's quite possible that perf doesn't recognize the register number. Downgrade the warning for unknown registers to a debug message.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/probe-finder.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

tools/perf/util/probe-finder.c +2 -2

index 137b2fe71838..5fe6466254f9 100644
@@ -272,8 +272,8 @@ static int convert_variable_location(Dwarf_Die *vr_die, Dwarf_Addr addr,
 
 	regs = get_dwarf_regstr(regn, machine);
 	if (!regs) {
-		/* This should be a bug in DWARF or this tool */
-		pr_warning("Mapping for the register number %u "
+		/* This can happen with floating point */
+		pr_debug("Mapping for the register number %u "
 			   "missing on this architecture.\n", regn);
 		return -ENOTSUP;
 	}

Signature · 1 line

2.13.6

From: Andi Kleen <[email protected]>

When the perf probe code is called from perf script we may end up with a flood of bad binary errors with -v. Only print the error message once in this case.

Signed-off-by Andi Kleen <[email protected]>

---
 tools/perf/util/probe-event.c | 16 ++++++++++------
 1 file changed, 10 insertions(+), 6 deletions(-)

tools/perf/util/probe-event.c +10 -6

index fb5031ac24a2..85fbeeb364bf 100644
@@ -492,12 +492,16 @@ static struct debuginfo *open_debuginfo(const char *module, struct nsinfo *nsi,
 	nsinfo__mountns_enter(nsi, &nsc);
 	ret = debuginfo__new(path);
 	if (!ret && (!silent || verbose)) {
-		pr_warning("The %s file has no debug information.\n", path);
-		if (!module || !strtailcmp(path, ".ko"))
-			pr_warning("Rebuild with CONFIG_DEBUG_INFO=y, ");
-		else
-			pr_warning("Rebuild with -g, ");
-		pr_warning("or install an appropriate debuginfo package.\n");
+		static char printed[1024];
+		if (strcmp(path, printed)) {
+			snprintf(printed, sizeof printed, "%s", path);
+			pr_warning("The %s file has no debug information.\n", path);
+			if (!module || !strtailcmp(path, ".ko"))
+				pr_warning("Rebuild with CONFIG_DEBUG_INFO=y, ");
+			else
+				pr_warning("Rebuild with -g, ");
+			pr_warning("or install an appropriate debuginfo package.\n");
+		}
 	}
 	nsinfo__mountns_exit(&nsc);
 	return ret;

Signature · 1 line

2.13.6

From perf itself

From: Andi Kleen <[email protected]>

Implement resolving arguments of instructions to dwarf variable names.

When we sample an instruction, decode the instruction and try to symbolize the register or destination it is using. Also print the type. It builds on the perf probe debugging information reverse lookup infrastructure added earlier.

The dwarf decoding magic is all done using Masami Hiramatsu's perf probe code.

This is useful for

- The PTWRITE instruction: when the compiler generates debugging information for PTWRITE arguments. The value logged by PTWRITE is available to the PT decoder, so it can print the value.

- It also works for other samples with an IP, so it's possible to follow their memory access patterns (but not the values)

For the sample we use the instruction decoder to decode the instruction at the sample point, and then map the arguments to dwarf information.

For structure reference we only print the numeric offset, but do not resolve the field name.

Absolute memory references are not supported

It doesn't distinguish SSE (but AVX) registers from GPRs (this would require extending the instruction decoder to detect SSE instructions)

Example:

From perf itself

% perf record -e intel_pt//u -a sleep 1
% perf script --itrace=i0ns -F insnvar,insn,ip,sym -f 2>&1 | xed -F insn: -A -64 | less
...

           4f7e61 xyarray__max_y                pushq  %rbp
           4f7e62 xyarray__max_y                mov %rsp, %rbp
           4f7e65 xyarray__max_y                sub $0x20, %rsp
           4f7e69 xyarray__max_y                movq  %rdi, -0x18(%rbp) { -24(xy), struct xyarray* }
           4f7e6d xyarray__max_y                movq  %fs:0x28, %rax
           4f7e76 xyarray__max_y                movq  %rax, -0x8(%rbp) { -8(xy), struct xyarray* }
           4f7e7a xyarray__max_y                xor %eax, %eax
           4f7e7c xyarray__max_y                movq  -0x18(%rbp), %rax { -24(xy), struct xyarray* }
           4f7e80 xyarray__max_y                movq  0x20(%rax), %rax
           4f7e84 xyarray__max_y                movq  -0x8(%rbp), %rdx { -8(xy), struct xyarray* }
           4f7e88 xyarray__max_y                xorq  %fs:0x28, %rdx
           4f7e91 xyarray__max_y                jz 0x7
           4f7e98 xyarray__max_y                leaveq
           4f7e99 xyarray__max_y                retq

In this example we now know that this function accesses two fields in struct xyarray *

Open Issues:
- It is fairly slow. Some caching would likely help.

- Frame pointer references are usually not correctly resolved, which are common in unoptimized code. That's usually fine because memory access on the stack is not very interesting.
- It cannot resolve some references.

But I find it already quite useful.

Signed-off-by Andi Kleen <[email protected]>

tools/perf/util/probe-event.c +1 -0

+
 	symbol_conf.sort_by_name = true;
 	symbol_conf.allow_aliases = true;
 	ret = symbol__init(NULL);

Signature · 1 line

2.13.6

This patchkit extends perf script to query dwarf information for variable names or types/structure fields accessed from code.

The dwarf resolution is all on top of Masami's perf probe dwarf code.

It supports multiple use cases:
- When we sample registers it can use the dwarf information to resolve the registers to names.
- When we sample any instruction the instruction can be decoded and we can determine the type/struct field to make an estimate of the memory access patterns in data structures.
- When we sample the new PTWRITE instruction the logged value from the PT log can be associated with a variable.
- Various cleanups and fixes to make the one above all possible.

It is all implemented with new output formats in perf script:
iregval (map register values to names) and insnvar (decode instruction and map back memory operand to dwarf operation)

There are some limitations, it cannot decode everything, and is somewhat slow, but it's already quite useful for typical code

    % perf record -Idi,si ./targ
    % perf script -F +iregvals
    ...
        targ  8584 169763.761843:    2091795 cycles:ppp:            40041a main (targ)
        targ  8584 169763.762520:    1913932 cycles:ppp:            400534 f1 (targ) { b = 0x2, int }  { a = 0x1, int }
        targ  8584 169763.763141:    1638913 cycles:ppp:            400523 f2 (targ) { b = 0x1, int }  { a = 0x2, int }
        targ  8584 169763.763672:    1516522 cycles:ppp:            400522 f2 (targ) { b = 0x1, int }  { a = 0x2, int }
        targ  8584 169763.764165:    1335501 cycles:ppp:            400523 f2 (targ) { b = 0x1, int }  { a = 0x2, int }
        targ  8584 169763.764598:    1253289 cycles:ppp:            400522 f2 (targ) { b = 0x2, int }  { a = 0x1, int }
        targ  8584 169763.765005:    1135131 cycles:ppp:            400534 f1 (targ) { b = 0x2, int }  { a = 0x1, int }
        targ  8584 169763.765373:    1080325 cycles:ppp:            400522 f2 (targ) { b = 0x2, int }  { a = 0x1, int }
        targ  8584 169763.765724:    1036999 cycles:ppp:            400522 f2 (targ) { b = 0x1, int }  { a = 0x2, int }
        targ  8584 169763.766061:     971213 cycles:ppp:            400534 f1 (targ) { b = 0x2, int }  { a = 0x1, int }


    % perf record -e intel_pt//u  -a sleep 1
    % perf script --itrace=i0ns -F insnvar,insn,ip,sym  -f 2>&1 | xed -F insn: -A -64 | less
    ...
               4f7e61 xyarray__max_y                pushq  %rbp
               4f7e62 xyarray__max_y                mov %rsp, %rbp
               4f7e65 xyarray__max_y                sub $0x20, %rsp
               4f7e69 xyarray__max_y                movq  %rdi, -0x18(%rbp) { -24(xy), struct xyarray* }
               4f7e6d xyarray__max_y                movq  %fs:0x28, %rax
               4f7e76 xyarray__max_y                movq  %rax, -0x8(%rbp) { -8(xy), struct xyarray* }
               4f7e7a xyarray__max_y                xor %eax, %eax
               4f7e7c xyarray__max_y                movq  -0x18(%rbp), %rax { -24(xy), struct xyarray* }
               4f7e80 xyarray__max_y                movq  0x20(%rax), %rax
               4f7e84 xyarray__max_y                movq  -0x8(%rbp), %rdx { -8(xy), struct xyarray* }
               4f7e88 xyarray__max_y                xorq  %fs:0x28, %rdx
               4f7e91 xyarray__max_y                jz 0x7
               4f7e98 xyarray__max_y                leaveq
               4f7e99 xyarray__max_y                retq

In this example we now know that this function accesses two fields in struct xyarray *

Available from

git://git.kernel.org/pub/scm/linux/kernel/git/ak/linux-misc perf/var-resolve-2

v1: Initial post