tracing: fully-qualified var-ref testcase

Hi Steve,

Here's the testcase for fully-qualified var references mentioned here [1].

While working on it, I realized that the printing of the fully-qualified references was wrong (because the testcases use that output to remove the trigger), so added the first patch.

It depends on Pengpeng Hou's patch:

[PATCH v2 1/2] tracing/hist: rebuild full_name on each hist_field_name() call

Thanks,

Tom

[1] https://lore.kernel.org/lkml/[email protected]/

Tom Zanussi (2):
tracing: Fix fully-qualified variable reference printing in histograms selftests/ftrace: Add test case for fully-qualified variable
references

 kernel/trace/trace_events_hist.c              | 15 +++++---
 .../trigger-fully-qualified-var-ref.tc        | 34 +++++++++++++++++++
 2 files changed, 44 insertions(+), 5 deletions(-)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-fully-qualified-var-ref.tc

2.43.0

The syntax for fully-qualified variable references in histograms is subsys.event.$var, which is parsed correctly, but not displayed correctly when printing a histogram spec. The current code puts the $ reference at the beginning of the fully-qualified variable name i.e. $subsys.event.var, which is incorrect.

Before:

trigger info: hist:keys=next_comm:vals=hitcount:wakeup_lat=common_timestamp.usecs-$sched.sched_wakeup.ts0: ...

After:

trigger info: hist:keys=next_comm:vals=hitcount:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0: ...

---
 kernel/trace/trace_events_hist.c | 15 ++++++++++-----
 1 file changed, 10 insertions(+), 5 deletions(-)

index b2b675c7d663..0dbbf6cca9bc 100644
@@ -1361,9 +1361,12 @@ static const char *hist_field_name(struct hist_field *field,
 		 field->flags & HIST_FIELD_FL_VAR_REF) {
 		if (field->system) {
 			static char full_name[MAX_FILTER_STR_VAL];
+			static char *fmt;
 			int len;
 
-			len = snprintf(full_name, sizeof(full_name), "%s.%s.%s",
+			fmt = field->flags & HIST_FIELD_FL_VAR_REF ? "%s.%s.$%s" : "%s.%s.%s";
+
+			len = snprintf(full_name, sizeof(full_name), fmt,
 				       field->system, field->event_name,
 				       field->name);
 			if (len >= sizeof(full_name))

@@ -1742,9 +1745,10 @@ static const char *get_hist_field_flags(struct hist_field *hist_field)
 
 static void expr_field_str(struct hist_field *field, char *expr)
 {
-	if (field->flags & HIST_FIELD_FL_VAR_REF)
-		strcat(expr, "$");
-	else if (field->flags & HIST_FIELD_FL_CONST) {
+	if (field->flags & HIST_FIELD_FL_VAR_REF) {
+		if (!field->system)
+			strcat(expr, "$");
+	} else if (field->flags & HIST_FIELD_FL_CONST) {
 		char str[HIST_CONST_DIGITS_MAX];
 
 		snprintf(str, HIST_CONST_DIGITS_MAX, "%llu", field->constant);

@@ -6156,7 +6160,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 	else if (field_name) {
 		if (hist_field->flags & HIST_FIELD_FL_VAR_REF ||
 		    hist_field->flags & HIST_FIELD_FL_ALIAS)
-			seq_putc(m, '$');
+			if (!hist_field->system)
+				seq_putc(m, '$');
 		seq_printf(m, "%s", field_name);
 	} else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
 		seq_puts(m, "common_timestamp");

2.43.0

This test adds a variable (ts0) to two events (sched_waking and sched_wakeup) and uses a fully-qualified variable reference to expicitly choose a particular one (sched_wakeup.$ts0) when calculating the wakeup latency.

---
 .../trigger-fully-qualified-var-ref.tc        | 34 +++++++++++++++++++
 1 file changed, 34 insertions(+)
 create mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-fully-qualified-var-ref.tc

new file mode 100644
index 000000000000..8d12cdd06f1d
@@ -0,0 +1,34 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: event trigger - test fully-qualified variable reference support
+# requires: set_event synthetic_events events/sched/sched_process_fork/hist ping:program
+
+fail() { #msg
+    echo $1
+    exit_fail
+}
+
+echo "Test fully-qualified variable reference support"
+
+echo 'wakeup_latency u64 lat; pid_t pid; int prio; char comm[16]' > synthetic_events
+echo 'hist:keys=comm:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_waking/trigger
+echo 'hist:keys=comm:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
+echo 'hist:keys=next_comm:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger
+echo 'hist:keys=pid,prio,comm:vals=lat:sort=pid,prio' > events/synthetic/wakeup_latency/trigger
+
+ping $LOCALHOST -c 3
+if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then
+    fail "Failed to create inter-event histogram"
+fi
+
+if ! grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then
+    fail "Failed to create histogram with fully-qualified variable reference"
+fi
+
+echo '!hist:keys=next_comm:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger
+
+if grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then
+    fail "Failed to remove histogram with fully-qualified variable reference"
+fi
+
+exit 0

2.43.0