perf script: format regression due to libtraceevent
PATCH 1/1 perf script: format regression due to libtraceevent
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=120prev_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
--- tools/lib/traceevent/event-parse.c | 36 ------------------------------------ 1 file changed, 36 deletions(-)
tools/lib/traceevent/event-parse.c +0 -36
@@ -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); }
Signature · 1 line
1.7.10.1
Quoted 2 lines · David Ahern
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.
Quoted 81 lines
perf script -i
/tmp/perf.dataIn 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=120prev_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<[email protected]>--- tools/lib/traceevent/event-parse.c | 36 ------------------------------------ 1 file changed, 36 deletions(-)tools/lib/traceevent/event-parse.c +0
-36@@ -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); }
Quoted 13 lines · 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.dataIn 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
Quoted 8 lines
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