[PATCH 0/4] tracing: A few inter-event bugfixes

[PATCH 0/4] tracing: A few inter-event bugfixes

[Tom Zanussi]

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(-)

-- 
1.9.3

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

[Tom Zanussi]

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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 19 +++++--------------
 1 file changed, 5 insertions(+), 14 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 4f02764..fb81447 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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,
-- 
1.9.3

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

[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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index fb81447..468e43f 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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) {
-- 
1.9.3

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

[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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 50 ++++++++++++++++++++++++++++++++++++++++
 1 file changed, 50 insertions(+)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 468e43f..ae84470 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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;
 }
 
-- 
1.9.3

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

[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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index ae84470..2751a0f 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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);
-- 
1.9.3

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

[Masami Hiramatsu]

On Wed, 28 Mar 2018 15:10:55 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> 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,

> 
> Add and call an actions_match() function to address that.
> 
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
>  kernel/trace/trace_events_hist.c | 50 ++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 50 insertions(+)
> 
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 468e43f..ae84470 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -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;
>  }
>  
> -- 
> 1.9.3
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH 0/4] tracing: A few inter-event bugfixes

[Steven Rostedt]

On Wed, 28 Mar 2018 15:10:52 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> 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

> 
> 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(-)
> 

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

[Tom Zanussi]

Hi Masami,

On Tue, 2018-04-03 at 00:10 +0900, Masami Hiramatsu wrote:
> On Wed, 28 Mar 2018 15:10:55 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > 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.
> 

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

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

[Masami Hiramatsu]

Hi Tom,

On Mon, 02 Apr 2018 12:09:33 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> 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,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

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

[Steven Rostedt]

On Wed, 4 Apr 2018 21:33:38 +0900
Masami Hiramatsu <mhiramat@kernel.org> 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

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

[Tom Zanussi]

Hi Masami,

On Wed, 2018-04-04 at 21:33 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Mon, 02 Apr 2018 12:09:33 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > 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
> #
> ======

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?

> 
> 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, 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... 

> 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"'
>> events/sched/sched_wakeup/trigger

Thanks,

Tom



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

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

[Masami Hiramatsu]

On Wed, 04 Apr 2018 10:17:03 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Hi Masami,
> 
> On Wed, 2018-04-04 at 21:33 +0900, Masami Hiramatsu wrote:
> > Hi Tom,
> > 
> > On Mon, 02 Apr 2018 12:09:33 -0500
> > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> > 
> > > 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
> > #
> > ======
> 
> 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?

Hmm, OK, it is ftrace's behavior.

> > 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, 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.

> > 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"'
> >> events/sched/sched_wakeup/trigger

OK, anyway this works good to me too.

Tested-by: Masami Hiramatsu <mhiramat@kernel.org>

Thanks,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

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

[Tom Zanussi]

Hi Masami,

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

[...]

> 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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 32 +++++++++++++++++++++++++++++---
 1 file changed, 29 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 66c87be4ebb2..38a4566f74a7 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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)
-- 
2.14.1


> 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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 38a4566f74a7..f5c85ba6f580 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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;
-- 
2.14.1






> 
> > > 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"'
> > >> events/sched/sched_wakeup/trigger
> 
> OK, anyway this works good to me too.
> 
> Tested-by: Masami Hiramatsu <mhiramat@kernel.org>
> 

Thanks!

Tom

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

[Masami Hiramatsu]

Hi Tom,

On Thu, 05 Apr 2018 18:34:13 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Hi Masami,
> 
> On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu wrote:
> 
> [...]
> 
> > 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"

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

[...]
> 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,



-- 
Masami Hiramatsu <mhiramat@kernel.org>

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

[Tom Zanussi]

Hi Masami,

On Fri, 2018-04-06 at 10:53 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Thu, 05 Apr 2018 18:34:13 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > Hi Masami,
> > 
> > On Thu, 2018-04-05 at 12:50 +0900, Masami Hiramatsu wrote:
> > 
> > [...]
> > 
> > > 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"
> 
> 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.

> [...]
> > 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.
> 

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.

> 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?
> 

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

> Thank you,
> 
> 
> 

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

[Masami Hiramatsu]

On Fri, 06 Apr 2018 11:47:29 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> > > > 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"
> > 
> > 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.

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.

> 
> > [...]
> > > 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.
> > 
> 
> 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?

> 
> 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).

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...

> 
> 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"

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


> 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.

> 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 :)

> > 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?
> > 
> 
> 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!

-- 
Masami Hiramatsu <mhiramat@kernel.org>

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

[Tom Zanussi]

Hi Masami,

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

On Sat, 2018-04-07 at 21:16 +0900, Masami Hiramatsu wrote:
> On Fri, 06 Apr 2018 11:47:29 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > > > > 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"
> > > 
> > > 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.
> 
> 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.
> 
> > 
> > > [...]
> > > > 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.
> > > 
> > 
> > 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?
> 

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.

> > 
> > 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).
> 
> 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...

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