tracing: A few inter-event bugfixes

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

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.

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

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

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?

Quoted 1 line

events/sched/sched_wakeup/trigger

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

Thank you,

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

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

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

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

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

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

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

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

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

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

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

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