tracing: A few inter-event bugfixes

PATCH In review Tom Zanussi 3 participants 17 messages Mar 28, 2018 – Apr 12, 2018 Tracing

lore

Share & tools

lore

Tom Zanussi

author

2018-03-28 20:10 UTC #0 lore raw

cover tracing: A few inter-event bugfixes

Hi Steven,

Here are a few bugfixes that should be applied on top of the 'Inter-event (e.g. latency) support v9' patchset.

The first two are things introduced by the refactoring of the last version, the third I noticed when adding further actions for a future add-on, and the last was prompted by a patch for a similar problem posted this morning by Arnd Bergmann.

Thanks,

Tom

The following changes since commit 80765597bc587feae8dbc8ce97a0f32e12a6e625:

tracing: Rewrite filter logic to be simpler and faster (2018-03-14 12:35:39 -0400)

are available in the git repository at:

https://github.com/tzanussi/linux-trace-inter-event.git tzanussi/inter-event-update1
https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-update1

Tom Zanussi (4):
tracing: Fix display of hist trigger expressions containing timestamps
tracing: Don't add flag strings when displaying variable references
tracing: Add action comparisons when testing matching hist triggers
tracing: Make sure variable string fields are NULL-terminated

 kernel/trace/trace_events_hist.c | 75 +++++++++++++++++++++++++++++++---------
 1 file changed, 58 insertions(+), 17 deletions(-)

Signature · 1 line

1.9.3

Tom Zanussi

author

2018-03-28 20:10 UTC #1 lore raw

PATCH 1/4 tracing: Fix display of hist trigger expressions containing timestamps

When displaying hist triggers, variable references that have the timestamp field flag set are erroneously displayed as common_timestamp rather than the variable reference. Additionally, timestamp expressions are displayed in the same way. Fix this by forcing the timestamp flag handling to follow variable reference and expression handling.

Before:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs:...

After:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0.usecs:...

Signed-off-by Tom Zanussi <[email protected]>

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

kernel/trace/trace_events_hist.c +5 ~~-14~~

index 4f02764..fb81447 100644
@@ -1686,8 +1686,6 @@ static const char *hist_field_name(struct hist_field *field,
 	else if (field->flags & HIST_FIELD_FL_LOG2 ||
 		 field->flags & HIST_FIELD_FL_ALIAS)
 		field_name = hist_field_name(field->operands[0], ++level);
-	else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
-		field_name = "common_timestamp";
 	else if (field->flags & HIST_FIELD_FL_CPU)
 		field_name = "cpu";
 	else if (field->flags & HIST_FIELD_FL_EXPR ||

@@ -1703,7 +1701,8 @@ static const char *hist_field_name(struct hist_field *field,
 			field_name = full_name;
 		} else
 			field_name = field->name;
-	}
+	} else if (field->flags & HIST_FIELD_FL_TIMESTAMP)
+		field_name = "common_timestamp";
 
 	if (field_name == NULL)
 		field_name = "";

@@ -4857,23 +4856,15 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 	if (hist_field->var.name)
 		seq_printf(m, "%s=", hist_field->var.name);
 
-	if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
-		seq_puts(m, "common_timestamp");
-	else if (hist_field->flags & HIST_FIELD_FL_CPU)
+	if (hist_field->flags & HIST_FIELD_FL_CPU)
 		seq_puts(m, "cpu");
 	else if (field_name) {
 		if (hist_field->flags & HIST_FIELD_FL_VAR_REF ||
 		    hist_field->flags & HIST_FIELD_FL_ALIAS)
 			seq_putc(m, '$');
 		seq_printf(m, "%s", field_name);
-	}
-
-	if (hist_field->flags) {
-		const char *flags_str = get_hist_field_flags(hist_field);
-
-		if (flags_str)
-			seq_printf(m, ".%s", flags_str);
-	}
+	} else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
+		seq_puts(m, "common_timestamp");
 }
 
 static int event_hist_trigger_print(struct seq_file *m,

Signature · 1 line

1.9.3

Tom Zanussi

author

2018-03-28 20:10 UTC #2 lore raw

PATCH 2/4 tracing: Don't add flag strings when displaying variable references

In reply to Tom Zanussi

Variable references should never have flags appended when displayed - prevent that from happening.

Before:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0.usecs:...

After:

hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:...

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

kernel/trace/trace_events_hist.c +1 -1

index fb81447..468e43f 100644
@@ -2052,7 +2052,7 @@ static void expr_field_str(struct hist_field *field, char *expr)
 
 	strcat(expr, hist_field_name(field, 0));
 
-	if (field->flags) {
+	if (field->flags && !(field->flags & HIST_FIELD_FL_VAR_REF)) {
 		const char *flags_str = get_hist_field_flags(field);
 
 		if (flags_str) {

Signature · 1 line

1.9.3

Tom Zanussi

author

2018-03-28 20:10 UTC #3 lore raw

PATCH 3/4 tracing: Add action comparisons when testing matching hist triggers

In reply to Tom Zanussi

Actions also need to be considered when checking for matching triggers
- triggers differing only by action should be allowed, but currently aren't because the matching check ignores the action and erroneously returns -EEXIST.

Add and call an actions_match() function to address that.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 50 ++++++++++++++++++++++++++++++++++++++++
 1 file changed, 50 insertions(+)

kernel/trace/trace_events_hist.c +50 -0

index 468e43f..ae84470 100644
@@ -4363,6 +4363,53 @@ static void print_onmatch_spec(struct seq_file *m,
 	seq_puts(m, ")");
 }
 
+static bool actions_match(struct hist_trigger_data *hist_data,
+			  struct hist_trigger_data *hist_data_test)
+{
+	unsigned int i, j;
+
+	if (hist_data->n_actions != hist_data_test->n_actions)
+		return false;
+
+	for (i = 0; i < hist_data->n_actions; i++) {
+		struct action_data *data = hist_data->actions[i];
+		struct action_data *data_test = hist_data_test->actions[i];
+
+		if (data->fn != data_test->fn)
+			return false;
+
+		if (data->n_params != data_test->n_params)
+			return false;
+
+		for (j = 0; j < data->n_params; j++) {
+			if (strcmp(data->params[j], data_test->params[j]) != 0)
+				return false;
+		}
+
+		if (data->fn == action_trace) {
+			if (strcmp(data->onmatch.synth_event_name,
+				   data_test->onmatch.synth_event_name) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event_system,
+				   data_test->onmatch.match_event_system) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event,
+				   data_test->onmatch.match_event) != 0)
+				return false;
+		} else if (data->fn == onmax_save) {
+			if (strcmp(data->onmax.var_str,
+				   data_test->onmax.var_str) != 0)
+				return false;
+			if (strcmp(data->onmax.fn_name,
+				   data_test->onmax.fn_name) != 0)
+				return false;
+		}
+	}
+
+	return true;
+}
+
+
 static void print_actions_spec(struct seq_file *m,
 			       struct hist_trigger_data *hist_data)
 {

@@ -5173,6 +5220,9 @@ static bool hist_trigger_match(struct event_trigger_data *data,
 	    (strcmp(data->filter_str, data_test->filter_str) != 0))
 		return false;
 
+	if (!actions_match(hist_data, hist_data_test))
+		return false;
+
 	return true;
 }

Signature · 1 line

1.9.3

Tom Zanussi

author

2018-03-28 20:10 UTC #15 lore raw

PATCH 4/4 tracing: Make sure variable string fields are NULL-terminated

In reply to Tom Zanussi

The strncpy() currently being used for variable string fields can result in a lack of termination if the string length is equal to the field size. Use the safer strscpy() instead, which will guarantee termination.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/trace/trace_events_hist.c +2 -2

index ae84470..2751a0f 100644
@@ -669,7 +669,7 @@ static notrace void trace_event_raw_event_synth(void *__data,
 			char *str_val = (char *)(long)var_ref_vals[var_ref_idx + i];
 			char *str_field = (char *)&entry->fields[n_u64];
 
-			strncpy(str_field, str_val, STR_VAR_LEN_MAX);
+			strscpy(str_field, str_val, STR_VAR_LEN_MAX);
 			n_u64 += STR_VAR_LEN_MAX / sizeof(u64);
 		} else {
 			entry->fields[n_u64] = var_ref_vals[var_ref_idx + i];

@@ -3090,7 +3090,7 @@ static inline void __update_field_vars(struct tracing_map_elt *elt,
 			char *str = elt_data->field_var_str[j++];
 			char *val_str = (char *)(uintptr_t)var_val;
 
-			strncpy(str, val_str, STR_VAR_LEN_MAX);
+			strscpy(str, val_str, STR_VAR_LEN_MAX);
 			var_val = (u64)(uintptr_t)str;
 		}
 		tracing_map_set_var(elt, var_idx, var_val);

Signature · 1 line

1.9.3

Masami Hiramatsu

maintainer

2018-04-02 15:10 UTC #4 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

In reply to Tom Zanussi

Quoted 4 lines · On Wed, 28 Mar 2018 15:10:55 -0500 Tom Zanussi <[email protected]>…

Actions also need to be considered when checking for matching triggers
- triggers differing only by action should be allowed, but currently aren't because the matching check ignores the action and erroneously returns -EEXIST.

Hi Tom,

Could you show us the bad/good examples (maybe different onmatch() actions)? And if it is real bugfix, I would like to add a ftracetest testcase for this fix.

Thank you,

Quoted 79 lines

Add and call an actions_match() function to address that.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 50 ++++++++++++++++++++++++++++++++++++++++
 1 file changed, 50 insertions(+)

kernel/trace/trace_events_hist.c +50 -0

index 468e43f..ae84470 100644
@@ -4363,6 +4363,53 @@ static void print_onmatch_spec(struct seq_file *m,
 	seq_puts(m, ")");
 }
 
+static bool actions_match(struct hist_trigger_data *hist_data,
+			  struct hist_trigger_data *hist_data_test)
+{
+	unsigned int i, j;
+
+	if (hist_data->n_actions != hist_data_test->n_actions)
+		return false;
+
+	for (i = 0; i < hist_data->n_actions; i++) {
+		struct action_data *data = hist_data->actions[i];
+		struct action_data *data_test = hist_data_test->actions[i];
+
+		if (data->fn != data_test->fn)
+			return false;
+
+		if (data->n_params != data_test->n_params)
+			return false;
+
+		for (j = 0; j < data->n_params; j++) {
+			if (strcmp(data->params[j], data_test->params[j]) != 0)
+				return false;
+		}
+
+		if (data->fn == action_trace) {
+			if (strcmp(data->onmatch.synth_event_name,
+				   data_test->onmatch.synth_event_name) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event_system,
+				   data_test->onmatch.match_event_system) != 0)
+				return false;
+			if (strcmp(data->onmatch.match_event,
+				   data_test->onmatch.match_event) != 0)
+				return false;
+		} else if (data->fn == onmax_save) {
+			if (strcmp(data->onmax.var_str,
+				   data_test->onmax.var_str) != 0)
+				return false;
+			if (strcmp(data->onmax.fn_name,
+				   data_test->onmax.fn_name) != 0)
+				return false;
+		}
+	}
+
+	return true;
+}
+
+
 static void print_actions_spec(struct seq_file *m,
 			       struct hist_trigger_data *hist_data)
 {

@@ -5173,6 +5220,9 @@ static bool hist_trigger_match(struct event_trigger_data *data,
 	    (strcmp(data->filter_str, data_test->filter_str) != 0))
 		return false;
 
+	if (!actions_match(hist_data, hist_data_test))
+		return false;
+
 	return true;
 }

Signature · 1 line

1.9.3

Signature · 1 line

Masami Hiramatsu <[email protected]>

Steven Rostedt

maintainer

2018-04-02 15:26 UTC #16 lore raw

In reply to Tom Zanussi

Quoted 4 lines · On Wed, 28 Mar 2018 15:10:52 -0500 Tom Zanussi <[email protected]>…

Hi Steven,
Here are a few bugfixes that should be applied on top of the 'Inter-event (e.g. latency) support v9' patchset.

Thanks, I pulled them in and will send them out to git after testing has succeeded.

-- Steve

Quoted 28 lines

The first two are things introduced by the refactoring of the last version, the third I noticed when adding further actions for a future add-on, and the last was prompted by a patch for a similar problem posted this morning by Arnd Bergmann.
Thanks,
Tom
The following changes since commit 80765597bc587feae8dbc8ce97a0f32e12a6e625:
tracing: Rewrite filter logic to be simpler and faster (2018-03-14 12:35:39 -0400)
are available in the git repository at:
https://github.com/tzanussi/linux-trace-inter-event.git tzanussi/inter-event-update1
https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-update1
Tom Zanussi (4):
tracing: Fix display of hist trigger expressions containing timestamps
tracing: Don't add flag strings when displaying variable references
tracing: Add action comparisons when testing matching hist triggers
tracing: Make sure variable string fields are NULL-terminated
 kernel/trace/trace_events_hist.c | 75 +++++++++++++++++++++++++++++++---------
 1 file changed, 58 insertions(+), 17 deletions(-)

Tom Zanussi

author

2018-04-02 17:09 UTC #5 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

In reply to Masami Hiramatsu

Hi Masami,

Quoted 8 lines · Masami Hiramatsu

Quoted 4 lines · On Wed, 28 Mar 2018 15:10:55 -0500 Tom Zanussi <[email protected]>…
Actions also need to be considered when checking for matching triggers
- triggers differing only by action should be allowed, but currently aren't because the matching check ignores the action and erroneously returns -EEXIST.

Quoted 5 lines

Hi Tom,
Could you show us the bad/good examples (maybe different onmatch() actions)? And if it is real bugfix, I would like to add a ftracetest testcase for this fix.

Here's an example using onmatch() actions. The first -EEXIST shouldn't occur because the onmatch() is different in the second wakeup_latency() param. The second -EEXIST shouldn't occur because it's a different action (in this case, it doesn't have an action, so shouldn't be seen as being the same and therefore rejected).

In the after case, both are correctly accepted (and trying to add one of them again returns -EEXIST as it should).

before:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
-su: echo: write error: File exists
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
-su: echo: write error: File exists

after:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

Thanks,

Tom

Masami Hiramatsu

maintainer

2018-04-04 12:33 UTC #6 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Hi Tom,

Quoted 8 lines · On Mon, 02 Apr 2018 12:09:33 -0500 Tom Zanussi <[email protected]>…

after:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

I ensured this sequence has no problem.
After above sequence, the trigger file shows

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048 if next_comm=="cyclictest" [active]
======

So I clear the last one

======

# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

OK, it should be removed. I can not see it anymore on the trigger file.

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
======

But when I missed to remove it again, it is accepted (is not an error?)

======

# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

Hmm... anyway, let's clear others too.

======

# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# cat events/sched/sched_switch/trigger
# Available triggers:
# traceon traceoff snapshot stacktrace enable_event disable_event enable_hist disable_hist hist
======

OK, it is cleared now.

Now I test it again.

======

# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> events/sched/sched_wakeup/trigger
sh: write error: Invalid argument
======

Oops, what's the error?

======

# cat events/sched/sched_switch/hist

ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
======

Hmm, how can I undef ts0 and test it again?
If I can not clean it, the testcase must fail on the 2nd time.

Thank you,

Signature · 1 line

Masami Hiramatsu <[email protected]>

Steven Rostedt

maintainer

2018-04-04 13:01 UTC #7 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Quoted 2 lines · On Wed, 4 Apr 2018 21:33:38 +0900 Masami Hiramatsu <[email protected]> wrote:

Hmm, how can I undef ts0 and test it again?
If I can not clean it, the testcase must fail on the 2nd time.

Tom,

I already pulled in your patches and almost completed my tests (which obviously are not stress testing this code).

Any fixes you make to address Masami's concerns, can you please make as separate patches on top of this. You can see my current tree that I'm testing and base on top of that one.

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
branch: ftrace/core

(Note, that can rebase, but mostly to add acks)

Thanks!

-- Steve

Tom Zanussi

author

2018-04-04 15:17 UTC #8 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

In reply to Masami Hiramatsu

Hi Masami,

Quoted 41 lines · Masami Hiramatsu

Hi Tom,

Quoted 8 lines · On Mon, 02 Apr 2018 12:09:33 -0500 Tom Zanussi <[email protected]>…

after:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

I ensured this sequence has no problem.
After above sequence, the trigger file shows

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048 if next_comm=="cyclictest" [active]
======

So I clear the last one

======

# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

OK, it should be removed. I can not see it anymore on the trigger file.

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
======

Quoted 6 lines

But when I missed to remove it again, it is accepted (is not an error?)
======
# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

This is consistent with existing behavior, not only for the hist triggers but ftrace in general I think e.g.

# echo 'traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger
# echo '!traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger
# echo '!traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger

# echo 'try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter
# echo '!try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter
# echo '!try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter

Neither produces an error trying to remove an already-removed trigger. Or are you thinking about something else?

Quoted 20 lines

Hmm... anyway, let's clear others too.

======

# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# cat events/sched/sched_switch/trigger
# Available triggers:
# traceon traceoff snapshot stacktrace enable_event disable_event enable_hist disable_hist hist
======

OK, it is cleared now.

Now I test it again.

======

# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> events/sched/sched_wakeup/trigger
sh: write error: Invalid argument
======

Quoted 9 lines

Oops, what's the error?
======
# cat events/sched/sched_switch/hist
ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
======

Hmm, but ts0 is defined on sched_wakeup - you removed the triggers on sched_switch, but I didn't see where you removed the sched_wakeup trigger defining ts0...

Quoted 1 line

Hmm, how can I undef ts0 and test it again?

You should be able to remove the sched_wakeup trigger defining ts0 and after doing that test again. At least I was able to:

# echo '!hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> 
events/sched/sched_wakeup/trigger

# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"'

Quoted 1 line

Quoted 1 line
events/sched/sched_wakeup/trigger

Thanks,

Tom

Quoted 4 lines

If I can not clean it, the testcase must fail on the 2nd time.
Thank you,

Masami Hiramatsu

maintainer Tested-by

2018-04-05 03:50 UTC #9 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Quoted 58 lines · On Wed, 04 Apr 2018 10:17:03 -0500 Tom Zanussi <[email protected]>…

Hi Masami,

Quoted 41 lines · Masami Hiramatsu

Hi Tom,

Quoted 8 lines · On Mon, 02 Apr 2018 12:09:33 -0500 Tom Zanussi <[email protected]>…

after:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

I ensured this sequence has no problem.
After above sequence, the trigger file shows

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048 if next_comm=="cyclictest" [active]
======

So I clear the last one

======

# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

OK, it should be removed. I can not see it anymore on the trigger file.

======

# cat events/sched/sched_switch/trigger
hist:keys=next_pid:vals=hitcount:wakeup_lat=common_timestamp.usecs-$ts0:sort=hitcount:size=2048:clock=global if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest" [active]
hist:keys=next_pid:vals=hitcount:sort=hitcount:size=2048:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest" [active]
======

Quoted 6 lines

But when I missed to remove it again, it is accepted (is not an error?)
======
# echo '!hist:keys=next_pid if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
#
======

This is consistent with existing behavior, not only for the hist triggers but ftrace in general I think e.g.

# echo 'traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger
# echo '!traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger
# echo '!traceoff:1 if nr_rq > 1' >> /sys/kernel/debug/tracing/events/block/block_unplug/trigger

Quoted 6 lines

# echo 'try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter
# echo '!try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter
# echo '!try_to_wake_up:enable_event:sched:sched_switch:2' >> set_ftrace_filter
Neither produces an error trying to remove an already-removed trigger. Or are you thinking about something else?

Hmm, OK, it is ftrace's behavior.

Quoted 24 lines

Hmm... anyway, let's clear others too.

======

# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,next_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# echo '!hist:keys=next_pid:onmatch(sched.sched_wakeup).wakeup_latency(sched.sched_switch.$wakeup_lat,prev_pid) if next_comm=="cyclictest"' >> events/sched/sched_switch/trigger
# cat events/sched/sched_switch/trigger
# Available triggers:
# traceon traceoff snapshot stacktrace enable_event disable_event enable_hist disable_hist hist
======

OK, it is cleared now.

Now I test it again.

======

# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> events/sched/sched_wakeup/trigger
sh: write error: Invalid argument
======

Oops, what's the error?

======

# cat events/sched/sched_switch/hist

Quoted 8 lines

Quoted 4 lines
ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
======
Hmm, but ts0 is defined on sched_wakeup - you removed the triggers on sched_switch, but I didn't see where you removed the sched_wakeup trigger defining ts0...

Ah, I confused that the sched_switch and sched_wakeup...

Can you print out the error with which event we should see? e.g.

ERROR: Variable already defined at sched_wakeup: ts0

And this shows the good reason why we should reject removing unexist trigger (with -ENOENT). If I find I can not remove 'hist:keys=pid:ts0=...' from sched_switch, it helps me to notice my mistake.

Quoted 10 lines

Quoted 1 line
Hmm, how can I undef ts0 and test it again?
You should be able to remove the sched_wakeup trigger defining ts0 and after doing that test again. At least I was able to:
# echo '!hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> 
events/sched/sched_wakeup/trigger
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"'
Quoted 1 line
Quoted 1 line
events/sched/sched_wakeup/trigger

OK, anyway this works good to me too.

Tested-by Masami Hiramatsu <[email protected]>

Thanks,

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2018-04-05 23:34 UTC #10 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Hi Masami,

On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu wrote:

[...]

Quoted 4 lines

Can you print out the error with which event we should see? e.g.
ERROR: Variable already defined at sched_wakeup: ts0

How about printing the event name along with the last command, for any error? :

ERROR: Variable already defined: ts0

    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

If that seems fine to you (more detailed explanation below), I'll test the patch below and submit it along with a couple others after testing.

[PATCH 2/3] tracing: Add system:event_name to hist trigger 'last
command' error info

In order to help users determine what might have gone wrong when entering a hist trigger command, a simple 'last error' facility was added which simply displays the last error that occurred at the end of whatever hist file is read.

The assumption is that the user would normally read the hist file for the event that caused the error, but in some cases a user may become confused about which was the command that caused the error and read a different hist file. In that case it's still useful to be able to access the error info, but can cause even more confusion if the user thinks the error is associated with that event.

So, along with the 'last cmd' itself, we explicitly add the event associated with it and clearly show which event the error was triggered on.

Before:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger

  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

And other commands making us think we cleared everything out so the below error is a surprise

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument

Wait, we think, we cleared it all out, how can there still be something defined?

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
  ERROR: Variable already defined: ts0
    Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Confusion because there's nothing defined on sched_switch, we did clear it all out.

After:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger

  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

And other commands making us think we cleared everything out so the below error is a surprise

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument

Wait, we think, we cleared it all out, how can there still be something defined?

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
  ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Oh, that's saying it's defined on sched_wakeup, let's look there...

  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist
  # event histogram
  #
  # trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
  #

Totals:

      Hits: 0
      Entries: 0
      Dropped: 0

ERROR: Variable already defined: ts0

    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Yeah, the sched_wakeup command defining ts0 is still there so what happened was that the last command to sched_wakeup again defining ts0 failed because we hadn't actually cleared the previous sched_wakeup command like we thought we had.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 32 +++++++++++++++++++++++++++++---
 1 file changed, 29 insertions(+), 3 deletions(-)

kernel/trace/trace_events_hist.c +29 -3

index 66c87be4ebb2..38a4566f74a7 100644
@@ -356,12 +356,37 @@ struct action_data {
 static char last_hist_cmd[MAX_FILTER_STR_VAL];
 static char hist_err_str[MAX_FILTER_STR_VAL];
 
-static void last_cmd_set(char *str)
+static void last_cmd_set(struct trace_event_file *file, char *str)
 {
+	int event_len = 0, maxlen = MAX_FILTER_STR_VAL - 1;
+	const char *system = NULL, *name = NULL;
+	char event_name[MAX_FILTER_STR_VAL];
+	struct trace_event_call *call;
+
 	if (!str)
 		return;
 
-	strncpy(last_hist_cmd, str, MAX_FILTER_STR_VAL - 1);
+	if (file) {
+		call = file->event_call;
+
+		system = call->class->system;
+		if (system) {
+			name = trace_event_name(call);
+			if (!name)
+				system = NULL;
+		}
+	}
+
+	if (system)
+		event_len = snprintf(event_name, MAX_FILTER_STR_VAL, "[%s:%s] ", system, name);
+
+	if (event_len + strlen(str) > maxlen)
+		return;
+
+	if (event_len)
+		strcat(last_hist_cmd, event_name);
+
+	strcat(last_hist_cmd, str);
 }
 
 static void hist_err(char *str, char *var)

@@ -401,6 +426,7 @@ static void hist_err_event(char *str, char *system, char *event, char *var)
 static void hist_err_clear(void)
 {
 	hist_err_str[0] = '\0';
+	last_hist_cmd[0] = '\0';
 }
 
 static bool have_hist_err(void)

@@ -5478,8 +5504,8 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
 	int ret = 0;
 
 	if (glob && strlen(glob)) {
-		last_cmd_set(param);
 		hist_err_clear();
+		last_cmd_set(file, param);
 	}
 
 	if (!param)

Signature · 1 line

2.14.1

Quoted 4 lines

And this shows the good reason why we should reject removing unexist trigger (with -ENOENT). If I find I can not remove 'hist:keys=pid:ts0=...' from sched_switch, it helps me to notice my mistake.

That's very easy to implement, see the patch below, but it changes existing behavior (which makes some sense, see below), and the -ENOENT would seem to cause more confusion for the user, who would probably think it refers to the trigger file not existing, which it clearly does...

Anyway, I hope the above patch to explicitly show the event name will be sufficient to avoid confusion in cases like this.

[PATCH 3/3] tracing: Return error when trying to delete nonexistent
hist trigger

Rather than being silent about it, explicitly let the user know it doesn't exist and so can't be removed.

The current behavior is to just be silent about it - if there's no error like -EBUSY, the user can be assured the trigger no longer exists whether or not it did before.

Before:

  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

After:

  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  -su: echo: write error: No such file or directory

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

kernel/trace/trace_events_hist.c +3 -1

index 38a4566f74a7..f5c85ba6f580 100644
@@ -5584,8 +5584,10 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
 	}
 
 	if (remove) {
-		if (!have_hist_trigger_match(trigger_data, file))
+		if (!have_hist_trigger_match(trigger_data, file)) {
+			ret = -ENOENT;
 			goto out_free;
+		}
 
 		if (hist_trigger_check_refs(trigger_data, file)) {
 			ret = -EBUSY;

Signature · 1 line

2.14.1

Quoted 9 lines

Quoted 9 lines
Quoted 2 lines
Hmm, how can I undef ts0 and test it again?
You should be able to remove the sched_wakeup trigger defining ts0 and after doing that test again. At least I was able to:
# echo '!hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> 
events/sched/sched_wakeup/trigger

Quoted 7 lines

Quoted 2 lines
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"'
Quoted 1 line
Quoted 1 line
events/sched/sched_wakeup/trigger
OK, anyway this works good to me too.
Tested-by Masami Hiramatsu <[email protected]>

Thanks!

Tom

Masami Hiramatsu

maintainer

2018-04-06 01:53 UTC #11 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Hi Tom,

Quoted 8 lines · On Thu, 05 Apr 2018 18:34:13 -0500 Tom Zanussi <[email protected]>…

Hi Masami,
On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu wrote:
[...]
Quoted 2 lines
Can you print out the error with which event we should see? e.g.

Quoted 8 lines

Quoted 2 lines
ERROR: Variable already defined at sched_wakeup: ts0
How about printing the event name along with the last command, for any error? :
ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Hmm, is the Last command shows the last command on sched_wakeup ? or sched_switch??

[...]

Quoted 11 lines

Before:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger

  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

And other commands making us think we cleared everything out so the below error is a surprise

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument

No, my senario is different.

Your senario tries
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on sched_wakeup and get an error

In this case, user can dump sched_wakeup/trigger and see there is already ts0 defined.

My senario is a bit different
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on *sched_switch* and get an error

The 3rd operation failed on "sched_switch" not on "sched_wakeup". In this case we will totally lost where the ts0 defined. That's why I have asked you to show "where the ts0 is defined" at error line.

Anyway, I think it is a good chance to introduce <tracefs>/error_log file, since we have too many non-critical errors on operations. I feel that checking hist file by errors on trigger file is not a bit intuitive.

# cat /sys/kernel/debug/tracing/error_log
ERROR(events/sched/sched_switch/trigger): Variable already defined: ts0@sched:sched_wakeup
  Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

This can be used from probe events too :)
e.g.

ERROR(kprobe_events): Unsupported type: uint8
Command: p vfs_read arg1=%di:uint8

Any thought?

Thank you,

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2018-04-06 16:47 UTC #12 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Hi Masami,

Quoted 16 lines · Masami Hiramatsu

Hi Tom,
Quoted 11 lines · On Thu, 05 Apr 2018 18:34:13 -0500 Tom Zanussi <[email protected]>…
Hi Masami,
On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu wrote:
[...]
Quoted 4 lines
Can you print out the error with which event we should see? e.g.
ERROR: Variable already defined at sched_wakeup: ts0

Quoted 8 lines

Quoted 5 lines
How about printing the event name along with the last command, for any error? :
ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
Hmm, is the Last command shows the last command on sched_wakeup ? or sched_switch??

Just the last command that executed with an error - it's a global set by the last command that failed, kind of like errno.

In this case, the last error was for the command listed, on the sched_wakeup event. Even if you see it by reading a different hist file, the last error is still the same - we don't keep a last error for each event.

Quoted 22 lines

[...]
Quoted 11 lines
Before:
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
And other commands making us think we cleared everything out so the below error is a surprise
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument
No, my senario is different.
Your senario tries
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on sched_wakeup and get an error
In this case, user can dump sched_wakeup/trigger and see there is already ts0 defined.

Quoted 8 lines

My senario is a bit different
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on *sched_switch* and get an error
The 3rd operation failed on "sched_switch" not on "sched_wakeup". In this case we will totally lost where the ts0 defined. That's why I have asked you to show "where the ts0 is defined" at error line.

Your scenario should work, which is why I assumed my scenario. Anyway, this I think corresponds to your scenario, which works for me:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

I also tried this, which works too:

  # echo '!wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

When I looked at the details of what you did in your script, it corresponded to my scenario - the error you saw was because you didn't remove the sched_wakeup trigger though you apparently thought you did, and then tried to do it again (according to your script, the command that failed was to sched_wakeup, and then you looked at sched_switch and saw the error).

Anyway, here's the corresponding version that works if you add the trigger to sched_switch instead of twice to sched_wakeup:

Try adding to sched_wakeup, fails:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    -su: echo: 
    write error: Invalid argument

Look at sched_switch instead of sched_wakeup, shows error was on sched_wakeup:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Look at sched_wakeup, sched_wakeup trigger exists and has the ts0 defined:

  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

Let's add a trigger with ts0 to sched_switch:

  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

No error seen, and now we can see that both sched_switch and sched_wakeup have triggers with ts0:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
    hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

Now at this point, we have two triggers with the same variable name, ts0
- if we try to use an unqualified ts0 in another trigger, we get an error:

  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
    -su: echo: write error: Invalid argument
  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
  # event histogram
  #
  # trigger info: 
    hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
  #

Totals:

       Hits: 0
       Entries: 0
       Dropped: 0

ERROR: Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ts0
Last command: [sched:sched_switch] keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"

So in order to set the trigger, we need to explicitly specify which ts0 to use:

# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

So we use the explicit sched.sched_wakeup.$ts0 to specify that we want to use the ts0 on sched_wakeup for the calculation.

Note that the most common use case is to put the wakeup_lat=common_timestamp.usecs-$ts0 expression on a trigger with an onmatch() action, and onmatch() specifies the matching event, so there's no need to explicitly use the fully qualified sched.sched_wakeup.$ts0 in that case. The above doesn't have onmatch(), and therefore has no way to disambiguate the name without specifying which event explicitly.

Quoted 6 lines

Anyway, I think it is a good chance to introduce <tracefs>/error_log file, since we have too many non-critical errors on operations. I feel that checking hist file by errors on trigger file is not a bit intuitive.
# cat /sys/kernel/debug/tracing/error_log
ERROR(events/sched/sched_switch/trigger): Variable already defined: ts0@sched:sched_wakeup
  Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Quoted 8 lines

This can be used from probe events too :)
e.g.
ERROR(kprobe_events): Unsupported type: uint8
Command: p vfs_read arg1=%di:uint8
Any thought?

I agree - I think that would make more sense than using the hist files for that purpose. I'll work on adding this and getting rid of the hist file error mechanism.

Thanks,

Tom

Quoted 4 lines

Thank you,

Masami Hiramatsu

maintainer

2018-04-07 12:16 UTC #13 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Quoted 14 lines · On Fri, 06 Apr 2018 11:47:29 -0500 Tom Zanussi <[email protected]>…

Quoted 5 lines
Quoted 5 lines
Quoted 4 lines
Can you print out the error with which event we should see? e.g.
ERROR: Variable already defined at sched_wakeup: ts0
Quoted 8 lines
Quoted 5 lines
How about printing the event name along with the last command, for any error? :
ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
Hmm, is the Last command shows the last command on sched_wakeup ? or sched_switch??

Quoted 7 lines

Just the last command that executed with an error - it's a global set by the last command that failed, kind of like errno.
In this case, the last error was for the command listed, on the sched_wakeup event. Even if you see it by reading a different hist file, the last error is still the same - we don't keep a last error for each event.

OK, in that case, it may not be useful for my case.
I need to know why the error happens and where should I see to solve it.

Quoted 32 lines

Quoted 23 lines
[...]
Quoted 11 lines
Before:
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
And other commands making us think we cleared everything out so the below error is a surprise
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument
No, my senario is different.
Your senario tries
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on sched_wakeup and get an error
In this case, user can dump sched_wakeup/trigger and see there is already ts0 defined.
Quoted 8 lines
My senario is a bit different
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on *sched_switch* and get an error
The 3rd operation failed on "sched_switch" not on "sched_wakeup". In this case we will totally lost where the ts0 defined. That's why I have asked you to show "where the ts0 is defined" at error line.

Quoted 7 lines

Your scenario should work, which is why I assumed my scenario. Anyway, this I think corresponds to your scenario, which works for me:

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

Hmm, is it possible to redefine ts0 on different event??
In that case, will ts0 be updated on both sched_switch and sched_wakeup?

Quoted 10 lines

I also tried this, which works too:

  # echo '!wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

Quoted 6 lines

When I looked at the details of what you did in your script, it corresponded to my scenario - the error you saw was because you didn't remove the sched_wakeup trigger though you apparently thought you did, and then tried to do it again (according to your script, the command that failed was to sched_wakeup, and then you looked at sched_switch and saw the error).

Ah, I got it! I mixed it up, sorry.

BTW, if I defied ts0 at sched_wakeup

====
[root@devbox ~]# echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
====

and do it again,

====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -bash: echo: write error: Invalid argument
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist

# event histogram
#
# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#

Totals:

    Hits: 0
    Entries: 0
    Dropped: 0

ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
====

OK, I got this error message.
However, if I write same command on sched_switch,

====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger -bash: echo: write error: Invalid argument
====

This gets error because there is no "pid" argument in the event, but

====
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist# event histogram #

# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#

Totals:

    Hits: 0
    Entries: 0
    Dropped: 0

[root@devbox ~]#
====

I can't see the corresponding error message...

Quoted 46 lines

Anyway, here's the corresponding version that works if you add the trigger to sched_switch instead of twice to sched_wakeup:

Try adding to sched_wakeup, fails:

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    -su: echo: 
    write error: Invalid argument

Look at sched_switch instead of sched_wakeup, shows error was on sched_wakeup:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
    ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"

Look at sched_wakeup, sched_wakeup trigger exists and has the ts0 defined:

  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

Let's add a trigger with ts0 to sched_switch:

  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

No error seen, and now we can see that both sched_switch and sched_wakeup have triggers with ts0:

  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
    hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
    hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

Now at this point, we have two triggers with the same variable name, ts0
- if we try to use an unqualified ts0 in another trigger, we get an error:

  # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
    -su: echo: write error: Invalid argument
  # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
  # event histogram
  #
  # trigger info: 
    hist:keys=next_pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
  #

Quoted 7 lines

Totals:
       Hits: 0
       Entries: 0
       Dropped: 0
ERROR: Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ts0
Last command: [sched:sched_switch] keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0 if next_comm=="cyclictest"

Ah, I see. So ts0 is abbreviated name :) we have 2 different variables.

Quoted 6 lines

So in order to set the trigger, we need to explicitly specify which ts0 to use:
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-sched.sched_wakeup.$ts0 if next_comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
So we use the explicit sched.sched_wakeup.$ts0 to specify that we want to use the ts0 on sched_wakeup for the calculation.

got it.

Quoted 6 lines

Note that the most common use case is to put the wakeup_lat=common_timestamp.usecs-$ts0 expression on a trigger with an onmatch() action, and onmatch() specifies the matching event, so there's no need to explicitly use the fully qualified sched.sched_wakeup.$ts0 in that case. The above doesn't have onmatch(), and therefore has no way to disambiguate the name without specifying which event explicitly.

Cool :)

Quoted 12 lines

Quoted 12 lines
Anyway, I think it is a good chance to introduce <tracefs>/error_log file, since we have too many non-critical errors on operations. I feel that checking hist file by errors on trigger file is not a bit intuitive.
# cat /sys/kernel/debug/tracing/error_log
ERROR(events/sched/sched_switch/trigger): Variable already defined: ts0@sched:sched_wakeup
  Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
This can be used from probe events too :)
e.g.
ERROR(kprobe_events): Unsupported type: uint8
Command: p vfs_read arg1=%di:uint8

Quoted 6 lines

Quoted 2 lines
Any thought?
I agree - I think that would make more sense than using the hist files for that purpose. I'll work on adding this and getting rid of the hist file error mechanism.

Thank you!

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2018-04-12 15:22 UTC #14 lore raw

Re: [PATCH 3/4] tracing: Add action comparisons when testing matching hist triggers

Hi Masami,

Sorry for the delay in replying - was off for a few days..

Quoted 63 lines · Masami Hiramatsu

Quoted 14 lines · On Fri, 06 Apr 2018 11:47:29 -0500 Tom Zanussi <[email protected]>…
Quoted 5 lines
Quoted 5 lines
Quoted 4 lines
Can you print out the error with which event we should see? e.g.
ERROR: Variable already defined at sched_wakeup: ts0
Quoted 8 lines
Quoted 5 lines
How about printing the event name along with the last command, for any error? :
ERROR: Variable already defined: ts0
    Last command: [sched:sched_wakeup] keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
Hmm, is the Last command shows the last command on sched_wakeup ? or sched_switch??
Quoted 7 lines
Just the last command that executed with an error - it's a global set by the last command that failed, kind of like errno.
In this case, the last error was for the command listed, on the sched_wakeup event. Even if you see it by reading a different hist file, the last error is still the same - we don't keep a last error for each event.
OK, in that case, it may not be useful for my case.
I need to know why the error happens and where should I see to solve it.
Quoted 35 lines
Quoted 23 lines
[...]
Quoted 11 lines
Before:
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
And other commands making us think we cleared everything out so the below error is a surprise
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument
No, my senario is different.
Your senario tries
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on sched_wakeup and get an error
In this case, user can dump sched_wakeup/trigger and see there is already ts0 defined.
Quoted 8 lines
My senario is a bit different
1) define ts0 on sched_wakeup
2) remove ts0 from sched_switch (but silently failed)
3) re-define ts0 on *sched_switch* and get an error
The 3rd operation failed on "sched_switch" not on "sched_wakeup". In this case we will totally lost where the ts0 defined. That's why I have asked you to show "where the ts0 is defined" at error line.
Your scenario should work, which is why I assumed my scenario. Anyway, this I think corresponds to your scenario, which works for me:

Quoted 8 lines

Quoted 4 lines

  # echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger

Hmm, is it possible to redefine ts0 on different event??
In that case, will ts0 be updated on both sched_switch and sched_wakeup?

It's not really redefining ts0 - those are separate variables on two different events that happen to have the same name (thus the need to disambiguate when referencing them in later expressions). And yes, they are updated separately whenever the corresponding event occurs.

Quoted 64 lines

Quoted 10 lines
I also tried this, which works too:
  # echo '!wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo '!hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
  # echo 'hist:keys=next_pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
Quoted 6 lines
When I looked at the details of what you did in your script, it corresponded to my scenario - the error you saw was because you didn't remove the sched_wakeup trigger though you apparently thought you did, and then tried to do it again (according to your script, the command that failed was to sched_wakeup, and then you looked at sched_switch and saw the error).
Ah, I got it! I mixed it up, sorry.
BTW, if I defied ts0 at sched_wakeup
====
[root@devbox ~]# echo 'wakeup_latency u64 lat; pid_t pid' >> /sys/kernel/debug/tracing/synthetic_events
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
====
and do it again,
====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -bash: echo: write error: Invalid argument
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist
# event histogram
#
# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#
Totals:
    Hits: 0
    Entries: 0
    Dropped: 0
ERROR: Variable already defined: ts0
Last command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
====
OK, I got this error message.
However, if I write same command on sched_switch,
====
[root@devbox ~]# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_switch/trigger -bash: echo: write error: Invalid argument
====
This gets error because there is no "pid" argument in the event, but
====
[root@devbox ~]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist# event histogram #
# trigger info: hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]
#

Quoted 8 lines

Totals:
    Hits: 0
    Entries: 0
    Dropped: 0
[root@devbox ~]#
====
I can't see the corresponding error message...

Right, that's because I forgot to generate an error message for that. The patchset I just posted adds an error message for that - thanks for pointing it out.

Tom