* [PATCH RFC] tracing: Call triggers only if event passes filter checks
@ 2018-06-15 1:01 Joel Fernandes
2018-06-15 16:16 ` Steven Rostedt
2018-06-16 13:43 ` Masami Hiramatsu
0 siblings, 2 replies; 5+ messages in thread
From: Joel Fernandes @ 2018-06-15 1:01 UTC (permalink / raw)
To: linux-kernel
Cc: kernel-team, Joel Fernandes (Google),
Ingo Molnar, Steven Rostedt, tglx, mhiramat, namhyung,
mathieu.desnoyers, linux-rt-users, Tom Zanussi, peterz
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks
2018-06-15 1:01 [PATCH RFC] tracing: Call triggers only if event passes filter checks Joel Fernandes
@ 2018-06-15 16:16 ` Steven Rostedt
2018-06-15 18:18 ` Joel Fernandes
2018-06-16 13:43 ` Masami Hiramatsu
1 sibling, 1 reply; 5+ messages in thread
From: Steven Rostedt @ 2018-06-15 16:16 UTC (permalink / raw)
To: Joel Fernandes; +Cc: BarclaycardUS, linux-kernel
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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks
2018-06-15 16:16 ` Steven Rostedt
@ 2018-06-15 18:18 ` Joel Fernandes
0 siblings, 0 replies; 5+ messages in thread
From: Joel Fernandes @ 2018-06-15 18:18 UTC (permalink / raw)
To: Steven Rostedt
Cc: Joel Fernandes, kernel-team, Joel Fernandes (Google),
Ingo Molnar, Steven Rostedt, tglx, mhiramat, namhyung,
mathieu.desnoyers, linux-rt-users, Tom Zanussi, peterz,
linux-kernel
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.
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks
2018-06-15 1:01 [PATCH RFC] tracing: Call triggers only if event passes filter checks Joel Fernandes
2018-06-15 16:16 ` Steven Rostedt
@ 2018-06-16 13:43 ` Masami Hiramatsu
2018-06-18 0:15 ` Joel Fernandes
1 sibling, 1 reply; 5+ messages in thread
From: Masami Hiramatsu @ 2018-06-16 13:43 UTC (permalink / raw)
To: Joel Fernandes
Cc: linux-kernel, kernel-team, Joel Fernandes (Google),
Ingo Molnar, Steven Rostedt, tglx, mhiramat, namhyung,
mathieu.desnoyers, linux-rt-users, Tom Zanussi, peterz
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>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH RFC] tracing: Call triggers only if event passes filter checks
2018-06-16 13:43 ` Masami Hiramatsu
@ 2018-06-18 0:15 ` Joel Fernandes
0 siblings, 0 replies; 5+ messages in thread
From: Joel Fernandes @ 2018-06-18 0:15 UTC (permalink / raw)
To: Masami Hiramatsu
Cc: Joel Fernandes, linux-kernel, kernel-team, Ingo Molnar,
Steven Rostedt, tglx, namhyung, mathieu.desnoyers,
linux-rt-users, Tom Zanussi, peterz
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
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2018-06-18 0:15 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-06-15 1:01 [PATCH RFC] tracing: Call triggers only if event passes filter checks Joel Fernandes
2018-06-15 16:16 ` Steven Rostedt
2018-06-15 18:18 ` Joel Fernandes
2018-06-16 13:43 ` Masami Hiramatsu
2018-06-18 0:15 ` Joel Fernandes
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.