[PATCH 0/5] trace-cmd: Triaging bugzillas and fixes

[PATCH 0/5] trace-cmd: Triaging bugzillas and fixes

[Steven Rostedt]

This includes the two updates Tzvetomir did, as well as fixes for
bugzillas: 207069, 205953, and 204703

Steven Rostedt (VMware) (3):
      trace-cmd: Explicitly state what trace-cmd report -f does
      tools lib traceevent: Let function symbols be used in operations
      trace-cmd: Print raw hex for flags when trace-cmd report -R

Tzvetomir Stoyanov (VMware) (2):
      trace-cmd: Fix trace-cmd report -t to show full timestamp
      tools lib traceveent: Fix kbuffer_start_of_data() to return the first record

----
 Documentation/trace-cmd-report.1.txt |  4 ++-
 lib/traceevent/event-parse.c         | 49 +++++++++++++++++++++++++++-
 lib/traceevent/kbuffer-parse.c       |  7 +++-
 tracecmd/trace-read.c                | 63 ++++++++++++++++++++++++++----------
 tracecmd/trace-usage.c               |  2 +-
 5 files changed, 104 insertions(+), 21 deletions(-)

[PATCH 1/5] trace-cmd: Fix trace-cmd report -t to show full timestamp

[Steven Rostedt]

From: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>

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>
[ Finished the patch from Steven ]
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 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

[PATCH 2/5] tools lib traceveent: Fix kbuffer_start_of_data() to return the first record

[Steven Rostedt]

From: "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com>

The first record in a ring buffer page may not allways be at the
beginning of the page. There could be time-extends injected before it.
In this case kbuffer_start_of_data() will not return the first record,
as expected. Additional field "start" is added in kbuffer struct, to hold
the offset of the first record from the page and kbuffer_start_of_data()
is modified to use it.

Link: https://lore.kernel.org/linux-trace-devel/20200706154714.27566-1-tz.stoyanov@gmail.com

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
[ Finished the patch from Steven ]
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 lib/traceevent/kbuffer-parse.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

diff --git a/lib/traceevent/kbuffer-parse.c b/lib/traceevent/kbuffer-parse.c
index 2c5f00a9e786..844db976b38c 100644
--- a/lib/traceevent/kbuffer-parse.c
+++ b/lib/traceevent/kbuffer-parse.c
@@ -35,6 +35,7 @@ enum {
  * @next		- offset from @data to the start of next event
  * @size		- The size of data on @data
  * @start		- The offset from @subbuffer where @data lives
+ * @first		- The offset from @subbuffer where the first non time stamp event lives
  *
  * @read_4		- Function to read 4 raw bytes (may swap)
  * @read_8		- Function to read 8 raw bytes (may swap)
@@ -51,6 +52,7 @@ struct kbuffer {
 	unsigned int		next;
 	unsigned int		size;
 	unsigned int		start;
+	unsigned int		first;
 
 	unsigned int (*read_4)(void *ptr);
 	unsigned long long (*read_8)(void *ptr);
@@ -546,6 +548,9 @@ int kbuffer_load_subbuffer(struct kbuffer *kbuf, void *subbuffer)
 
 	next_event(kbuf);
 
+	/* save the first record from the page */
+	kbuf->first = kbuf->curr;
+
 	return 0;
 }
 
@@ -755,7 +760,7 @@ void kbuffer_set_old_format(struct kbuffer *kbuf)
  */
 int kbuffer_start_of_data(struct kbuffer *kbuf)
 {
-	return kbuf->start;
+	return kbuf->first + kbuf->start;
 }
 
 /**
-- 
2.26.2

[PATCH 3/5] trace-cmd: Explicitly state what trace-cmd report -f does

[Steven Rostedt]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The current man page and usage of trace-cmd report is confusing when it
comes to the -f option. This option will list all the functions in the
trace.dat file that have a address to name mapping. As it currently is
stated, it may confuse users in thinking that it will list the functions
that have been traced. But this is not the case.

Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=207069
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 Documentation/trace-cmd-report.1.txt | 4 +++-
 tracecmd/trace-usage.c               | 2 +-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/Documentation/trace-cmd-report.1.txt b/Documentation/trace-cmd-report.1.txt
index 87f4d7a1b046..66e96da7c3fa 100644
--- a/Documentation/trace-cmd-report.1.txt
+++ b/Documentation/trace-cmd-report.1.txt
@@ -27,7 +27,9 @@ OPTIONS
     versa.
 
 *-f*::
-    This outputs the list of functions that have been recorded in the file.
+    This outputs the list of all functions that have been mapped in the trace.dat file.
+    Note, this list may contain functions that may not appear in the trace, as
+    it is the list of mappings to translate function addresses into function names.
 
 *-P*::
     This outputs the list of "trace_printk()" data. The raw trace data points
diff --git a/tracecmd/trace-usage.c b/tracecmd/trace-usage.c
index ada44c68eb00..85c635125617 100644
--- a/tracecmd/trace-usage.c
+++ b/tracecmd/trace-usage.c
@@ -191,7 +191,7 @@ static struct usage_help usage_help[] = {
 		"           [-G]\n"
 		"          -i input file [default trace.dat]\n"
 		"          -e show file endianess\n"
-		"          -f show function list\n"
+		"          -f show function mapping list\n"
 		"          -P show printk list\n"
 		"          -E show event files stored\n"
 		"          -F filter to filter output on\n"
-- 
2.26.2

[PATCH 4/5] tools lib traceevent: Let function symbols be used in operations

[Steven Rostedt]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

The preemptirq events records only 32 bits for the locations of where the
events occur. It records the offset from _stext to do so. But the
libtraceevent does not handle function names in operations to add offsets
to.

Have the eval_num_arg() check if the value found is zero and then check if
it is a string. If it is a string value, check if that string matches any
function. If it does, then evaluate the function symbol and replace the
value with the actual number to complete the calculation.

Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=205953
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 lib/traceevent/event-parse.c | 49 +++++++++++++++++++++++++++++++++++-
 1 file changed, 48 insertions(+), 1 deletion(-)

diff --git a/lib/traceevent/event-parse.c b/lib/traceevent/event-parse.c
index ee16be96697b..77c3249220d3 100644
--- a/lib/traceevent/event-parse.c
+++ b/lib/traceevent/event-parse.c
@@ -3649,6 +3649,50 @@ tep_find_event_by_name(struct tep_handle *tep,
 	return event;
 }
 
+static unsigned long long test_for_symbol(struct tep_handle *tep,
+					  struct tep_print_arg *arg)
+{
+	unsigned long long val = 0;
+	struct func_list *item = tep->funclist;
+	char *func;
+	int i;
+
+	if (isdigit(arg->atom.atom[0]))
+		return 0;
+
+	/* Linear search but only happens once (see after the loop) */
+	for (i = 0; i < (int)tep->func_count; i++) {
+		unsigned long long addr;
+		const char *name;
+
+		if (tep->func_map) {
+			addr = tep->func_map[i].addr;
+			name = tep->func_map[i].func;
+		} else if (item) {
+			addr = item->addr;
+			name = item->func;
+			item = item->next;
+		} else
+			break;
+
+		if (strcmp(arg->atom.atom, name) == 0) {
+			val = addr;
+			break;
+		}
+	}
+
+	/*
+	 * This modifies the arg to hardcode the value
+	 * and will not loop again.
+	 */
+	func = realloc(arg->atom.atom, 32);
+	if (func) {
+		snprintf(func, 32, "%lld", val);
+		arg->atom.atom = func;
+	}
+	return val;
+}
+
 static unsigned long long
 eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg *arg)
 {
@@ -3665,7 +3709,10 @@ eval_num_arg(void *data, int size, struct tep_event *event, struct tep_print_arg
 		/* ?? */
 		return 0;
 	case TEP_PRINT_ATOM:
-		return strtoull(arg->atom.atom, NULL, 0);
+		val = strtoull(arg->atom.atom, NULL, 0);
+		if (!val)
+			val = test_for_symbol(tep, arg);
+		return val;
 	case TEP_PRINT_FIELD:
 		if (!arg->field.field) {
 			arg->field.field = tep_find_any_field(event, arg->field.name);
-- 
2.26.2

[PATCH 5/5] trace-cmd: Print raw hex for flags when trace-cmd report -R

[Steven Rostedt]

From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>

When the '-R' raw flag is specified on the command line for trace-cmd
report, show the latency flags as a raw hex number. This is useful for
seeing exactly what was saved in the flags field.

Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=204703
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
---
 tracecmd/trace-read.c | 32 ++++++++++++++++++--------------
 1 file changed, 18 insertions(+), 14 deletions(-)

diff --git a/tracecmd/trace-read.c b/tracecmd/trace-read.c
index 2ab89ab57c6e..e18110745d37 100644
--- a/tracecmd/trace-read.c
+++ b/tracecmd/trace-read.c
@@ -101,6 +101,7 @@ static int no_softirqs;
 static int tsdiff;
 
 static int latency_format;
+static bool raw_format;
 static const char *format_type = TEP_PRINT_INFO;
 
 static struct tep_format_field *wakeup_task;
@@ -807,6 +808,7 @@ 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 = time_format(handle, TIME_FMT_NORMAL);
+	const char *cfmt = latency_format ? "%8.8s-%-5d %3d" : "%16s-%-5d [%03d]";
 	struct tep_handle *pevent;
 	struct tep_event *event;
 	struct trace_seq s;
@@ -847,17 +849,20 @@ void trace_show_data(struct tracecmd_input *handle, struct tep_record *record)
 		}
 	}
 
-	if (latency_format)
-		tep_print_event(pevent, &s, record, "%8.8s-%-5d %3d%s",
-				TEP_PRINT_COMM,
-				TEP_PRINT_PID,
-				TEP_PRINT_CPU,
-				TEP_PRINT_LATENCY);
-	else
-		tep_print_event(pevent, &s, record, "%16s-%-5d [%03d]",
-				TEP_PRINT_COMM,
-				TEP_PRINT_PID,
-				TEP_PRINT_CPU);
+	tep_print_event(pevent, &s, record, cfmt,
+			TEP_PRINT_COMM,
+			TEP_PRINT_PID,
+			TEP_PRINT_CPU);
+
+	if (latency_format) {
+		if (raw_format)
+			trace_seq_printf(&s, "-0x%x",
+					 tep_data_flags(pevent, record));
+		else
+			tep_print_event(pevent, &s, record, "%s",
+					TEP_PRINT_LATENCY);
+	}
+
 	tep_print_event(pevent, &s, record, tfmt, TEP_PRINT_TIME);
 
 	if (tsdiff) {
@@ -1506,7 +1511,6 @@ void trace_report (int argc, char **argv)
 	int nanosec = 0;
 	int no_date = 0;
 	int global = 0;
-	int raw = 0;
 	int neg = 0;
 	int ret = 0;
 	int check_event_parsing = 0;
@@ -1618,7 +1622,7 @@ void trace_report (int argc, char **argv)
 			global = 1;
 			break;
 		case 'R':
-			raw = 1;
+			raw_format = true;
 			break;
 		case 'r':
 			*raw_ptr = malloc(sizeof(struct event_str));
@@ -1769,7 +1773,7 @@ void trace_report (int argc, char **argv)
 		if (nanosec)
 			tep_set_flag(pevent, TEP_NSEC_OUTPUT);
 
-		if (raw)
+		if (raw_format)
 			format_type = TEP_PRINT_INFO_RAW;
 
 		if (test_filters_mode)
-- 
2.26.2