This series adds some features/tests to event probe, which includes
- Add event probe syntax error logs on <tracefs>/error_log file.
- Add 'if' filter to the event probe.
- Add a syntax error test case for event probe.
'if' filter is a new feature, which allows us to define new event based on
the condition. There are some events which include both start and end
events by one event type. e.g. CPU idle (power/cpu_idle) event is called
at the CPU idle start with "state=C-state ID" and at the end with "state=(u32)-1".
In that case, it is useful if we can define 2 new event probes on it for
the start and the end besed on the state value. Or, we can classify events
based on running CPU, etc.
Thanks,
---
Masami Hiramatsu (Google) (3):
tracing/eprobe: Show syntax error logs in error_log file
tracing/eprobe: Add eprobe filter support
selftests/ftrace: Add eprobe syntax error testcase
kernel/trace/trace_eprobe.c | 115 ++++++++++++++++++--
kernel/trace/trace_probe.h | 6 +
.../test.d/dynevent/eprobes_syntax_errors.tc | 27 +++++
3 files changed, 137 insertions(+), 11 deletions(-)
create mode 100644 tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc
--
Masami Hiramatsu (Google) <[email protected]>
From: Masami Hiramatsu (Google) <[email protected]>
Show the syntax errors for event probes in error_log file as same as
other dynamic events, so that user can understand what is the problem.
Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
---
kernel/trace/trace_eprobe.c | 11 +++++++++--
kernel/trace/trace_probe.h | 5 ++++-
2 files changed, 13 insertions(+), 3 deletions(-)
diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
index a30f21499e81..4a0e9d927443 100644
--- a/kernel/trace/trace_eprobe.c
+++ b/kernel/trace/trace_eprobe.c
@@ -839,8 +839,11 @@ static int trace_eprobe_tp_update_arg(struct trace_eprobe *ep, const char *argv[
if (ret)
return ret;
- if (ep->tp.args[i].code->op == FETCH_OP_TP_ARG)
+ if (ep->tp.args[i].code->op == FETCH_OP_TP_ARG) {
ret = trace_eprobe_tp_arg_update(ep, i);
+ if (ret)
+ trace_probe_log_err(0, BAD_ATTACH_ARG);
+ }
return ret;
}
@@ -880,8 +883,10 @@ static int __trace_eprobe_create(int argc, const char *argv[])
trace_probe_log_set_index(1);
sys_event = argv[1];
ret = traceprobe_parse_event_name(&sys_event, &sys_name, buf2, 0);
- if (!sys_event || !sys_name)
+ if (!sys_event || !sys_name) {
+ trace_probe_log_err(0, NO_EVENT_INFO);
goto parse_error;
+ }
if (!event) {
strscpy(buf1, argv[1], MAX_EVENT_NAME_LEN);
@@ -896,6 +901,8 @@ static int __trace_eprobe_create(int argc, const char *argv[])
if (IS_ERR(ep)) {
ret = PTR_ERR(ep);
+ if (ret == -ENODEV)
+ trace_probe_log_err(0, BAD_ATTACH_EVENT);
/* This must return -ENOMEM or missing event, else there is a bug */
WARN_ON_ONCE(ret != -ENOMEM && ret != -ENODEV);
ep = NULL;
diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
index 92cc149af0fd..3b3869ae8cfd 100644
--- a/kernel/trace/trace_probe.h
+++ b/kernel/trace/trace_probe.h
@@ -442,7 +442,10 @@ extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
C(FAIL_REG_PROBE, "Failed to register probe event"),\
C(DIFF_PROBE_TYPE, "Probe type is different from existing probe"),\
C(DIFF_ARG_TYPE, "Argument type or name is different from existing probe"),\
- C(SAME_PROBE, "There is already the exact same probe event"),
+ C(SAME_PROBE, "There is already the exact same probe event"),\
+ C(NO_EVENT_INFO, "This requires both group and event name to attach"),\
+ C(BAD_ATTACH_EVENT, "Attached event does not exist"),\
+ C(BAD_ATTACH_ARG, "Attached event does not have this field"),
#undef C
#define C(a, b) TP_ERR_##a
From: Masami Hiramatsu (Google) <[email protected]>
Add the filter option to the event probe. This is useful if user wants
to derive a new event based on the condition of the original event.
E.g.
echo 'e:egroup/stat_runtime_4core sched/sched_stat_runtime \
runtime=$runtime:u32 if cpu < 4' >> ../dynamic_events
Then it can filter the events only on first 4 cores.
Note that the fields used for 'if' must be the fields in the original
events, not eprobe events.
Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
---
kernel/trace/trace_eprobe.c | 104 ++++++++++++++++++++++++++++++++++++++++---
kernel/trace/trace_probe.h | 3 +
2 files changed, 98 insertions(+), 9 deletions(-)
diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
index 4a0e9d927443..8b32d1a3b9c7 100644
--- a/kernel/trace/trace_eprobe.c
+++ b/kernel/trace/trace_eprobe.c
@@ -26,6 +26,9 @@ struct trace_eprobe {
/* tracepoint event */
const char *event_name;
+ /* filter string for the tracepoint */
+ char *filter_str;
+
struct trace_event_call *event;
struct dyn_event devent;
@@ -589,14 +592,15 @@ static struct event_trigger_data *
new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
{
struct event_trigger_data *trigger;
+ struct event_filter *filter = NULL;
struct eprobe_data *edata;
+ int ret;
edata = kzalloc(sizeof(*edata), GFP_KERNEL);
trigger = kzalloc(sizeof(*trigger), GFP_KERNEL);
if (!trigger || !edata) {
- kfree(edata);
- kfree(trigger);
- return ERR_PTR(-ENOMEM);
+ ret = -ENOMEM;
+ goto error;
}
trigger->flags = EVENT_TRIGGER_FL_PROBE;
@@ -611,13 +615,25 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
trigger->cmd_ops = &event_trigger_cmd;
INIT_LIST_HEAD(&trigger->list);
- RCU_INIT_POINTER(trigger->filter, NULL);
+
+ if (ep->filter_str) {
+ ret = create_event_filter(file->tr, file->event_call,
+ ep->filter_str, false, &filter);
+ if (ret)
+ goto error;
+ }
+ RCU_INIT_POINTER(trigger->filter, filter);
edata->file = file;
edata->ep = ep;
trigger->private_data = edata;
return trigger;
+error:
+ free_event_filter(filter);
+ kfree(edata);
+ kfree(trigger);
+ return ERR_PTR(ret);
}
static int enable_eprobe(struct trace_eprobe *ep,
@@ -651,6 +667,7 @@ static int disable_eprobe(struct trace_eprobe *ep,
{
struct event_trigger_data *trigger = NULL, *iter;
struct trace_event_file *file;
+ struct event_filter *filter;
struct eprobe_data *edata;
file = find_event_file(tr, ep->event_system, ep->event_name);
@@ -677,6 +694,10 @@ static int disable_eprobe(struct trace_eprobe *ep,
/* Make sure nothing is using the edata or trigger */
tracepoint_synchronize_unregister();
+ filter = rcu_access_pointer(trigger->filter);
+
+ if (filter)
+ free_event_filter(filter);
kfree(edata);
kfree(trigger);
@@ -848,12 +869,62 @@ static int trace_eprobe_tp_update_arg(struct trace_eprobe *ep, const char *argv[
return ret;
}
+static int trace_eprobe_parse_filter(struct trace_eprobe *ep, int argc, const char *argv[])
+{
+ struct event_filter *dummy;
+ int i, ret, len = 0;
+ char *p;
+
+ if (argc == 0) {
+ trace_probe_log_err(0, NO_EP_FILTER);
+ return -EINVAL;
+ }
+
+ /* Recover the filter string */
+ for (i = 0; i < argc; i++)
+ len += strlen(argv[i]) + 1;
+
+ ep->filter_str = kzalloc(len, GFP_KERNEL);
+ if (!ep->filter_str)
+ return -ENOMEM;
+
+ p = ep->filter_str;
+ for (i = 0; i < argc; i++) {
+ ret = snprintf(p, len, "%s ", argv[i]);
+ if (ret < 0)
+ goto error;
+ if (ret > len) {
+ ret = -E2BIG;
+ goto error;
+ }
+ p += ret;
+ len -= ret;
+ }
+ p[-1] = '\0';
+
+ /*
+ * Ensure the filter string can be parsed correctly. Note, this
+ * filter string is for the original event, not for the eprobe.
+ */
+ ret = create_event_filter(top_trace_array(), ep->event, ep->filter_str,
+ true, &dummy);
+ free_event_filter(dummy);
+ if (ret)
+ goto error;
+
+ return 0;
+error:
+ kfree(ep->filter_str);
+ ep->filter_str = NULL;
+ return ret;
+}
+
static int __trace_eprobe_create(int argc, const char *argv[])
{
/*
* Argument syntax:
- * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS]
- * Fetch args:
+ * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS] [if FILTER]
+ * Fetch args (no space):
* <name>=$<field>[:TYPE]
*/
const char *event = NULL, *group = EPROBE_EVENT_SYSTEM;
@@ -863,8 +934,8 @@ static int __trace_eprobe_create(int argc, const char *argv[])
char buf1[MAX_EVENT_NAME_LEN];
char buf2[MAX_EVENT_NAME_LEN];
char gbuf[MAX_EVENT_NAME_LEN];
- int ret = 0;
- int i;
+ int ret = 0, filter_idx = 0;
+ int i, filter_cnt;
if (argc < 2 || argv[0][0] != 'e')
return -ECANCELED;
@@ -894,6 +965,15 @@ static int __trace_eprobe_create(int argc, const char *argv[])
event = buf1;
}
+ for (i = 2; i < argc; i++) {
+ if (!strcmp(argv[i], "if")) {
+ filter_idx = i + 1;
+ filter_cnt = argc - filter_idx;
+ argc = i;
+ break;
+ }
+ }
+
mutex_lock(&event_mutex);
event_call = find_and_get_event(sys_name, sys_event);
ep = alloc_event_probe(group, event, event_call, argc - 2);
@@ -909,6 +989,14 @@ static int __trace_eprobe_create(int argc, const char *argv[])
goto error;
}
+ if (filter_idx) {
+ trace_probe_log_set_index(filter_idx);
+ ret = trace_eprobe_parse_filter(ep, filter_cnt, argv + filter_idx);
+ if (ret)
+ goto parse_error;
+ } else
+ ep->filter_str = NULL;
+
argc -= 2; argv += 2;
/* parse arguments */
for (i = 0; i < argc && i < MAX_TRACE_ARGS; i++) {
diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
index 3b3869ae8cfd..de38f1c03776 100644
--- a/kernel/trace/trace_probe.h
+++ b/kernel/trace/trace_probe.h
@@ -445,7 +445,8 @@ extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
C(SAME_PROBE, "There is already the exact same probe event"),\
C(NO_EVENT_INFO, "This requires both group and event name to attach"),\
C(BAD_ATTACH_EVENT, "Attached event does not exist"),\
- C(BAD_ATTACH_ARG, "Attached event does not have this field"),
+ C(BAD_ATTACH_ARG, "Attached event does not have this field"),\
+ C(NO_EP_FILTER, "No filter rule after 'if'"),
#undef C
#define C(a, b) TP_ERR_##a
From: Masami Hiramatsu (Google) <[email protected]>
Add a syntax error test case for eprobe as same as kprobes.
Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
---
.../test.d/dynevent/eprobes_syntax_errors.tc | 27 ++++++++++++++++++++
1 file changed, 27 insertions(+)
create mode 100644 tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc
diff --git a/tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc b/tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc
new file mode 100644
index 000000000000..fc1daac7f066
--- /dev/null
+++ b/tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc
@@ -0,0 +1,27 @@
+#!/bin/sh
+# SPDX-License-Identifier: GPL-2.0
+# description: Event probe event parser error log check
+# requires: dynamic_events events/syscalls/sys_enter_openat "<attached-group>.<attached-event> [<args>]":README error_log
+
+check_error() { # command-with-error-pos-by-^
+ ftrace_errlog_check 'event_probe' "$1" 'dynamic_events'
+}
+
+check_error 'e ^a.' # NO_EVENT_INFO
+check_error 'e ^.b' # NO_EVENT_INFO
+check_error 'e ^a.b' # BAD_ATTACH_EVENT
+check_error 'e syscalls/sys_enter_openat ^foo' # BAD_ATTACH_ARG
+check_error 'e:^/bar syscalls/sys_enter_openat' # NO_GROUP_NAME
+check_error 'e:^12345678901234567890123456789012345678901234567890123456789012345/bar syscalls/sys_enter_openat' # GROUP_TOO_LONG
+
+check_error 'e:^foo.1/bar syscalls/sys_enter_openat' # BAD_GROUP_NAME
+check_error 'e:^ syscalls/sys_enter_openat' # NO_EVENT_NAME
+check_error 'e:foo/^12345678901234567890123456789012345678901234567890123456789012345 syscalls/sys_enter_openat' # EVENT_TOO_LONG
+check_error 'e:foo/^bar.1 syscalls/sys_enter_openat' # BAD_EVENT_NAME
+
+check_error 'e:foo/bar syscalls/sys_enter_openat arg=^dfd' # BAD_FETCH_ARG
+check_error 'e:foo/bar syscalls/sys_enter_openat ^arg=$foo' # BAD_ATTACH_ARG
+
+check_error 'e:foo/bar syscalls/sys_enter_openat if ^' # NO_EP_FILTER
+
+exit 0
On Mon, 1 Aug 2022 11:32:25 +0900
"Masami Hiramatsu (Google)" <[email protected]> wrote:
> From: Masami Hiramatsu (Google) <[email protected]>
>
> Add the filter option to the event probe. This is useful if user wants
> to derive a new event based on the condition of the original event.
>
> E.g.
> echo 'e:egroup/stat_runtime_4core sched/sched_stat_runtime \
> runtime=$runtime:u32 if cpu < 4' >> ../dynamic_events
>
> Then it can filter the events only on first 4 cores.
> Note that the fields used for 'if' must be the fields in the original
> events, not eprobe events.
>
> Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
Hi Masami,
Thanks! But I'm not going to be able to add this for this merge window (too
late, it just opened up), because it's a new feature.
I'll take patch 1 though, as that's just a clean up, and then keep the
other two for the next merge window.
-- Steve
On Mon, Aug 01, 2022 at 11:32:25AM +0900, Masami Hiramatsu (Google) wrote:
> From: Masami Hiramatsu (Google) <[email protected]>
>
> Add the filter option to the event probe. This is useful if user wants
> to derive a new event based on the condition of the original event.
>
> E.g.
> echo 'e:egroup/stat_runtime_4core sched/sched_stat_runtime \
> runtime=$runtime:u32 if cpu < 4' >> ../dynamic_events
>
> Then it can filter the events only on first 4 cores.
> Note that the fields used for 'if' must be the fields in the original
> events, not eprobe events.
>
> Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
> ---
> kernel/trace/trace_eprobe.c | 104 ++++++++++++++++++++++++++++++++++++++++---
> kernel/trace/trace_probe.h | 3 +
> 2 files changed, 98 insertions(+), 9 deletions(-)
>
> diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
> index 4a0e9d927443..8b32d1a3b9c7 100644
> --- a/kernel/trace/trace_eprobe.c
> +++ b/kernel/trace/trace_eprobe.c
> @@ -26,6 +26,9 @@ struct trace_eprobe {
> /* tracepoint event */
> const char *event_name;
>
> + /* filter string for the tracepoint */
> + char *filter_str;
> +
> struct trace_event_call *event;
>
> struct dyn_event devent;
> @@ -589,14 +592,15 @@ static struct event_trigger_data *
> new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
> {
> struct event_trigger_data *trigger;
> + struct event_filter *filter = NULL;
> struct eprobe_data *edata;
> + int ret;
>
> edata = kzalloc(sizeof(*edata), GFP_KERNEL);
> trigger = kzalloc(sizeof(*trigger), GFP_KERNEL);
> if (!trigger || !edata) {
> - kfree(edata);
> - kfree(trigger);
> - return ERR_PTR(-ENOMEM);
> + ret = -ENOMEM;
> + goto error;
> }
>
> trigger->flags = EVENT_TRIGGER_FL_PROBE;
> @@ -611,13 +615,25 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
> trigger->cmd_ops = &event_trigger_cmd;
>
> INIT_LIST_HEAD(&trigger->list);
> - RCU_INIT_POINTER(trigger->filter, NULL);
> +
> + if (ep->filter_str) {
> + ret = create_event_filter(file->tr, file->event_call,
Hi Masami,
I was playing around with the filter option and couldn't get it to work the way
I was expecting. For example, I'm getting the following output:
root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
[ 114.551550] event trace: Could not enable event sys_enter_openat
-bash: echo: write error: Invalid argument
I was wondering if the trace_event_call passed to create_event_filter()
shouldn't be 'ep->event' instead of 'file->event_call' as such:
diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
index e888446d80fa..123d2c0a6b68 100644
--- a/kernel/trace/trace_eprobe.c
+++ b/kernel/trace/trace_eprobe.c
@@ -643,7 +643,7 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct
trace_event_file *file)
INIT_LIST_HEAD(&trigger->list);
if (ep->filter_str) {
- ret = create_event_filter(file->tr, file->event_call,
+ ret = create_event_filter(file->tr, ep->event,
ep->filter_str, false, &filter);
if (ret)
goto error;
Applying the above change seems to make it work the way I was expecting:
root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
root@localhost:/sys/kernel/tracing# tail trace
cat-241 [000] ...1. 266.498449: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
cat-242 [000] ...1. 266.977640: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
cat-242 [000] ...1. 266.979883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
bash-223 [000] ...1. 272.322714: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=577
cat-243 [000] ...1. 273.630900: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
cat-243 [000] ...1. 273.633464: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
tail-244 [000] ...1. 300.013530: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
tail-244 [000] ...1. 300.018584: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
tail-245 [000] ...1. 301.237883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
tail-245 [000] ...1. 301.243375: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
I'm not familiar with the eprobe code, sorry if this is nonsense.
> + ep->filter_str, false, &filter);
> + if (ret)
> + goto error;
> + }
> + RCU_INIT_POINTER(trigger->filter, filter);
>
> edata->file = file;
> edata->ep = ep;
> trigger->private_data = edata;
>
> return trigger;
> +error:
> + free_event_filter(filter);
> + kfree(edata);
> + kfree(trigger);
> + return ERR_PTR(ret);
> }
>
> static int enable_eprobe(struct trace_eprobe *ep,
> @@ -651,6 +667,7 @@ static int disable_eprobe(struct trace_eprobe *ep,
> {
> struct event_trigger_data *trigger = NULL, *iter;
> struct trace_event_file *file;
> + struct event_filter *filter;
> struct eprobe_data *edata;
>
> file = find_event_file(tr, ep->event_system, ep->event_name);
> @@ -677,6 +694,10 @@ static int disable_eprobe(struct trace_eprobe *ep,
> /* Make sure nothing is using the edata or trigger */
> tracepoint_synchronize_unregister();
>
> + filter = rcu_access_pointer(trigger->filter);
> +
> + if (filter)
> + free_event_filter(filter);
> kfree(edata);
> kfree(trigger);
>
> @@ -848,12 +869,62 @@ static int trace_eprobe_tp_update_arg(struct trace_eprobe *ep, const char *argv[
> return ret;
> }
>
> +static int trace_eprobe_parse_filter(struct trace_eprobe *ep, int argc, const char *argv[])
> +{
> + struct event_filter *dummy;
> + int i, ret, len = 0;
> + char *p;
> +
> + if (argc == 0) {
> + trace_probe_log_err(0, NO_EP_FILTER);
> + return -EINVAL;
> + }
> +
> + /* Recover the filter string */
> + for (i = 0; i < argc; i++)
> + len += strlen(argv[i]) + 1;
> +
> + ep->filter_str = kzalloc(len, GFP_KERNEL);
> + if (!ep->filter_str)
> + return -ENOMEM;
> +
> + p = ep->filter_str;
> + for (i = 0; i < argc; i++) {
> + ret = snprintf(p, len, "%s ", argv[i]);
> + if (ret < 0)
> + goto error;
> + if (ret > len) {
> + ret = -E2BIG;
> + goto error;
> + }
> + p += ret;
> + len -= ret;
> + }
> + p[-1] = '\0';
> +
> + /*
> + * Ensure the filter string can be parsed correctly. Note, this
> + * filter string is for the original event, not for the eprobe.
> + */
> + ret = create_event_filter(top_trace_array(), ep->event, ep->filter_str,
> + true, &dummy);
> + free_event_filter(dummy);
> + if (ret)
> + goto error;
> +
> + return 0;
> +error:
> + kfree(ep->filter_str);
> + ep->filter_str = NULL;
> + return ret;
> +}
> +
> static int __trace_eprobe_create(int argc, const char *argv[])
> {
> /*
> * Argument syntax:
> - * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS]
> - * Fetch args:
> + * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS] [if FILTER]
> + * Fetch args (no space):
> * <name>=$<field>[:TYPE]
> */
> const char *event = NULL, *group = EPROBE_EVENT_SYSTEM;
> @@ -863,8 +934,8 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> char buf1[MAX_EVENT_NAME_LEN];
> char buf2[MAX_EVENT_NAME_LEN];
> char gbuf[MAX_EVENT_NAME_LEN];
> - int ret = 0;
> - int i;
> + int ret = 0, filter_idx = 0;
> + int i, filter_cnt;
>
> if (argc < 2 || argv[0][0] != 'e')
> return -ECANCELED;
> @@ -894,6 +965,15 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> event = buf1;
> }
>
> + for (i = 2; i < argc; i++) {
> + if (!strcmp(argv[i], "if")) {
> + filter_idx = i + 1;
> + filter_cnt = argc - filter_idx;
> + argc = i;
> + break;
> + }
> + }
> +
> mutex_lock(&event_mutex);
> event_call = find_and_get_event(sys_name, sys_event);
> ep = alloc_event_probe(group, event, event_call, argc - 2);
> @@ -909,6 +989,14 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> goto error;
> }
>
> + if (filter_idx) {
> + trace_probe_log_set_index(filter_idx);
> + ret = trace_eprobe_parse_filter(ep, filter_cnt, argv + filter_idx);
> + if (ret)
> + goto parse_error;
> + } else
> + ep->filter_str = NULL;
> +
> argc -= 2; argv += 2;
> /* parse arguments */
> for (i = 0; i < argc && i < MAX_TRACE_ARGS; i++) {
> diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
> index 3b3869ae8cfd..de38f1c03776 100644
> --- a/kernel/trace/trace_probe.h
> +++ b/kernel/trace/trace_probe.h
> @@ -445,7 +445,8 @@ extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
> C(SAME_PROBE, "There is already the exact same probe event"),\
> C(NO_EVENT_INFO, "This requires both group and event name to attach"),\
> C(BAD_ATTACH_EVENT, "Attached event does not exist"),\
> - C(BAD_ATTACH_ARG, "Attached event does not have this field"),
> + C(BAD_ATTACH_ARG, "Attached event does not have this field"),\
> + C(NO_EP_FILTER, "No filter rule after 'if'"),
>
> #undef C
> #define C(a, b) TP_ERR_##a
>
Hi Rafael,
On Wed, 9 Nov 2022 00:33:37 -0300
Rafael Mendonca <[email protected]> wrote:
> On Mon, Aug 01, 2022 at 11:32:25AM +0900, Masami Hiramatsu (Google) wrote:
> > From: Masami Hiramatsu (Google) <[email protected]>
> >
> > Add the filter option to the event probe. This is useful if user wants
> > to derive a new event based on the condition of the original event.
> >
> > E.g.
> > echo 'e:egroup/stat_runtime_4core sched/sched_stat_runtime \
> > runtime=$runtime:u32 if cpu < 4' >> ../dynamic_events
> >
> > Then it can filter the events only on first 4 cores.
> > Note that the fields used for 'if' must be the fields in the original
> > events, not eprobe events.
> >
> > Signed-off-by: Masami Hiramatsu (Google) <[email protected]>
> > ---
> > kernel/trace/trace_eprobe.c | 104 ++++++++++++++++++++++++++++++++++++++++---
> > kernel/trace/trace_probe.h | 3 +
> > 2 files changed, 98 insertions(+), 9 deletions(-)
> >
> > diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
> > index 4a0e9d927443..8b32d1a3b9c7 100644
> > --- a/kernel/trace/trace_eprobe.c
> > +++ b/kernel/trace/trace_eprobe.c
> > @@ -26,6 +26,9 @@ struct trace_eprobe {
> > /* tracepoint event */
> > const char *event_name;
> >
> > + /* filter string for the tracepoint */
> > + char *filter_str;
> > +
> > struct trace_event_call *event;
> >
> > struct dyn_event devent;
> > @@ -589,14 +592,15 @@ static struct event_trigger_data *
> > new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
> > {
> > struct event_trigger_data *trigger;
> > + struct event_filter *filter = NULL;
> > struct eprobe_data *edata;
> > + int ret;
> >
> > edata = kzalloc(sizeof(*edata), GFP_KERNEL);
> > trigger = kzalloc(sizeof(*trigger), GFP_KERNEL);
> > if (!trigger || !edata) {
> > - kfree(edata);
> > - kfree(trigger);
> > - return ERR_PTR(-ENOMEM);
> > + ret = -ENOMEM;
> > + goto error;
> > }
> >
> > trigger->flags = EVENT_TRIGGER_FL_PROBE;
> > @@ -611,13 +615,25 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file)
> > trigger->cmd_ops = &event_trigger_cmd;
> >
> > INIT_LIST_HEAD(&trigger->list);
> > - RCU_INIT_POINTER(trigger->filter, NULL);
> > +
> > + if (ep->filter_str) {
> > + ret = create_event_filter(file->tr, file->event_call,
>
> Hi Masami,
> I was playing around with the filter option and couldn't get it to work the way
> I was expecting. For example, I'm getting the following output:
>
> root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
> flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
> root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
> [ 114.551550] event trace: Could not enable event sys_enter_openat
> -bash: echo: write error: Invalid argument
>
> I was wondering if the trace_event_call passed to create_event_filter()
> shouldn't be 'ep->event' instead of 'file->event_call' as such:
Oops! Good catch!
>
> diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
> index e888446d80fa..123d2c0a6b68 100644
> --- a/kernel/trace/trace_eprobe.c
> +++ b/kernel/trace/trace_eprobe.c
> @@ -643,7 +643,7 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct
> trace_event_file *file)
> INIT_LIST_HEAD(&trigger->list);
>
> if (ep->filter_str) {
> - ret = create_event_filter(file->tr, file->event_call,
> + ret = create_event_filter(file->tr, ep->event,
> ep->filter_str, false, &filter);
> if (ret)
> goto error;
>
> Applying the above change seems to make it work the way I was expecting:
>
> root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
> flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
> root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
> root@localhost:/sys/kernel/tracing# tail trace
> cat-241 [000] ...1. 266.498449: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-242 [000] ...1. 266.977640: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-242 [000] ...1. 266.979883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> bash-223 [000] ...1. 272.322714: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=577
> cat-243 [000] ...1. 273.630900: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-243 [000] ...1. 273.633464: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-244 [000] ...1. 300.013530: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-244 [000] ...1. 300.018584: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-245 [000] ...1. 301.237883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-245 [000] ...1. 301.243375: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
>
> I'm not familiar with the eprobe code, sorry if this is nonsense.
Thanks for reporting!
Let me check what I had done on this. I thought ep->event is same as
file->event_call, but it can be my fault.
Thank you!
>
> > + ep->filter_str, false, &filter);
> > + if (ret)
> > + goto error;
> > + }
> > + RCU_INIT_POINTER(trigger->filter, filter);
> >
> > edata->file = file;
> > edata->ep = ep;
> > trigger->private_data = edata;
> >
> > return trigger;
> > +error:
> > + free_event_filter(filter);
> > + kfree(edata);
> > + kfree(trigger);
> > + return ERR_PTR(ret);
> > }
> >
> > static int enable_eprobe(struct trace_eprobe *ep,
> > @@ -651,6 +667,7 @@ static int disable_eprobe(struct trace_eprobe *ep,
> > {
> > struct event_trigger_data *trigger = NULL, *iter;
> > struct trace_event_file *file;
> > + struct event_filter *filter;
> > struct eprobe_data *edata;
> >
> > file = find_event_file(tr, ep->event_system, ep->event_name);
> > @@ -677,6 +694,10 @@ static int disable_eprobe(struct trace_eprobe *ep,
> > /* Make sure nothing is using the edata or trigger */
> > tracepoint_synchronize_unregister();
> >
> > + filter = rcu_access_pointer(trigger->filter);
> > +
> > + if (filter)
> > + free_event_filter(filter);
> > kfree(edata);
> > kfree(trigger);
> >
> > @@ -848,12 +869,62 @@ static int trace_eprobe_tp_update_arg(struct trace_eprobe *ep, const char *argv[
> > return ret;
> > }
> >
> > +static int trace_eprobe_parse_filter(struct trace_eprobe *ep, int argc, const char *argv[])
> > +{
> > + struct event_filter *dummy;
> > + int i, ret, len = 0;
> > + char *p;
> > +
> > + if (argc == 0) {
> > + trace_probe_log_err(0, NO_EP_FILTER);
> > + return -EINVAL;
> > + }
> > +
> > + /* Recover the filter string */
> > + for (i = 0; i < argc; i++)
> > + len += strlen(argv[i]) + 1;
> > +
> > + ep->filter_str = kzalloc(len, GFP_KERNEL);
> > + if (!ep->filter_str)
> > + return -ENOMEM;
> > +
> > + p = ep->filter_str;
> > + for (i = 0; i < argc; i++) {
> > + ret = snprintf(p, len, "%s ", argv[i]);
> > + if (ret < 0)
> > + goto error;
> > + if (ret > len) {
> > + ret = -E2BIG;
> > + goto error;
> > + }
> > + p += ret;
> > + len -= ret;
> > + }
> > + p[-1] = '\0';
> > +
> > + /*
> > + * Ensure the filter string can be parsed correctly. Note, this
> > + * filter string is for the original event, not for the eprobe.
> > + */
> > + ret = create_event_filter(top_trace_array(), ep->event, ep->filter_str,
> > + true, &dummy);
> > + free_event_filter(dummy);
> > + if (ret)
> > + goto error;
> > +
> > + return 0;
> > +error:
> > + kfree(ep->filter_str);
> > + ep->filter_str = NULL;
> > + return ret;
> > +}
> > +
> > static int __trace_eprobe_create(int argc, const char *argv[])
> > {
> > /*
> > * Argument syntax:
> > - * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS]
> > - * Fetch args:
> > + * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS] [if FILTER]
> > + * Fetch args (no space):
> > * <name>=$<field>[:TYPE]
> > */
> > const char *event = NULL, *group = EPROBE_EVENT_SYSTEM;
> > @@ -863,8 +934,8 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > char buf1[MAX_EVENT_NAME_LEN];
> > char buf2[MAX_EVENT_NAME_LEN];
> > char gbuf[MAX_EVENT_NAME_LEN];
> > - int ret = 0;
> > - int i;
> > + int ret = 0, filter_idx = 0;
> > + int i, filter_cnt;
> >
> > if (argc < 2 || argv[0][0] != 'e')
> > return -ECANCELED;
> > @@ -894,6 +965,15 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > event = buf1;
> > }
> >
> > + for (i = 2; i < argc; i++) {
> > + if (!strcmp(argv[i], "if")) {
> > + filter_idx = i + 1;
> > + filter_cnt = argc - filter_idx;
> > + argc = i;
> > + break;
> > + }
> > + }
> > +
> > mutex_lock(&event_mutex);
> > event_call = find_and_get_event(sys_name, sys_event);
> > ep = alloc_event_probe(group, event, event_call, argc - 2);
> > @@ -909,6 +989,14 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > goto error;
> > }
> >
> > + if (filter_idx) {
> > + trace_probe_log_set_index(filter_idx);
> > + ret = trace_eprobe_parse_filter(ep, filter_cnt, argv + filter_idx);
> > + if (ret)
> > + goto parse_error;
> > + } else
> > + ep->filter_str = NULL;
> > +
> > argc -= 2; argv += 2;
> > /* parse arguments */
> > for (i = 0; i < argc && i < MAX_TRACE_ARGS; i++) {
> > diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
> > index 3b3869ae8cfd..de38f1c03776 100644
> > --- a/kernel/trace/trace_probe.h
> > +++ b/kernel/trace/trace_probe.h
> > @@ -445,7 +445,8 @@ extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
> > C(SAME_PROBE, "There is already the exact same probe event"),\
> > C(NO_EVENT_INFO, "This requires both group and event name to attach"),\
> > C(BAD_ATTACH_EVENT, "Attached event does not exist"),\
> > - C(BAD_ATTACH_ARG, "Attached event does not have this field"),
> > + C(BAD_ATTACH_ARG, "Attached event does not have this field"),\
> > + C(NO_EP_FILTER, "No filter rule after 'if'"),
> >
> > #undef C
> > #define C(a, b) TP_ERR_##a
> >
--
Masami Hiramatsu (Google) <[email protected]>
On Wed, 9 Nov 2022 00:33:37 -0300
Rafael Mendonca <[email protected]> wrote:
> Hi Masami,
> I was playing around with the filter option and couldn't get it to work the way
> I was expecting. For example, I'm getting the following output:
>
> root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
> flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
> root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
> [ 114.551550] event trace: Could not enable event sys_enter_openat
> -bash: echo: write error: Invalid argument
>
> I was wondering if the trace_event_call passed to create_event_filter()
> shouldn't be 'ep->event' instead of 'file->event_call' as such:
>
> diff --git a/kernel/trace/trace_eprobe.c b/kernel/trace/trace_eprobe.c
> index e888446d80fa..123d2c0a6b68 100644
> --- a/kernel/trace/trace_eprobe.c
> +++ b/kernel/trace/trace_eprobe.c
> @@ -643,7 +643,7 @@ new_eprobe_trigger(struct trace_eprobe *ep, struct
> trace_event_file *file)
> INIT_LIST_HEAD(&trigger->list);
>
> if (ep->filter_str) {
> - ret = create_event_filter(file->tr, file->event_call,
> + ret = create_event_filter(file->tr, ep->event,
> ep->filter_str, false, &filter);
> if (ret)
> goto error;
Ah, OK. I got it. the "file->event_call" is for the eprobe's event
itself, thus the filter doesn't work. ep->event is the event of the
original event. Thus your fix is correct.
Thank you!
>
> Applying the above change seems to make it work the way I was expecting:
>
> root@localhost:/sys/kernel/tracing# echo 'e syscalls/sys_enter_openat \
> flags_rename=$flags:u32 if flags < 1000' >> dynamic_events
> root@localhost:/sys/kernel/tracing# echo 1 > events/eprobes/sys_enter_openat/enable
> root@localhost:/sys/kernel/tracing# tail trace
> cat-241 [000] ...1. 266.498449: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-242 [000] ...1. 266.977640: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-242 [000] ...1. 266.979883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> bash-223 [000] ...1. 272.322714: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=577
> cat-243 [000] ...1. 273.630900: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> cat-243 [000] ...1. 273.633464: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-244 [000] ...1. 300.013530: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-244 [000] ...1. 300.018584: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-245 [000] ...1. 301.237883: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
> tail-245 [000] ...1. 301.243375: sys_enter_openat: (syscalls.sys_enter_openat) flags_rename=0
>
> I'm not familiar with the eprobe code, sorry if this is nonsense.
>
> > + ep->filter_str, false, &filter);
> > + if (ret)
> > + goto error;
> > + }
> > + RCU_INIT_POINTER(trigger->filter, filter);
> >
> > edata->file = file;
> > edata->ep = ep;
> > trigger->private_data = edata;
> >
> > return trigger;
> > +error:
> > + free_event_filter(filter);
> > + kfree(edata);
> > + kfree(trigger);
> > + return ERR_PTR(ret);
> > }
> >
> > static int enable_eprobe(struct trace_eprobe *ep,
> > @@ -651,6 +667,7 @@ static int disable_eprobe(struct trace_eprobe *ep,
> > {
> > struct event_trigger_data *trigger = NULL, *iter;
> > struct trace_event_file *file;
> > + struct event_filter *filter;
> > struct eprobe_data *edata;
> >
> > file = find_event_file(tr, ep->event_system, ep->event_name);
> > @@ -677,6 +694,10 @@ static int disable_eprobe(struct trace_eprobe *ep,
> > /* Make sure nothing is using the edata or trigger */
> > tracepoint_synchronize_unregister();
> >
> > + filter = rcu_access_pointer(trigger->filter);
> > +
> > + if (filter)
> > + free_event_filter(filter);
> > kfree(edata);
> > kfree(trigger);
> >
> > @@ -848,12 +869,62 @@ static int trace_eprobe_tp_update_arg(struct trace_eprobe *ep, const char *argv[
> > return ret;
> > }
> >
> > +static int trace_eprobe_parse_filter(struct trace_eprobe *ep, int argc, const char *argv[])
> > +{
> > + struct event_filter *dummy;
> > + int i, ret, len = 0;
> > + char *p;
> > +
> > + if (argc == 0) {
> > + trace_probe_log_err(0, NO_EP_FILTER);
> > + return -EINVAL;
> > + }
> > +
> > + /* Recover the filter string */
> > + for (i = 0; i < argc; i++)
> > + len += strlen(argv[i]) + 1;
> > +
> > + ep->filter_str = kzalloc(len, GFP_KERNEL);
> > + if (!ep->filter_str)
> > + return -ENOMEM;
> > +
> > + p = ep->filter_str;
> > + for (i = 0; i < argc; i++) {
> > + ret = snprintf(p, len, "%s ", argv[i]);
> > + if (ret < 0)
> > + goto error;
> > + if (ret > len) {
> > + ret = -E2BIG;
> > + goto error;
> > + }
> > + p += ret;
> > + len -= ret;
> > + }
> > + p[-1] = '\0';
> > +
> > + /*
> > + * Ensure the filter string can be parsed correctly. Note, this
> > + * filter string is for the original event, not for the eprobe.
> > + */
> > + ret = create_event_filter(top_trace_array(), ep->event, ep->filter_str,
> > + true, &dummy);
> > + free_event_filter(dummy);
> > + if (ret)
> > + goto error;
> > +
> > + return 0;
> > +error:
> > + kfree(ep->filter_str);
> > + ep->filter_str = NULL;
> > + return ret;
> > +}
> > +
> > static int __trace_eprobe_create(int argc, const char *argv[])
> > {
> > /*
> > * Argument syntax:
> > - * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS]
> > - * Fetch args:
> > + * e[:[GRP/][ENAME]] SYSTEM.EVENT [FETCHARGS] [if FILTER]
> > + * Fetch args (no space):
> > * <name>=$<field>[:TYPE]
> > */
> > const char *event = NULL, *group = EPROBE_EVENT_SYSTEM;
> > @@ -863,8 +934,8 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > char buf1[MAX_EVENT_NAME_LEN];
> > char buf2[MAX_EVENT_NAME_LEN];
> > char gbuf[MAX_EVENT_NAME_LEN];
> > - int ret = 0;
> > - int i;
> > + int ret = 0, filter_idx = 0;
> > + int i, filter_cnt;
> >
> > if (argc < 2 || argv[0][0] != 'e')
> > return -ECANCELED;
> > @@ -894,6 +965,15 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > event = buf1;
> > }
> >
> > + for (i = 2; i < argc; i++) {
> > + if (!strcmp(argv[i], "if")) {
> > + filter_idx = i + 1;
> > + filter_cnt = argc - filter_idx;
> > + argc = i;
> > + break;
> > + }
> > + }
> > +
> > mutex_lock(&event_mutex);
> > event_call = find_and_get_event(sys_name, sys_event);
> > ep = alloc_event_probe(group, event, event_call, argc - 2);
> > @@ -909,6 +989,14 @@ static int __trace_eprobe_create(int argc, const char *argv[])
> > goto error;
> > }
> >
> > + if (filter_idx) {
> > + trace_probe_log_set_index(filter_idx);
> > + ret = trace_eprobe_parse_filter(ep, filter_cnt, argv + filter_idx);
> > + if (ret)
> > + goto parse_error;
> > + } else
> > + ep->filter_str = NULL;
> > +
> > argc -= 2; argv += 2;
> > /* parse arguments */
> > for (i = 0; i < argc && i < MAX_TRACE_ARGS; i++) {
> > diff --git a/kernel/trace/trace_probe.h b/kernel/trace/trace_probe.h
> > index 3b3869ae8cfd..de38f1c03776 100644
> > --- a/kernel/trace/trace_probe.h
> > +++ b/kernel/trace/trace_probe.h
> > @@ -445,7 +445,8 @@ extern int traceprobe_define_arg_fields(struct trace_event_call *event_call,
> > C(SAME_PROBE, "There is already the exact same probe event"),\
> > C(NO_EVENT_INFO, "This requires both group and event name to attach"),\
> > C(BAD_ATTACH_EVENT, "Attached event does not exist"),\
> > - C(BAD_ATTACH_ARG, "Attached event does not have this field"),
> > + C(BAD_ATTACH_ARG, "Attached event does not have this field"),\
> > + C(NO_EP_FILTER, "No filter rule after 'if'"),
> >
> > #undef C
> > #define C(a, b) TP_ERR_##a
> >
--
Masami Hiramatsu (Google) <[email protected]>