From: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@xxxxxxxxx> The -t wasn't printing the full nanosecond time stamp as it is described in the man pages. Instead it was still printing just microsecond precision. Before the patch: # trace-cmd report -t kworker/5:1H-887 [005] 14943901.178049: sched_stat_runtime: comm=kworker/5:1H pid=887 runtime=13436 [ns] vruntime=1660916130854173 [ns] kworker/5:1H-887 [005] 14943901.178066: sched_switch: kworker/5:1H:887 [100] W ==> swapper/5:0 [120] sleep-25090 [002] 14943901.178089: sched_waking: comm=migration/2 pid=22 prio=0 target_cpu=002 sleep-25090 [002] 14943901.178091: sched_wakeup: migration/2:22 [0] success=1 CPU:002 sleep-25090 [002] 14943901.178092: sched_stat_runtime: comm=trace-cmd pid=25090 runtime=221204 [ns] vruntime=20995297524016 [ns] sleep-25090 [002] 14943901.178094: sched_switch: trace-cmd:25090 [120] R ==> migration/2:22 [0] migration/2-22 [002] 14943901.178097: sched_migrate_task: comm=trace-cmd pid=25090 prio=120 orig_cpu=2 dest_cpu=17 migration/2-22 [002] 14943901.178101: sched_wake_idle_without_ipi: cpu=17 migration/2-22 [002] 14943901.178103: sched_switch: migration/2:22 [0] S ==> swapper/2:0 [120] After the patch: # trace-cmd report -t kworker/5:1H-887 [005] 14943901.178048648 sched_stat_runtime: comm=kworker/5:1H pid=887 runtime=13436 [ns] vruntime=1660916130854173 [ns] kworker/5:1H-887 [005] 14943901.178065741 sched_switch: kworker/5:1H:887 [100] W ==> swapper/5:0 [120] sleep-25090 [002] 14943901.178088505 sched_waking: comm=migration/2 pid=22 prio=0 target_cpu=002 sleep-25090 [002] 14943901.178090827 sched_wakeup: migration/2:22 [0] success=1 CPU:002 sleep-25090 [002] 14943901.178091660 sched_stat_runtime: comm=trace-cmd pid=25090 runtime=221204 [ns] vruntime=20995297524016 [ns] sleep-25090 [002] 14943901.178093512 sched_switch: trace-cmd:25090 [120] R ==> migration/2:22 [0] migration/2-22 [002] 14943901.178097240 sched_migrate_task: comm=trace-cmd pid=25090 prio=120 orig_cpu=2 dest_cpu=17 migration/2-22 [002] 14943901.178101255 sched_wake_idle_without_ipi: cpu=17 migration/2-22 [002] 14943901.178103431 sched_switch: migration/2:22 [0] S ==> swapper/2:0 [120] Link: https://lore.kernel.org/linux-trace-devel/20200706151404.25603-1-tz.stoyanov@xxxxxxxxx Fixes: 150d479b623a ("libtraceevent, perf tools: Changes in tep_print_event_* APIs") Signed-off-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx> [ Finished the patch from Steven ] Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@xxxxxxxxx> --- tracecmd/trace-read.c | 31 ++++++++++++++++++++++++++++--- 1 file changed, 28 insertions(+), 3 deletions(-) diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c index c1f840d560f2..2ab89ab57c6e 100644 --- a/tracecmd/trace-read.c +++ b/tracecmd/trace-read.c @@ -141,13 +141,38 @@ static void print_event_name(struct trace_seq *s, struct tep_event *event) trace_seq_printf(s, "%.*s", 20 - len, spaces); } +enum time_fmt { + TIME_FMT_LAT = 1, + TIME_FMT_NORMAL = 2, +}; + +static const char *time_format(struct tracecmd_input *handle, enum time_fmt tf) +{ + struct tep_handle *tep = tracecmd_get_pevent(handle); + + switch (tf) { + case TIME_FMT_LAT: + if (latency_format) + return "%8.8s-%-5d %3d"; + return "%16s-%-5d [%03d]"; + default: + if (tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS) { + if (tep_test_flag(tep, TEP_NSEC_OUTPUT)) + return " %9.1d:"; + else + return " %6.1000d:"; + } else + return "%12d:"; + } +} + static void print_event(struct trace_seq *s, struct tracecmd_input *handle, struct tep_record *record) { struct tep_handle *tep = tracecmd_get_pevent(handle); struct tep_event *event; - const char *lfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]"; - const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:"; + const char *lfmt = time_format(handle, TIME_FMT_LAT); + const char *tfmt = time_format(handle, TIME_FMT_NORMAL); event = tep_find_event_by_record(tep, record); tep_print_event(tep, s, record, lfmt, TEP_PRINT_COMM, @@ -781,7 +806,7 @@ static void finish_wakeup(void) void trace_show_data(struct tracecmd_input *handle, struct tep_record *record) { tracecmd_show_data_func func = tracecmd_get_show_data_func(handle); - const char *tfmt = tracecmd_get_flags(handle) & TRACECMD_FL_IN_USECS ? " %6.1000d:" : "%12d:"; + const char *tfmt = time_format(handle, TIME_FMT_NORMAL); struct tep_handle *pevent; struct tep_event *event; struct trace_seq s; -- 2.26.2