ftrace: Event probe updates
Masami Hiramatsu (Google)
maintainercover ftrace: Event probe updates
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]>
Masami Hiramatsu (Google)
maintainerPATCH 1/3 tracing/eprobe: Show syntax error logs in error_log file
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.
--- kernel/trace/trace_eprobe.c | 11 +++++++++-- kernel/trace/trace_probe.h | 5 ++++- 2 files changed, 13 insertions(+), 3 deletions(-)
kernel/trace/trace_eprobe.c +9 -2
@@ -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 ;
kernel/trace/trace_probe.h +4 -1
@@ -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
Masami Hiramatsu (Google)
maintainerPATCH 2/3 tracing/eprobe: Add eprobe filter support
In reply to Masami Hiramatsu (Google)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_eventsThen 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.
--- kernel/trace/trace_eprobe.c | 104 ++++++++++++++++++++++++++++++++++++++++--- kernel/trace/trace_probe.h | 3 + 2 files changed, 98 insertions(+), 9 deletions(-)
kernel/trace/trace_eprobe.c +96 -8
@@ -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++) {
kernel/trace/trace_probe.h +2 -1
@@ -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
Steven Rostedt
maintainerRe: [PATCH 2/3] tracing/eprobe: Add eprobe filter support
Quoted 6 lines · On Mon, 1 Aug 2022 11:32:25 +0900 "Masami Hiramatsu (Google)"…
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.
Quoted 8 lines
echo 'e:egroup/stat_runtime_4core sched/sched_stat_runtime \ runtime=$runtime:u32 if cpu < 4' >> ../dynamic_eventsThen 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
Re: [PATCH 2/3] tracing/eprobe: Add eprobe filter support
In reply to Masami Hiramatsu (Google)Quoted 53 lines · Masami Hiramatsu (Google)
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_eventsThen 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(-)kernel/trace/trace_eprobe.c +7
-3@@ -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 ;
kernel/trace/trace_eprobe.c new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file) · line 620
Quoted 7 lines
kernel/trace/trace_eprobe.c +3
-1@@ -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:
kernel/trace/trace_eprobe.c +0 -0
@@ -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.
Quoted 160 lines
kernel/trace/trace_eprobe.c +86
-4+ 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++) {kernel/trace/trace_probe.h +2
-1@@ -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)
maintainerRe: [PATCH 2/3] tracing/eprobe: Add eprobe filter support
Hi Rafael,
Quoted 66 lines · On Wed, 9 Nov 2022 00:33:37 -0300 Rafael Mendonca <[email protected]>…
Quoted 53 lines · Masami Hiramatsu (Google)
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_eventsThen 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(-)kernel/trace/trace_eprobe.c +7
-3@@ -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 ;kernel/trace/trace_eprobe.c new_eprobe_trigger(struct trace_eprobe *ep, struct trace_event_file *file) · line 620
Quoted 7 lines
kernel/trace/trace_eprobe.c +3
-1@@ -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:
Quoted 8 lines
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 argumentI was wondering if the
trace_event_callpassed tocreate_event_filter()shouldn't be 'ep->event' instead of 'file->event_call' as such:
Oops! Good catch!
Quoted 33 lines
kernel/trace/trace_eprobe.c +1
-1@@ -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
Quoted 1 line
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!
Quoted 161 lines
Quoted 161 lines
kernel/trace/trace_eprobe.c +86
-4+ 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++) {kernel/trace/trace_probe.h +2
-1@@ -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
Signature · 1 line
Masami Hiramatsu (Google) <[email protected]>
Masami Hiramatsu (Google)
maintainerRe: [PATCH 2/3] tracing/eprobe: Add eprobe filter support
In reply to Rafael MendoncaQuoted 26 lines · On Wed, 9 Nov 2022 00:33:37 -0300 Rafael Mendonca <[email protected]>…
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 argumentI was wondering if the
trace_event_callpassed tocreate_event_filter()shouldn't be 'ep->event' instead of 'file->event_call' as such:kernel/trace/trace_eprobe.c +1
-1@@ -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)
Quoted 1 line
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!
Quoted 180 lines
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=0I'm not familiar with the eprobe code, sorry if this is nonsense.
Quoted 160 lines
(quoted diff) +86
-4+ 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++) {kernel/trace/trace_probe.h +2
-1@@ -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
Signature · 1 line
Masami Hiramatsu (Google) <[email protected]>
Masami Hiramatsu (Google)
maintainerPATCH 3/3 selftests/ftrace: Add eprobe syntax error testcase
In reply to Masami Hiramatsu (Google)From: Masami Hiramatsu (Google) <[email protected]>
Add a syntax error test case for eprobe as same as kprobes.
--- .../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
tools/testing/selftests/ftrace/test.d/dynevent/eprobes_syntax_errors.tc new file +27 -0
@@ -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