[PATCH] perf script: format regression due to libtraceevent

[PATCH] perf script: format regression due to libtraceevent

[David Ahern]

Consider the commands:
perf record -e sched:sched_switch -fo /tmp/perf-3.5.data  -a -- sleep 1
perf script -i /tmp/perf.data

In v3.4 the output has the form (lines wrapped)
            perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

In 3.5 that same line has become:
           perf 29214 [005] 821043.582596: sched_switch:
            <...>-29214 [005]     0.000000000: sched_switch:
         prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

Note the duplicates in the output -- pid, cpu, event name. With
this patch the v3.4 output is restored:
           perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

Signed-off-by: David Ahern <dsahern@gmail.com>
---
 tools/lib/traceevent/event-parse.c |   36 ------------------------------------
 1 file changed, 36 deletions(-)

diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
index 5548282..261107a 100644
--- a/tools/lib/traceevent/event-parse.c
+++ b/tools/lib/traceevent/event-parse.c
@@ -4027,20 +4027,9 @@ void pevent_event_info(struct trace_seq *s, struct event_format *event,
 void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 			struct pevent_record *record)
 {
-	static char *spaces = "                    "; /* 20 spaces */
 	struct event_format *event;
-	unsigned long secs;
-	unsigned long usecs;
-	unsigned long nsecs;
-	const char *comm;
 	void *data = record->data;
 	int type;
-	int pid;
-	int len;
-	int p;
-
-	secs = record->ts / NSECS_PER_SEC;
-	nsecs = record->ts - secs * NSECS_PER_SEC;
 
 	if (record->size < 0) {
 		do_warning("ug! negative record size %d", record->size);
@@ -4055,31 +4044,6 @@ void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
 		return;
 	}
 
-	pid = parse_common_pid(pevent, data);
-	comm = find_cmdline(pevent, pid);
-
-	if (pevent->latency_format) {
-		trace_seq_printf(s, "%8.8s-%-5d %3d",
-		       comm, pid, record->cpu);
-		pevent_data_lat_fmt(pevent, s, record);
-	} else
-		trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
-
-	if (pevent->flags & PEVENT_NSEC_OUTPUT) {
-		usecs = nsecs;
-		p = 9;
-	} else {
-		usecs = (nsecs + 500) / NSECS_PER_USEC;
-		p = 6;
-	}
-
-	trace_seq_printf(s, " %5lu.%0*lu: %s: ", secs, p, usecs, event->name);
-
-	/* Space out the event names evenly. */
-	len = strlen(event->name);
-	if (len < 20)
-		trace_seq_printf(s, "%.*s", 20 - len, spaces);
-
 	pevent_event_info(s, event, record);
 }
 
-- 
1.7.10.1

Re: [PATCH] perf script: format regression due to libtraceevent

[David Ahern]

On 6/14/12 9:48 AM, David Ahern wrote:
> Consider the commands:
> perf record -e sched:sched_switch -fo /tmp/perf-3.5.data  -a -- sleep 1

grr..... copied the wrong filename above when creating the commit log. 
/tmp/perf.data was used for both the record and the script commands.


> perf script -i /tmp/perf.data
>
> In v3.4 the output has the form (lines wrapped)
>              perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==>  next_comm=swapper/5 next_pid=0 next_prio=120
>
> In 3.5 that same line has become:
>             perf 29214 [005] 821043.582596: sched_switch:
>              <...>-29214 [005]     0.000000000: sched_switch:
>           prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==>  next_comm=swapper/5 next_pid=0 next_prio=120
>
> Note the duplicates in the output -- pid, cpu, event name. With
> this patch the v3.4 output is restored:
>             perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==>  next_comm=swapper/5 next_pid=0 next_prio=120
>
> Signed-off-by: David Ahern<dsahern@gmail.com>
> ---
>   tools/lib/traceevent/event-parse.c |   36 ------------------------------------
>   1 file changed, 36 deletions(-)
>
> diff --git a/tools/lib/traceevent/event-parse.c b/tools/lib/traceevent/event-parse.c
> index 5548282..261107a 100644
> --- a/tools/lib/traceevent/event-parse.c
> +++ b/tools/lib/traceevent/event-parse.c
> @@ -4027,20 +4027,9 @@ void pevent_event_info(struct trace_seq *s, struct event_format *event,
>   void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
>   			struct pevent_record *record)
>   {
> -	static char *spaces = "                    "; /* 20 spaces */
>   	struct event_format *event;
> -	unsigned long secs;
> -	unsigned long usecs;
> -	unsigned long nsecs;
> -	const char *comm;
>   	void *data = record->data;
>   	int type;
> -	int pid;
> -	int len;
> -	int p;
> -
> -	secs = record->ts / NSECS_PER_SEC;
> -	nsecs = record->ts - secs * NSECS_PER_SEC;
>
>   	if (record->size<  0) {
>   		do_warning("ug! negative record size %d", record->size);
> @@ -4055,31 +4044,6 @@ void pevent_print_event(struct pevent *pevent, struct trace_seq *s,
>   		return;
>   	}
>
> -	pid = parse_common_pid(pevent, data);
> -	comm = find_cmdline(pevent, pid);
> -
> -	if (pevent->latency_format) {
> -		trace_seq_printf(s, "%8.8s-%-5d %3d",
> -		       comm, pid, record->cpu);
> -		pevent_data_lat_fmt(pevent, s, record);
> -	} else
> -		trace_seq_printf(s, "%16s-%-5d [%03d]", comm, pid, record->cpu);
> -
> -	if (pevent->flags&  PEVENT_NSEC_OUTPUT) {
> -		usecs = nsecs;
> -		p = 9;
> -	} else {
> -		usecs = (nsecs + 500) / NSECS_PER_USEC;
> -		p = 6;
> -	}
> -
> -	trace_seq_printf(s, " %5lu.%0*lu: %s: ", secs, p, usecs, event->name);
> -
> -	/* Space out the event names evenly. */
> -	len = strlen(event->name);
> -	if (len<  20)
> -		trace_seq_printf(s, "%.*s", 20 - len, spaces);
> -
>   	pevent_event_info(s, event, record);
>   }
>

Re: [PATCH] perf script: format regression due to libtraceevent

[Steven Rostedt]

On Thu, 2012-06-14 at 09:48 -0600, David Ahern wrote:
> Consider the commands:
> perf record -e sched:sched_switch -fo /tmp/perf-3.5.data  -a -- sleep 1
> perf script -i /tmp/perf.data
> 
> In v3.4 the output has the form (lines wrapped)
>             perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 
> In 3.5 that same line has become:
>            perf 29214 [005] 821043.582596: sched_switch:
>             <...>-29214 [005]     0.000000000: sched_switch:
>          prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 
> Note the duplicates in the output -- pid, cpu, event name. With
> this patch the v3.4 output is restored:
>            perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 

This patch breaks trace-cmd (as well as the API). I recommend adding
another function that just does what you want and call that instead.

-- Steve

[PATCH] perf script: format regression due to libtraceevent

[David Ahern]

Consider the commands:
perf record -e sched:sched_switch -fo /tmp/perf.data  -a -- sleep 1
perf script -i /tmp/perf.data

In v3.4 the output has the form (lines wrapped here)
            perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

In 3.5 that same line has become:
           perf 29214 [005] 821043.582596: sched_switch:
            <...>-29214 [005]     0.000000000: sched_switch:
         prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

Note the duplicates in the output -- pid, cpu, event name. With
this patch the v3.4 output is restored:
           perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

CC: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Signed-off-by: David Ahern <dsahern@gmail.com>
---
 tools/perf/util/trace-event-parse.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
index 134eb3a..1043bf5d 100644
--- a/tools/perf/util/trace-event-parse.c
+++ b/tools/perf/util/trace-event-parse.c
@@ -198,7 +198,7 @@ void print_trace_event(int cpu, void *data, int size)
 	record.data = data;
 
 	trace_seq_init(&s);
-	pevent_print_event(pevent, &s, &record);
+	pevent_event_info(&s, event, &record);
 	trace_seq_do_printf(&s);
 	printf("\n");
 }
-- 
1.7.10.1

[PATCH] perf script: format regression due to libtraceevent

[David Ahern]

Consider the commands:
    perf record -e sched:sched_switch -fo /tmp/perf.data  -a -- sleep 1
    perf script -i /tmp/perf.data

In v3.4 the output has the form (lines wrapped here)
    perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

In 3.5 that same line has become:
    perf 29214 [005] 821043.582596: sched_switch:
<...>-29214 [005]     0.000000000: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

Note the duplicates in the output -- pid, cpu, event name. With
this patch the v3.4 output is restored:
    perf 29214 [005] 821043.582596: sched_switch:
prev_comm=perf prev_pid=29214 prev_prio=120
prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120

v3:
Remove that pesky newline too. Output now matches v3.4 (pre-libtracevent).

v2:
Change print_trace_event function local to perf per Steve's comments.

CC: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Namhyung Kim <namhyung@gmail.com>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Stephane Eranian <eranian@google.com>
Signed-off-by: David Ahern <dsahern@gmail.com>
---
 tools/perf/util/trace-event-parse.c |    3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
index df2fddb..5dd3b5e 100644
--- a/tools/perf/util/trace-event-parse.c
+++ b/tools/perf/util/trace-event-parse.c
@@ -198,9 +198,8 @@ void print_trace_event(int cpu, void *data, int size)
 	record.data = data;
 
 	trace_seq_init(&s);
-	pevent_print_event(pevent, &s, &record);
+	pevent_event_info(&s, event, &record);
 	trace_seq_do_printf(&s);
-	printf("\n");
 }
 
 void print_event(int cpu, void *data, int size, unsigned long long nsecs,
-- 
1.7.10.1

Re: [PATCH] perf script: format regression due to libtraceevent

[Steven Rostedt]

On Thu, 2012-06-14 at 12:36 -0600, David Ahern wrote:
> Consider the commands:
>     perf record -e sched:sched_switch -fo /tmp/perf.data  -a -- sleep 1
>     perf script -i /tmp/perf.data
> 
> In v3.4 the output has the form (lines wrapped here)
>     perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 
> In 3.5 that same line has become:
>     perf 29214 [005] 821043.582596: sched_switch:
> <...>-29214 [005]     0.000000000: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 
> Note the duplicates in the output -- pid, cpu, event name. With
> this patch the v3.4 output is restored:
>     perf 29214 [005] 821043.582596: sched_switch:
> prev_comm=perf prev_pid=29214 prev_prio=120
> prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120
> 
> v3:
> Remove that pesky newline too. Output now matches v3.4 (pre-libtracevent).
> 
> v2:
> Change print_trace_event function local to perf per Steve's comments.
> 
> CC: Arnaldo Carvalho de Melo <acme@redhat.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>

Acked-by: Steven Rostedt <rostedt@goodmis.org>

-- Steve

> Cc: Namhyung Kim <namhyung@gmail.com>
> Cc: Frederic Weisbecker <fweisbec@gmail.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Stephane Eranian <eranian@google.com>
> Signed-off-by: David Ahern <dsahern@gmail.com>
> ---
>  tools/perf/util/trace-event-parse.c |    3 +--
>  1 file changed, 1 insertion(+), 2 deletions(-)
> 
> diff --git a/tools/perf/util/trace-event-parse.c b/tools/perf/util/trace-event-parse.c
> index df2fddb..5dd3b5e 100644
> --- a/tools/perf/util/trace-event-parse.c
> +++ b/tools/perf/util/trace-event-parse.c
> @@ -198,9 +198,8 @@ void print_trace_event(int cpu, void *data, int size)
>  	record.data = data;
>  
>  	trace_seq_init(&s);
> -	pevent_print_event(pevent, &s, &record);
> +	pevent_event_info(&s, event, &record);
>  	trace_seq_do_printf(&s);
> -	printf("\n");
>  }
>  
>  void print_event(int cpu, void *data, int size, unsigned long long nsecs,