Re: [PATCH] trace-cmd: Add helper function to get the time stamp print format

[Steven Rostedt <rostedt@goodmis.org>]

Hi Tzvetomir,

I change the commit log for the actual reason. The trace-cmd report -t
wasn't working.

-- Steve

From 3a7d928b1b9d67eec840c6a868627e39fc7b1a73 Mon Sep 17 00:00:00 2001
From: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>
Date: Mon, 6 Jul 2020 18:14:04 +0300
Subject: [PATCH] trace-cmd: Fix trace-cmd report -t to show full timestamp

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@gmail.com

Fixes: 150d479b623a ("libtraceevent, perf tools: Changes in tep_print_event_* APIs")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 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 c1f840d5..f1ba7835 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.25.4