[RFC] --dump-sym-trace

[RFC] --dump-sym-trace

[Arun Sharma]

[-- Attachment #1: Type: text/plain, Size: 673 bytes --]

Some of my coworkers want to build tools to aggregate perf.data files
from many different machines and provide web front ends and possibly
other ways of visualizing the data (graphviz dot format comes to
mind). One potential path is to use perf report -D (raw dump) and
analyze that. But it made no sense to duplicate the functionality
already in perf.

Attached is a preliminary patch that dumps the trace, but also
symbolizes the addresses. It's probably not terribly efficient - but I
wanted to post it anyway to figure out if this is a good starting
point or there are other ways of getting perf to report call graphs
that are easy to parse in another program.

 -Arun

[-- Attachment #2: dump-sym-trace.patch --]
[-- Type: application/octet-stream, Size: 5476 bytes --]

diff --git a/tools/perf/builtin-report.c b/tools/perf/builtin-report.c
index 75183a4..19c3d1b 100644
--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -443,6 +443,8 @@ static const struct option options[] = {
 		    "be more verbose (show symbol address, etc)"),
 	OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
 		    "dump raw trace in ASCII"),
+	OPT_BOOLEAN(0, "dump-sym-trace", &dump_sym_trace,
+		    "Similar to dump-raw-trace, but symbolized"),
 	OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
 		   "file", "vmlinux pathname"),
 	OPT_STRING(0, "kallsyms", &symbol_conf.kallsyms_name,
@@ -501,6 +503,10 @@ int cmd_report(int argc, const char **argv, const char *prefix __used)
 		setup_browser();
 	else
 		use_browser = 0;
+
+	if (dump_sym_trace)
+		dump_trace = 1;
+
 	/*
 	 * Only in the newt browser we are doing integrated annotation,
 	 * so don't allocate extra space that won't be used in the stdio
diff --git a/tools/perf/util/debug.c b/tools/perf/util/debug.c
index 01bbe8e..d645654 100644
--- a/tools/perf/util/debug.c
+++ b/tools/perf/util/debug.c
@@ -13,7 +13,7 @@
 #include "util.h"
 
 int verbose;
-bool dump_trace = false, quiet = false;
+bool dump_trace = false, dump_sym_trace = false, quiet = false;
 
 int eprintf(int level, const char *fmt, ...)
 {
diff --git a/tools/perf/util/debug.h b/tools/perf/util/debug.h
index ca35fd6..9cc4b7a 100644
--- a/tools/perf/util/debug.h
+++ b/tools/perf/util/debug.h
@@ -6,7 +6,7 @@
 #include "event.h"
 
 extern int verbose;
-extern bool quiet, dump_trace;
+extern bool quiet, dump_trace, dump_sym_trace;
 
 int dump_printf(const char *fmt, ...) __attribute__((format(printf, 1, 2)));
 void trace_event(event_t *event);
diff --git a/tools/perf/util/event.c b/tools/perf/util/event.c
index 2302ec0..4ef3a05 100644
--- a/tools/perf/util/event.c
+++ b/tools/perf/util/event.c
@@ -753,6 +753,22 @@ static void dso__calc_col_width(struct dso *self, struct hists *hists)
 	self->slen_calculated = 1;
 }
 
+int symbolize(const event_t *self, struct perf_session *session,
+	      struct addr_location *al, u64 addr) {
+	struct thread *thread = perf_session__findnew(session, self->ip.pid);
+	u8 cpumode = self->header.misc & PERF_RECORD_MISC_CPUMODE_MASK;
+
+	if (thread == NULL)
+		return -1;
+
+	thread__find_addr_map(thread, session, cpumode, MAP__FUNCTION,
+			      self->ip.pid, addr, al);
+	if (al->map) {
+		al->sym = map__find_symbol(al->map, al->addr, NULL);
+	}
+	return 0;
+}
+
 int event__preprocess_sample(const event_t *self, struct perf_session *session,
 			     struct addr_location *al, struct sample_data *data,
 			     symbol_filter_t filter)
diff --git a/tools/perf/util/event.h b/tools/perf/util/event.h
index 2b7e919..f6a6c99 100644
--- a/tools/perf/util/event.h
+++ b/tools/perf/util/event.h
@@ -166,6 +166,8 @@ int event__process(event_t *event, struct sample_data *sample,
 		   struct perf_session *session);
 
 struct addr_location;
+int symbolize(const event_t *self, struct perf_session *session,
+	      struct addr_location *al, u64 addr);
 int event__preprocess_sample(const event_t *self, struct perf_session *session,
 			     struct addr_location *al, struct sample_data *data,
 			     symbol_filter_t filter);
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index 313dac2..e4b2489 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -648,14 +648,29 @@ static int perf_session_queue_event(struct perf_session *s, event_t *event,
 	return 0;
 }
 
-static void callchain__printf(struct sample_data *sample)
+static void callchain__printf(struct perf_session *session, event_t *event,
+                              struct sample_data *sample)
 {
 	unsigned int i;
 
 	printf("... chain: nr:%Lu\n", sample->callchain->nr);
 
-	for (i = 0; i < sample->callchain->nr; i++)
-		printf("..... %2d: %016Lx\n", i, sample->callchain->ips[i]);
+	for (i = 0; i < sample->callchain->nr; i++) {
+		int ret = 0;
+		struct addr_location al;
+
+		if (dump_sym_trace) {
+			ret = symbolize(event, session, &al,
+					sample->callchain->ips[i]);	
+		}
+
+		if (dump_sym_trace && !ret && al.sym && al.sym->name) {
+			printf("..... %2d: %16s\n", i, al.sym->name);
+		} else {
+			printf("..... %2d: %016Lx\n", i,
+			       sample->callchain->ips[i]);
+		}
+	}
 }
 
 static void perf_session__print_tstamp(struct perf_session *session,
@@ -696,14 +711,28 @@ static void dump_event(struct perf_session *session, event_t *event,
 static void dump_sample(struct perf_session *session, event_t *event,
 			struct sample_data *sample)
 {
+	struct addr_location al;
+	int ret;
+
 	if (!dump_trace)
 		return;
 
-	printf("(IP, %d): %d/%d: %#Lx period: %Ld\n", event->header.misc,
-	       sample->pid, sample->tid, sample->ip, sample->period);
+	if (dump_sym_trace) {
+		/* Try to symbolize */
+		ret = symbolize(event, session, &al, sample->ip);	
+	}
+
+	if (dump_sym_trace && !ret && al.sym && al.sym->name) {
+		printf("(IP, %d): %d/%d: %s period: %Ld\n", event->header.misc,
+	       	       sample->pid, sample->tid, al.sym->name, sample->period);
+ 	} else {
+		printf("(IP, %d): %d/%d: %#Lx period: %Ld\n",
+                       event->header.misc,
+	       	       sample->pid, sample->tid, sample->ip, sample->period);
+	}
 
 	if (session->sample_type & PERF_SAMPLE_CALLCHAIN)
-		callchain__printf(sample);
+		callchain__printf(session, event, sample);
 }
 
 static int perf_session_deliver_event(struct perf_session *session,

Re: [RFC] --dump-sym-trace

[David Ahern]

On 01/25/11 18:47, Arun Sharma wrote:
> Some of my coworkers want to build tools to aggregate perf.data files
> from many different machines and provide web front ends and possibly
> other ways of visualizing the data (graphviz dot format comes to
> mind). One potential path is to use perf report -D (raw dump) and
> analyze that. But it made no sense to duplicate the functionality
> already in perf.
> 
> Attached is a preliminary patch that dumps the trace, but also
> symbolizes the addresses. It's probably not terribly efficient - but I
> wanted to post it anyway to figure out if this is a good starting
> point or there are other ways of getting perf to report call graphs
> that are easy to parse in another program.
> 
>  -Arun

From a brief glance seems similar to the timehist patch I proposed. See:
http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00049.html
http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00047.html
http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00048.html

The last URL shows an example of the output (abbreviated for email;
unwind the continuation lines for a better display).

That essentially dumps each sample point with the address-to-symbol
conversions done. The output of that is then fed to homegrown commands
to visualize/process the data.

David

Re: [RFC] --dump-sym-trace

[Arun Sharma]

On Tue, Jan 25, 2011 at 6:29 PM, David Ahern <daahern@cisco.com> wrote:
> From a brief glance seems similar to the timehist patch I proposed. See:
> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00049.html
> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00047.html
> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00048.html

The output could be a bit more compact (eg: print some info once per
stack trace rather than once per frame). Also, it doesn't seem to
print the DSO name when symbol lookup fails?

Otherwise looks great. I'll drop the other patch.

 -Arun

Re: [RFC] --dump-sym-trace

[David Ahern]

On 01/28/11 14:18, Arun Sharma wrote:
> On Tue, Jan 25, 2011 at 6:29 PM, David Ahern <daahern@cisco.com> wrote:
>> From a brief glance seems similar to the timehist patch I proposed. See:
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00049.html
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00047.html
>> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00048.html
> 
> The output could be a bit more compact (eg: print some info once per
> stack trace rather than once per frame). Also, it doesn't seem to
> print the DSO name when symbol lookup fails?

I am certainly interested in ideas on how to improve the output.

That version was derived from a local patch; in our case I wanted a
simple format for the output. Essentially, the timehist output is a
'text' version of the samples, with timestamps and address conversions
where possible.

Arnaldo has started a new version of it wherein the wall clock is a new
event that can be sampled (e.g., perf top) or generated at given rate. I
spent time looking at the changes to perf command, but have been
sidetracked with other priorities.

David


> 
> Otherwise looks great. I'll drop the other patch.
> 
>  -Arun

Re: [RFC] --dump-sym-trace

[Arnaldo Carvalho de Melo]

Em Fri, Jan 28, 2011 at 02:41:37PM -0700, David Ahern escreveu:
> 
> 
> On 01/28/11 14:18, Arun Sharma wrote:
> > On Tue, Jan 25, 2011 at 6:29 PM, David Ahern <daahern@cisco.com> wrote:
> >> From a brief glance seems similar to the timehist patch I proposed. See:
> >> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00049.html
> >> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00047.html
> >> http://www.mail-archive.com/linux-perf-users@vger.kernel.org/msg00048.html
> > 
> > The output could be a bit more compact (eg: print some info once per
> > stack trace rather than once per frame). Also, it doesn't seem to
> > print the DSO name when symbol lookup fails?
> 
> I am certainly interested in ideas on how to improve the output.
> 
> That version was derived from a local patch; in our case I wanted a
> simple format for the output. Essentially, the timehist output is a
> 'text' version of the samples, with timestamps and address conversions
> where possible.
> 
> Arnaldo has started a new version of it wherein the wall clock is a new
> event that can be sampled (e.g., perf top) or generated at given rate. I
> spent time looking at the changes to perf command, but have been
> sidetracked with other priorities.

/me too

I have to get back to that, it is definetely a feature we need to have.

- Arnaldo

Re: [RFC] --dump-sym-trace

[Arun Sharma]

On Sat, Jan 29, 2011 at 12:50 PM, Arnaldo Carvalho de Melo
<acme@ghostprotocols.net> wrote:
> /me too
>
> I have to get back to that, it is definetely a feature we need to have.

There are a couple of more minor nits I found in David's patch:

* perf record --timehist doesn't seem to be doing anything. I used
perf record -T -a.
* Some of the printfs are missing checks along the lines of:

--- a/tools/perf/builtin-report.c
+++ b/tools/perf/builtin-report.c
@@ -228,6 +228,7 @@ static int perf_session__print_sample(struct
perf_session *session,
                free(syms);

        } else {
+               if (!data || !al || !al->thread || !al->sym ||
!al->map) return 0;
                printf(TIMEHIST_FMT,
                           tstr, data->cpu,
                           al->thread->comm, al->thread->pid, al->addr,

to avoid SIGSEGVs when the information in the sample is incomplete.

 -Arun

Re: [RFC] --dump-sym-trace

[David Ahern]

On 02/04/11 18:48, Arun Sharma wrote:
> On Sat, Jan 29, 2011 at 12:50 PM, Arnaldo Carvalho de Melo
> <acme@ghostprotocols.net> wrote:
>> /me too
>>
>> I have to get back to that, it is definetely a feature we need to have.
> 
> There are a couple of more minor nits I found in David's patch:
> 
> * perf record --timehist doesn't seem to be doing anything. I used
> perf record -T -a.

For record the the --timehist flag adds the timestamp and cpu to the IP
samples -- hidden attributes from a 'perf report' perspective unless you
add the --timehist flag on the report as well in which case the output
is completely different.

I take it your mileage varied from the above.

David



> * Some of the printfs are missing checks along the lines of:
> 
> --- a/tools/perf/builtin-report.c
> +++ b/tools/perf/builtin-report.c
> @@ -228,6 +228,7 @@ static int perf_session__print_sample(struct
> perf_session *session,
>                 free(syms);
> 
>         } else {
> +               if (!data || !al || !al->thread || !al->sym ||
> !al->map) return 0;
>                 printf(TIMEHIST_FMT,
>                            tstr, data->cpu,
>                            al->thread->comm, al->thread->pid, al->addr,
> 
> to avoid SIGSEGVs when the information in the sample is incomplete.
> 
>  -Arun

Re: [RFC] --dump-sym-trace

[Arun Sharma]

On Fri, Feb 4, 2011 at 6:38 PM, David Ahern <daahern@cisco.com> wrote:

> I take it your mileage varied from the above.

I can't reproduce the issue anymore and the code looks just fine. The
issue I had was:

perf record -a -T + perf report --timehist produced samples where:
perf record --timehist + perf report --timehist didn't.

 -Arun

Re: [RFC] --dump-sym-trace

[David Ahern]

On 02/14/11 17:00, Arun Sharma wrote:
> On Fri, Feb 4, 2011 at 6:38 PM, David Ahern <daahern@cisco.com> wrote:
> 
>> I take it your mileage varied from the above.
> 
> I can't reproduce the issue anymore and the code looks just fine. The
> issue I had was:
> 
> perf record -a -T + perf report --timehist produced samples where:
> perf record --timehist + perf report --timehist didn't.

You need the --timehist on both to work properly. If you add it to
report but not record then you are asking for information that was not
recorded. Something to be addressed for proper inclusion.

I've been wanting to use this time history option to record/analyze
syscall events lately. I'll see if I can spend some time on it this week.

David


> 
>  -Arun
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html