[PATCH RFC] tracing: Call triggers only if event passes filter checks

[PATCH RFC] tracing: Call triggers only if event passes filter checks

[Joel Fernandes]

From: "Joel Fernandes (Google)" <joel@joelfernandes.org>

Currently, trace event triggers are called regardless of if the event
filter checks pass or fail. Thus if one were to enable event triggers
and filters at the same time, then the triggers will always be called
even if the filter checks didn't pass.

This is a problem for a usecase I was experimenting with: measuring the
time preemption is disabled using synthetic events and dump the stack
using the stacktrace trigger if the total preempt off time was greater
than a threshold. Following are the commands for the same:

Create synthetic event:

echo 'preemptdisable u64 lat' >> \
	      /sys/kernel/debug/tracing/synthetic_events

echo 'hist:keys=cpu:ts0=common_timestamp.usecs:scpu=cpu' >> \
	      /sys/kernel/debug/tracing/events/preemptirq/preempt_disable/trigger

echo 'hist:keys=cpu:wakeup_lat=common_timestamp.usecs-$ts0:\
onmatch(preemptirq.preempt_disable).preemptdisable($wakeup_lat)' >> \
	        /sys/kernel/debug/tracing/events/preemptirq/preempt_enable/trigger

Enable synthetic event:

echo stacktrace > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
echo 'lat > 400' > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/filter
echo 1 > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/enable

With the patch, the stacktrace is triggered only if the filter checks
passed. It also seems sensible to call triggers only if filter checks
pass so lets do that.

Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
---
 kernel/trace/trace.h | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 630c5a24b2b2..b0b5df288924 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1296,13 +1296,14 @@ __event_trigger_test_discard(struct trace_event_file *file,
 			     enum event_trigger_type *tt)
 {
 	unsigned long eflags = file->flags;
+	bool filtered = (file->flags & EVENT_FILE_FL_FILTERED) &&
+			 !filter_match_preds(file->filter, entry);
 
-	if (eflags & EVENT_FILE_FL_TRIGGER_COND)
+	if (!filtered && (eflags & EVENT_FILE_FL_TRIGGER_COND))
 		*tt = event_triggers_call(file, entry, event);
 
 	if (test_bit(EVENT_FILE_FL_SOFT_DISABLED_BIT, &file->flags) ||
-	    (unlikely(file->flags & EVENT_FILE_FL_FILTERED) &&
-	     !filter_match_preds(file->filter, entry))) {
+	    filtered) {
 		__trace_event_discard_commit(buffer, event);
 		return true;
 	}
-- 
2.18.0.rc1.244.gcf134e6275-goog

Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks

[Steven Rostedt]

On Thu, 14 Jun 2018 18:01:13 -0700
Joel Fernandes <joelaf@google.com> wrote:

> From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> 
> Currently, trace event triggers are called regardless of if the event
> filter checks pass or fail. Thus if one were to enable event triggers
> and filters at the same time, then the triggers will always be called
> even if the filter checks didn't pass.
> 
> This is a problem for a usecase I was experimenting with: measuring the
> time preemption is disabled using synthetic events and dump the stack
> using the stacktrace trigger if the total preempt off time was greater
> than a threshold. Following are the commands for the same:
> 
> Create synthetic event:
> 
> echo 'preemptdisable u64 lat' >> \
> 	      /sys/kernel/debug/tracing/synthetic_events
> 
> echo 'hist:keys=cpu:ts0=common_timestamp.usecs:scpu=cpu' >> \
> 	      /sys/kernel/debug/tracing/events/preemptirq/preempt_disable/trigger
> 
> echo 'hist:keys=cpu:wakeup_lat=common_timestamp.usecs-$ts0:\
> onmatch(preemptirq.preempt_disable).preemptdisable($wakeup_lat)' >> \
> 	        /sys/kernel/debug/tracing/events/preemptirq/preempt_enable/trigger
> 
> Enable synthetic event:
> 
> echo stacktrace > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
> echo 'lat > 400' > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/filter
> echo 1 > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/enable
> 
> With the patch, the stacktrace is triggered only if the filter checks
> passed. It also seems sensible to call triggers only if filter checks
> pass so lets do that.

No, it worked as expected. The filter is only to be used it the event
should be recorded or not. What you wanted to do is:

 echo 'stacktrace if lat > 400' > events/synthetic/preemptdisable/trigger

-- Steve

Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks

[Joel Fernandes]

On Fri, Jun 15, 2018 at 12:16:03PM -0400, Steven Rostedt wrote:
> On Thu, 14 Jun 2018 18:01:13 -0700
> Joel Fernandes <joelaf@google.com> wrote:
> 
> > From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> > 
> > Currently, trace event triggers are called regardless of if the event
> > filter checks pass or fail. Thus if one were to enable event triggers
> > and filters at the same time, then the triggers will always be called
> > even if the filter checks didn't pass.
> > 
> > This is a problem for a usecase I was experimenting with: measuring the
> > time preemption is disabled using synthetic events and dump the stack
> > using the stacktrace trigger if the total preempt off time was greater
> > than a threshold. Following are the commands for the same:
> > 
> > Create synthetic event:
> > 
> > echo 'preemptdisable u64 lat' >> \
> > 	      /sys/kernel/debug/tracing/synthetic_events
> > 
> > echo 'hist:keys=cpu:ts0=common_timestamp.usecs:scpu=cpu' >> \
> > 	      /sys/kernel/debug/tracing/events/preemptirq/preempt_disable/trigger
> > 
> > echo 'hist:keys=cpu:wakeup_lat=common_timestamp.usecs-$ts0:\
> > onmatch(preemptirq.preempt_disable).preemptdisable($wakeup_lat)' >> \
> > 	        /sys/kernel/debug/tracing/events/preemptirq/preempt_enable/trigger
> > 
> > Enable synthetic event:
> > 
> > echo stacktrace > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
> > echo 'lat > 400' > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/filter
> > echo 1 > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/enable
> > 
> > With the patch, the stacktrace is triggered only if the filter checks
> > passed. It also seems sensible to call triggers only if filter checks
> > pass so lets do that.
> 
> No, it worked as expected. The filter is only to be used it the event
> should be recorded or not. What you wanted to do is:
> 
>  echo 'stacktrace if lat > 400' > events/synthetic/preemptdisable/trigger

Thanks, that worked!

I was thinking at some point we should add these synthetic event 'recipes' to
the kernel tree as scripts or documentation, or something like that. Do you
have any suggestions on where to add these? A recipe would be 'report
preemptoff times > threshold us' or 'wake up latency > threshold us'. I think
there will be quite a few such useful ones.

Another idea could be to make the 'recipes' a part of ftrace itself.
Something like a 'built in' synthetic event that will set itself up when its
enabled without needing to create the hist triggers and other triggers
explicitly. Thoughts?

thanks!

 - Joel

PS: Your reply also went a weird address (barclay something) on CC. Wondering
what happened. The headers in my original email seemed correct. I have
included back the CC list.

Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks

[Masami Hiramatsu]

On Thu, 14 Jun 2018 18:01:13 -0700
Joel Fernandes <joelaf@google.com> wrote:

> From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> 
> Currently, trace event triggers are called regardless of if the event
> filter checks pass or fail. Thus if one were to enable event triggers
> and filters at the same time, then the triggers will always be called
> even if the filter checks didn't pass.
> 
> This is a problem for a usecase I was experimenting with: measuring the
> time preemption is disabled using synthetic events and dump the stack
> using the stacktrace trigger if the total preempt off time was greater
> than a threshold. Following are the commands for the same:
> 
> Create synthetic event:
> 
> echo 'preemptdisable u64 lat' >> \
> 	      /sys/kernel/debug/tracing/synthetic_events
> 
> echo 'hist:keys=cpu:ts0=common_timestamp.usecs:scpu=cpu' >> \
> 	      /sys/kernel/debug/tracing/events/preemptirq/preempt_disable/trigger
> 
> echo 'hist:keys=cpu:wakeup_lat=common_timestamp.usecs-$ts0:\
> onmatch(preemptirq.preempt_disable).preemptdisable($wakeup_lat)' >> \
> 	        /sys/kernel/debug/tracing/events/preemptirq/preempt_enable/trigger
> 
> Enable synthetic event:
> 
> echo stacktrace > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
> echo 'lat > 400' > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/filter

Have you tried if statement as below?

echo "stacktrace if lat > 400" > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger

As my understanding, filter is used for controlling "recording the event"
and trigger is out of its scope. Trigger itself has own filter as
"if statement", so you should use it.

Thank you,


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks

[Joel Fernandes]

On Sat, Jun 16, 2018 at 10:43:29PM +0900, Masami Hiramatsu wrote:
> On Thu, 14 Jun 2018 18:01:13 -0700
> Joel Fernandes <joelaf@google.com> wrote:
> 
> > From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> > 
> > Currently, trace event triggers are called regardless of if the event
> > filter checks pass or fail. Thus if one were to enable event triggers
> > and filters at the same time, then the triggers will always be called
> > even if the filter checks didn't pass.
> > 
> > This is a problem for a usecase I was experimenting with: measuring the
> > time preemption is disabled using synthetic events and dump the stack
> > using the stacktrace trigger if the total preempt off time was greater
> > than a threshold. Following are the commands for the same:
> > 
> > Create synthetic event:
> > 
> > echo 'preemptdisable u64 lat' >> \
> > 	      /sys/kernel/debug/tracing/synthetic_events
> > 
> > echo 'hist:keys=cpu:ts0=common_timestamp.usecs:scpu=cpu' >> \
> > 	      /sys/kernel/debug/tracing/events/preemptirq/preempt_disable/trigger
> > 
> > echo 'hist:keys=cpu:wakeup_lat=common_timestamp.usecs-$ts0:\
> > onmatch(preemptirq.preempt_disable).preemptdisable($wakeup_lat)' >> \
> > 	        /sys/kernel/debug/tracing/events/preemptirq/preempt_enable/trigger
> > 
> > Enable synthetic event:
> > 
> > echo stacktrace > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
> > echo 'lat > 400' > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/filter
> 
> Have you tried if statement as below?
> 
> echo "stacktrace if lat > 400" > /sys/kernel/debug/tracing/events/synthetic/preemptdisable/trigger
> 

Yes I tried this and it works, thanks!

Steven also suggested the same thing in his reply as well.

thanks,

 - Joel