2021-07-22 14:29:41

by Steven Rostedt

[permalink] [raw]
Subject: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

From: "Steven Rostedt (VMware)" <[email protected]>

Allow common_pid.execname to be saved in a variable in one histogram to be
passed to another histogram that can pass it as a parameter to a synthetic
event.

># echo 'hist:keys=pid:__arg__1=common_timestamp.usecs:arg2=common_pid.execname' \
> events/sched/sched_waking/trigger
># echo 'wakeup_lat s32 pid; u64 delta; char wake_comm[]' > synthetic_events
># echo 'hist:keys=next_pid:pid=next_pid,delta=common_timestamp.usecs-$__arg__1,exec=$arg2'\
':onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$delta,$exec)' \
> events/sched/sched_switch/trigger

The above is a wake up latency synthetic event setup that passes the execname
of the common_pid that woke the task to the scheduling of that task, which
triggers a synthetic event that passes the original execname as a
parameter to display it.

># echo 1 > events/synthetic/enable
># cat trace
<idle>-0 [006] d..4 186.863801: wakeup_lat: pid=1306 delta=65 wake_comm=kworker/u16:3
<idle>-0 [000] d..4 186.863858: wakeup_lat: pid=163 delta=27 wake_comm=<idle>
<idle>-0 [001] d..4 186.863903: wakeup_lat: pid=1307 delta=36 wake_comm=kworker/u16:4
<idle>-0 [000] d..4 186.863927: wakeup_lat: pid=163 delta=5 wake_comm=<idle>
<idle>-0 [006] d..4 186.863957: wakeup_lat: pid=1306 delta=24 wake_comm=kworker/u16:3
sshd-1306 [006] d..4 186.864051: wakeup_lat: pid=61 delta=62 wake_comm=<idle>
<idle>-0 [000] d..4 186.965030: wakeup_lat: pid=609 delta=18 wake_comm=<idle>
<idle>-0 [006] d..4 186.987582: wakeup_lat: pid=1306 delta=65 wake_comm=kworker/u16:3
<idle>-0 [000] d..4 186.987639: wakeup_lat: pid=163 delta=27 wake_comm=<idle>

Signed-off-by: Steven Rostedt (VMware) <[email protected]>
---
kernel/trace/trace_events_hist.c | 46 +++++++++++++++++++++++++++++---
1 file changed, 42 insertions(+), 4 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 5c9082201bc2..14b840de1326 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -1395,17 +1395,17 @@ static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
struct hist_trigger_data *hist_data = elt->map->private_data;
unsigned int size = TASK_COMM_LEN;
struct hist_elt_data *elt_data;
- struct hist_field *key_field;
+ struct hist_field *hist_field;
unsigned int i, n_str;

elt_data = kzalloc(sizeof(*elt_data), GFP_KERNEL);
if (!elt_data)
return -ENOMEM;

- for_each_hist_key_field(i, hist_data) {
- key_field = hist_data->fields[i];
+ for_each_hist_field(i, hist_data) {
+ hist_field = hist_data->fields[i];

- if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
+ if (hist_field->flags & HIST_FIELD_FL_EXECNAME) {
elt_data->comm = kzalloc(size, GFP_KERNEL);
if (!elt_data->comm) {
kfree(elt_data);
@@ -3703,6 +3703,41 @@ static int create_val_field(struct hist_trigger_data *hist_data,
return __create_val_field(hist_data, val_idx, file, NULL, field_str, 0);
}

+static const char *no_comm = "(no comm)";
+
+static u64 hist_field_execname(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ struct hist_elt_data *elt_data;
+
+ if (WARN_ON_ONCE(!elt))
+ return (u64)(unsigned long)no_comm;
+
+ elt_data = elt->private_data;
+
+ if (WARN_ON_ONCE(!elt_data->comm))
+ return (u64)(unsigned long)no_comm;
+
+ return (u64)(unsigned long)(elt_data->comm);
+}
+
+/* Convert a var that points to common_pid.execname to a string */
+static void update_var_execname(struct hist_field *hist_field)
+{
+ hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
+ HIST_FIELD_FL_EXECNAME;
+ hist_field->size = MAX_FILTER_STR_VAL;
+ hist_field->is_signed = 0;
+
+ kfree_const(hist_field->type);
+ hist_field->type = "char[]";
+
+ hist_field->fn = hist_field_execname;
+}
+
static int create_var_field(struct hist_trigger_data *hist_data,
unsigned int val_idx,
struct trace_event_file *file,
@@ -3727,6 +3762,9 @@ static int create_var_field(struct hist_trigger_data *hist_data,

ret = __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);

+ if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_EXECNAME)
+ update_var_execname(hist_data->fields[val_idx]);
+
if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_STRING)
hist_data->fields[val_idx]->var_str_idx = hist_data->n_var_str++;

--
2.30.2


2021-07-22 16:21:00

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

Hi Steve,

On Thu, 22 Jul 2021 10:27:07 -0400
Steven Rostedt <[email protected]> wrote:

> From: "Steven Rostedt (VMware)" <[email protected]>
>
> Allow common_pid.execname to be saved in a variable in one histogram to be
> passed to another histogram that can pass it as a parameter to a synthetic
> event.
>
> ># echo 'hist:keys=pid:__arg__1=common_timestamp.usecs:arg2=common_pid.execname' \
> > events/sched/sched_waking/trigger
> ># echo 'wakeup_lat s32 pid; u64 delta; char wake_comm[]' > synthetic_events
> ># echo 'hist:keys=next_pid:pid=next_pid,delta=common_timestamp.usecs-$__arg__1,exec=$arg2'\
> ':onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$delta,$exec)' \
> > events/sched/sched_switch/trigger
>
> The above is a wake up latency synthetic event setup that passes the execname
> of the common_pid that woke the task to the scheduling of that task, which
> triggers a synthetic event that passes the original execname as a
> parameter to display it.
>
> ># echo 1 > events/synthetic/enable
> ># cat trace
> <idle>-0 [006] d..4 186.863801: wakeup_lat: pid=1306 delta=65 wake_comm=kworker/u16:3
> <idle>-0 [000] d..4 186.863858: wakeup_lat: pid=163 delta=27 wake_comm=<idle>
> <idle>-0 [001] d..4 186.863903: wakeup_lat: pid=1307 delta=36 wake_comm=kworker/u16:4
> <idle>-0 [000] d..4 186.863927: wakeup_lat: pid=163 delta=5 wake_comm=<idle>
> <idle>-0 [006] d..4 186.863957: wakeup_lat: pid=1306 delta=24 wake_comm=kworker/u16:3
> sshd-1306 [006] d..4 186.864051: wakeup_lat: pid=61 delta=62 wake_comm=<idle>
> <idle>-0 [000] d..4 186.965030: wakeup_lat: pid=609 delta=18 wake_comm=<idle>
> <idle>-0 [006] d..4 186.987582: wakeup_lat: pid=1306 delta=65 wake_comm=kworker/u16:3
> <idle>-0 [000] d..4 186.987639: wakeup_lat: pid=163 delta=27 wake_comm=<idle>
>
> Signed-off-by: Steven Rostedt (VMware) <[email protected]>
> ---
> kernel/trace/trace_events_hist.c | 46 +++++++++++++++++++++++++++++---
> 1 file changed, 42 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 5c9082201bc2..14b840de1326 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -1395,17 +1395,17 @@ static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
> struct hist_trigger_data *hist_data = elt->map->private_data;
> unsigned int size = TASK_COMM_LEN;
> struct hist_elt_data *elt_data;
> - struct hist_field *key_field;
> + struct hist_field *hist_field;
> unsigned int i, n_str;
>
> elt_data = kzalloc(sizeof(*elt_data), GFP_KERNEL);
> if (!elt_data)
> return -ENOMEM;
>
> - for_each_hist_key_field(i, hist_data) {
> - key_field = hist_data->fields[i];
> + for_each_hist_field(i, hist_data) {
> + hist_field = hist_data->fields[i];
>
> - if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
> + if (hist_field->flags & HIST_FIELD_FL_EXECNAME) {
> elt_data->comm = kzalloc(size, GFP_KERNEL);
> if (!elt_data->comm) {
> kfree(elt_data);
> @@ -3703,6 +3703,41 @@ static int create_val_field(struct hist_trigger_data *hist_data,
> return __create_val_field(hist_data, val_idx, file, NULL, field_str, 0);
> }
>
> +static const char *no_comm = "(no comm)";
> +
> +static u64 hist_field_execname(struct hist_field *hist_field,
> + struct tracing_map_elt *elt,
> + struct trace_buffer *buffer,
> + struct ring_buffer_event *rbe,
> + void *event)
> +{
> + struct hist_elt_data *elt_data;
> +
> + if (WARN_ON_ONCE(!elt))
> + return (u64)(unsigned long)no_comm;
> +
> + elt_data = elt->private_data;
> +
> + if (WARN_ON_ONCE(!elt_data->comm))
> + return (u64)(unsigned long)no_comm;
> +
> + return (u64)(unsigned long)(elt_data->comm);
> +}
> +
> +/* Convert a var that points to common_pid.execname to a string */
> +static void update_var_execname(struct hist_field *hist_field)
> +{
> + hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
> + HIST_FIELD_FL_EXECNAME;
> + hist_field->size = MAX_FILTER_STR_VAL;
> + hist_field->is_signed = 0;
> +
> + kfree_const(hist_field->type);
> + hist_field->type = "char[]";
> +
> + hist_field->fn = hist_field_execname;
> +}

Hmm, this is a bit ad-hoc.

Can't this be done in the create_hist_field()? If you check 'var_name' and
flags & HIST_FIELD_FL_EXECNAME, you can do the same thing I think.

Thank you,

> +
> static int create_var_field(struct hist_trigger_data *hist_data,
> unsigned int val_idx,
> struct trace_event_file *file,
> @@ -3727,6 +3762,9 @@ static int create_var_field(struct hist_trigger_data *hist_data,
>
> ret = __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);
>
> + if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_EXECNAME)
> + update_var_execname(hist_data->fields[val_idx]);
> +
> if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_STRING)
> hist_data->fields[val_idx]->var_str_idx = hist_data->n_var_str++;
>
> --
> 2.30.2


--
Masami Hiramatsu <[email protected]>

2021-07-22 16:33:53

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Fri, 23 Jul 2021 01:19:35 +0900
Masami Hiramatsu <[email protected]> wrote:

> > +/* Convert a var that points to common_pid.execname to a string */
> > +static void update_var_execname(struct hist_field *hist_field)
> > +{
> > + hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
> > + HIST_FIELD_FL_EXECNAME;
> > + hist_field->size = MAX_FILTER_STR_VAL;
> > + hist_field->is_signed = 0;
> > +
> > + kfree_const(hist_field->type);
> > + hist_field->type = "char[]";
> > +
> > + hist_field->fn = hist_field_execname;
> > +}
>
> Hmm, this is a bit ad-hoc.
>
> Can't this be done in the create_hist_field()? If you check 'var_name' and
> flags & HIST_FIELD_FL_EXECNAME, you can do the same thing I think.

Hi Masami,

I originally tried that, but then found that it converted the pid over
to it as well. So this must be done only for vars, and not only that, it
needs to be done in a single place, because I was spending hours
debugging it.

I found this to be the least intrusive solution.

Maybe Tom has a better idea, but I don't have any more time to work on
it, and I really want this feature for the next merge window.

If you can make it work, and have time to play with it, I'm happy to
take an alternative :-)

-- Steve

2021-07-22 22:11:49

by Tom Zanussi

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

Hi Steve,

On Thu, 2021-07-22 at 10:27 -0400, Steven Rostedt wrote:
> From: "Steven Rostedt (VMware)" <[email protected]>
>
> Allow common_pid.execname to be saved in a variable in one histogram
> to be
> passed to another histogram that can pass it as a parameter to a
> synthetic
> event.
>
> ># echo
> 'hist:keys=pid:__arg__1=common_timestamp.usecs:arg2=common_pid.execna
> me' \
> > events/sched/sched_waking/trigger
> ># echo 'wakeup_lat s32 pid; u64 delta; char wake_comm[]' >
> synthetic_events
> ># echo
> 'hist:keys=next_pid:pid=next_pid,delta=common_timestamp.usecs-
> $__arg__1,exec=$arg2'\
> ':onmatch(sched.sched_waking).trace(wakeup_lat,$pid,$delta,$exec)' \
> > events/sched/sched_switch/trigger
>
> The above is a wake up latency synthetic event setup that passes the
> execname
> of the common_pid that woke the task to the scheduling of that task,
> which
> triggers a synthetic event that passes the original execname as a
> parameter to display it.
>
> ># echo 1 > events/synthetic/enable
> ># cat trace
> <idle>-0 [006] d..4 186.863801: wakeup_lat: pid=1306
> delta=65 wake_comm=kworker/u16:3
> <idle>-0 [000] d..4 186.863858: wakeup_lat: pid=163
> delta=27 wake_comm=<idle>
> <idle>-0 [001] d..4 186.863903: wakeup_lat: pid=1307
> delta=36 wake_comm=kworker/u16:4
> <idle>-0 [000] d..4 186.863927: wakeup_lat: pid=163
> delta=5 wake_comm=<idle>
> <idle>-0 [006] d..4 186.863957: wakeup_lat: pid=1306
> delta=24 wake_comm=kworker/u16:3
> sshd-1306 [006] d..4 186.864051: wakeup_lat: pid=61
> delta=62 wake_comm=<idle>
> <idle>-0 [000] d..4 186.965030: wakeup_lat: pid=609
> delta=18 wake_comm=<idle>
> <idle>-0 [006] d..4 186.987582: wakeup_lat: pid=1306
> delta=65 wake_comm=kworker/u16:3
> <idle>-0 [000] d..4 186.987639: wakeup_lat: pid=163
> delta=27 wake_comm=<idle>
>
> Signed-off-by: Steven Rostedt (VMware) <[email protected]>
> ---
> kernel/trace/trace_events_hist.c | 46 +++++++++++++++++++++++++++++-
> --
> 1 file changed, 42 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/trace/trace_events_hist.c
> b/kernel/trace/trace_events_hist.c
> index 5c9082201bc2..14b840de1326 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -1395,17 +1395,17 @@ static int hist_trigger_elt_data_alloc(struct
> tracing_map_elt *elt)
> struct hist_trigger_data *hist_data = elt->map->private_data;
> unsigned int size = TASK_COMM_LEN;
> struct hist_elt_data *elt_data;
> - struct hist_field *key_field;
> + struct hist_field *hist_field;
> unsigned int i, n_str;
>
> elt_data = kzalloc(sizeof(*elt_data), GFP_KERNEL);
> if (!elt_data)
> return -ENOMEM;
>
> - for_each_hist_key_field(i, hist_data) {
> - key_field = hist_data->fields[i];
> + for_each_hist_field(i, hist_data) {
> + hist_field = hist_data->fields[i];
>
> - if (key_field->flags & HIST_FIELD_FL_EXECNAME) {
> + if (hist_field->flags & HIST_FIELD_FL_EXECNAME) {
> elt_data->comm = kzalloc(size, GFP_KERNEL);
> if (!elt_data->comm) {
> kfree(elt_data);
> @@ -3703,6 +3703,41 @@ static int create_val_field(struct
> hist_trigger_data *hist_data,
> return __create_val_field(hist_data, val_idx, file, NULL,
> field_str, 0);
> }
>
> +static const char *no_comm = "(no comm)";
> +
> +static u64 hist_field_execname(struct hist_field *hist_field,
> + struct tracing_map_elt *elt,
> + struct trace_buffer *buffer,
> + struct ring_buffer_event *rbe,
> + void *event)
> +{
> + struct hist_elt_data *elt_data;
> +
> + if (WARN_ON_ONCE(!elt))
> + return (u64)(unsigned long)no_comm;
> +
> + elt_data = elt->private_data;
> +
> + if (WARN_ON_ONCE(!elt_data->comm))
> + return (u64)(unsigned long)no_comm;
> +
> + return (u64)(unsigned long)(elt_data->comm);
> +}
> +
> +/* Convert a var that points to common_pid.execname to a string */
> +static void update_var_execname(struct hist_field *hist_field)
> +{
> + hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
> + HIST_FIELD_FL_EXECNAME;
> + hist_field->size = MAX_FILTER_STR_VAL;
> + hist_field->is_signed = 0;
> +
> + kfree_const(hist_field->type);
> + hist_field->type = "char[]";
> +
> + hist_field->fn = hist_field_execname;
> +}
> +
> static int create_var_field(struct hist_trigger_data *hist_data,
> unsigned int val_idx,
> struct trace_event_file *file,
> @@ -3727,6 +3762,9 @@ static int create_var_field(struct
> hist_trigger_data *hist_data,
>
> ret = __create_val_field(hist_data, val_idx, file, var_name,
> expr_str, flags);
>
> + if (!ret && hist_data->fields[val_idx]->flags &
> HIST_FIELD_FL_EXECNAME)
> + update_var_execname(hist_data->fields[val_idx]);
> +
> if (!ret && hist_data->fields[val_idx]->flags &
> HIST_FIELD_FL_STRING)
> hist_data->fields[val_idx]->var_str_idx = hist_data-
> >n_var_str++;
>

Yeah, the common_pid.execname thing is kind of a strange beast, and I
think this is actually a nice and reasonable way to deal with it for
this case.

Thanks,

Reviewed-by: <[email protected]>


2021-07-23 01:15:05

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Thu, 22 Jul 2021 12:32:34 -0400
Steven Rostedt <[email protected]> wrote:

> On Fri, 23 Jul 2021 01:19:35 +0900
> Masami Hiramatsu <[email protected]> wrote:
>
> > > +/* Convert a var that points to common_pid.execname to a string */
> > > +static void update_var_execname(struct hist_field *hist_field)
> > > +{
> > > + hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
> > > + HIST_FIELD_FL_EXECNAME;
> > > + hist_field->size = MAX_FILTER_STR_VAL;
> > > + hist_field->is_signed = 0;
> > > +
> > > + kfree_const(hist_field->type);
> > > + hist_field->type = "char[]";
> > > +
> > > + hist_field->fn = hist_field_execname;
> > > +}
> >
> > Hmm, this is a bit ad-hoc.
> >
> > Can't this be done in the create_hist_field()? If you check 'var_name' and
> > flags & HIST_FIELD_FL_EXECNAME, you can do the same thing I think.
>
> Hi Masami,
>
> I originally tried that, but then found that it converted the pid over
> to it as well. So this must be done only for vars, and not only that, it
> needs to be done in a single place, because I was spending hours
> debugging it.

I understand. As far as I can see the code, it looks a bit complicated.
To simplify it, I need to understand the spec for "hist_field"
for keys and for vars. And maybe need to split both case.

> I found this to be the least intrusive solution.
>
> Maybe Tom has a better idea, but I don't have any more time to work on
> it, and I really want this feature for the next merge window.
>
> If you can make it work, and have time to play with it, I'm happy to
> take an alternative :-)

Me neither at least this moment, need more investigation. Let me try.

Thank you,

--
Masami Hiramatsu <[email protected]>

2021-07-23 01:24:47

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Fri, 23 Jul 2021 10:11:33 +0900
Masami Hiramatsu <[email protected]> wrote:

> On Thu, 22 Jul 2021 12:32:34 -0400
> Steven Rostedt <[email protected]> wrote:
>
> > On Fri, 23 Jul 2021 01:19:35 +0900
> > Masami Hiramatsu <[email protected]> wrote:
> >
> > > > +/* Convert a var that points to common_pid.execname to a string */
> > > > +static void update_var_execname(struct hist_field *hist_field)
> > > > +{
> > > > + hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
> > > > + HIST_FIELD_FL_EXECNAME;
> > > > + hist_field->size = MAX_FILTER_STR_VAL;
> > > > + hist_field->is_signed = 0;
> > > > +
> > > > + kfree_const(hist_field->type);
> > > > + hist_field->type = "char[]";
> > > > +
> > > > + hist_field->fn = hist_field_execname;
> > > > +}
> > >
> > > Hmm, this is a bit ad-hoc.
> > >
> > > Can't this be done in the create_hist_field()? If you check 'var_name' and
> > > flags & HIST_FIELD_FL_EXECNAME, you can do the same thing I think.
> >
> > Hi Masami,
> >
> > I originally tried that, but then found that it converted the pid over
> > to it as well. So this must be done only for vars, and not only that, it
> > needs to be done in a single place, because I was spending hours
> > debugging it.
>
> I understand. As far as I can see the code, it looks a bit complicated.
> To simplify it, I need to understand the spec for "hist_field"
> for keys and for vars. And maybe need to split both case.
>
> > I found this to be the least intrusive solution.
> >
> > Maybe Tom has a better idea, but I don't have any more time to work on
> > it, and I really want this feature for the next merge window.
> >
> > If you can make it work, and have time to play with it, I'm happy to
> > take an alternative :-)
>
> Me neither at least this moment, need more investigation. Let me try.

But anyway, maybe I need this weekend to make a time.
So, as far as it works OK, I'm OK for this patch.

Reviewed-by: Masami Hiramatsu <[email protected]>

BTW, please update the ftracetest testcases for hist triggers.

Thank you,


--
Masami Hiramatsu <[email protected]>

2021-07-23 01:28:32

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Fri, 23 Jul 2021 10:22:11 +0900
Masami Hiramatsu <[email protected]> wrote:

> But anyway, maybe I need this weekend to make a time.
> So, as far as it works OK, I'm OK for this patch.
>
> Reviewed-by: Masami Hiramatsu <[email protected]>

Thanks! I'll probably wont apply it till next week anyway because I'm
currently debugging other issues :-p

>
> BTW, please update the ftracetest testcases for hist triggers.

Will do!

Thanks for the review.

-- Steve

2021-07-23 01:28:41

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Fri, 23 Jul 2021 10:11:33 +0900
Masami Hiramatsu <[email protected]> wrote:

> I understand. As far as I can see the code, it looks a bit complicated.
> To simplify it, I need to understand the spec for "hist_field"
> for keys and for vars. And maybe need to split both case.

I'll give you a hint that took me a bit to figure out.

1) The execname is saved at the start of the histogram and not by one
of the ->fn() functions.

It's saved by hist_trigger_elt_data_init() if the elt_data->comm is
allocated. That function is part of the "tracing_map_ops" which gets
assigned by tracing_map_create() (in tracing_map.c) as the "elt_init"
function, which is called when getting a new elt element by
get_free_elt().

2) That elt_data->comm is only allocated if it finds a "hist_field"
that has HIST_FIELD_FL_EXECNAME flag set. It currently only looks for
that flag in the "keys" fields, which means that .execname is useless
for everything else. This patch changed it to search all hist_fields so
that it can find that flag if a variable has it set (which I added).

>
> > I found this to be the least intrusive solution.
> >
> > Maybe Tom has a better idea, but I don't have any more time to work on
> > it, and I really want this feature for the next merge window.
> >
> > If you can make it work, and have time to play with it, I'm happy to
> > take an alternative :-)
>
> Me neither at least this moment, need more investigation. Let me try.

Great! I can hold off on adding this. Or I can add it, and if you come
up with a better solution, we can just swap it.

-- Steve

2021-07-24 10:33:35

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

Hi Steve,

On Thu, 22 Jul 2021 21:24:38 -0400
Steven Rostedt <[email protected]> wrote:

> On Fri, 23 Jul 2021 10:11:33 +0900
> Masami Hiramatsu <[email protected]> wrote:
>
> > I understand. As far as I can see the code, it looks a bit complicated.
> > To simplify it, I need to understand the spec for "hist_field"
> > for keys and for vars. And maybe need to split both case.
>
> I'll give you a hint that took me a bit to figure out.
>
> 1) The execname is saved at the start of the histogram and not by one
> of the ->fn() functions.
>
> It's saved by hist_trigger_elt_data_init() if the elt_data->comm is
> allocated. That function is part of the "tracing_map_ops" which gets
> assigned by tracing_map_create() (in tracing_map.c) as the "elt_init"
> function, which is called when getting a new elt element by
> get_free_elt().
>
> 2) That elt_data->comm is only allocated if it finds a "hist_field"
> that has HIST_FIELD_FL_EXECNAME flag set. It currently only looks for
> that flag in the "keys" fields, which means that .execname is useless
> for everything else. This patch changed it to search all hist_fields so
> that it can find that flag if a variable has it set (which I added).

Thanks for the hints, but actually, that part looks good to me.

So, what I pointed was the part of update_var_execname(). Below diff
is what I intended.
This moves HIST_FIELD_FL_EXECNAME setup in the create_hist_field()
as same as other flags, and removed the add-hoc update_var_execname()
fixup function.

I confirmed it passed the ftracetest trigger testcases and your
example code.

Thank you,

---
kernel/trace/trace_events_hist.c | 69 ++++++++++++++------------------
1 file changed, 31 insertions(+), 38 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 14b840de1326..2fab91a22628 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -492,6 +492,27 @@ struct snapshot_context {
void *key;
};

+static const char *no_comm = "(no comm)";
+
+static u64 hist_field_execname(struct hist_field *hist_field,
+ struct tracing_map_elt *elt,
+ struct trace_buffer *buffer,
+ struct ring_buffer_event *rbe,
+ void *event)
+{
+ struct hist_elt_data *elt_data;
+
+ if (WARN_ON_ONCE(!elt))
+ return (u64)(unsigned long)no_comm;
+
+ elt_data = elt->private_data;
+
+ if (WARN_ON_ONCE(!elt_data->comm))
+ return (u64)(unsigned long)no_comm;
+
+ return (u64)(unsigned long)(elt_data->comm);
+}
+
static void track_data_free(struct track_data *track_data)
{
struct hist_elt_data *elt_data;
@@ -1682,6 +1703,16 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
goto out;
}

+ if ((flags & HIST_FIELD_FL_EXECNAME) && var_name) {
+ flags |= HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR;
+ hist_field->size = MAX_FILTER_STR_VAL;
+ hist_field->is_signed = 0;
+
+ hist_field->type = "char[]";
+ hist_field->fn = hist_field_execname;
+ goto out;
+ }
+
if (WARN_ON_ONCE(!field))
goto out;

@@ -3703,41 +3734,6 @@ static int create_val_field(struct hist_trigger_data *hist_data,
return __create_val_field(hist_data, val_idx, file, NULL, field_str, 0);
}

-static const char *no_comm = "(no comm)";
-
-static u64 hist_field_execname(struct hist_field *hist_field,
- struct tracing_map_elt *elt,
- struct trace_buffer *buffer,
- struct ring_buffer_event *rbe,
- void *event)
-{
- struct hist_elt_data *elt_data;
-
- if (WARN_ON_ONCE(!elt))
- return (u64)(unsigned long)no_comm;
-
- elt_data = elt->private_data;
-
- if (WARN_ON_ONCE(!elt_data->comm))
- return (u64)(unsigned long)no_comm;
-
- return (u64)(unsigned long)(elt_data->comm);
-}
-
-/* Convert a var that points to common_pid.execname to a string */
-static void update_var_execname(struct hist_field *hist_field)
-{
- hist_field->flags = HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR |
- HIST_FIELD_FL_EXECNAME;
- hist_field->size = MAX_FILTER_STR_VAL;
- hist_field->is_signed = 0;
-
- kfree_const(hist_field->type);
- hist_field->type = "char[]";
-
- hist_field->fn = hist_field_execname;
-}
-
static int create_var_field(struct hist_trigger_data *hist_data,
unsigned int val_idx,
struct trace_event_file *file,
@@ -3762,9 +3758,6 @@ static int create_var_field(struct hist_trigger_data *hist_data,

ret = __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags);

- if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_EXECNAME)
- update_var_execname(hist_data->fields[val_idx]);
-
if (!ret && hist_data->fields[val_idx]->flags & HIST_FIELD_FL_STRING)
hist_data->fields[val_idx]->var_str_idx = hist_data->n_var_str++;

--
2.25.1



--
Masami Hiramatsu <[email protected]>

2021-07-25 02:20:37

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

Hi,

On Sat, 24 Jul 2021 19:31:45 +0900
Masami Hiramatsu <[email protected]> wrote:

> Hi Steve,
>
> On Thu, 22 Jul 2021 21:24:38 -0400
> Steven Rostedt <[email protected]> wrote:
>
> > On Fri, 23 Jul 2021 10:11:33 +0900
> > Masami Hiramatsu <[email protected]> wrote:
> >
> > > I understand. As far as I can see the code, it looks a bit complicated.
> > > To simplify it, I need to understand the spec for "hist_field"
> > > for keys and for vars. And maybe need to split both case.
> >
> > I'll give you a hint that took me a bit to figure out.
> >
> > 1) The execname is saved at the start of the histogram and not by one
> > of the ->fn() functions.
> >
> > It's saved by hist_trigger_elt_data_init() if the elt_data->comm is
> > allocated. That function is part of the "tracing_map_ops" which gets
> > assigned by tracing_map_create() (in tracing_map.c) as the "elt_init"
> > function, which is called when getting a new elt element by
> > get_free_elt().
> >
> > 2) That elt_data->comm is only allocated if it finds a "hist_field"
> > that has HIST_FIELD_FL_EXECNAME flag set. It currently only looks for
> > that flag in the "keys" fields, which means that .execname is useless
> > for everything else. This patch changed it to search all hist_fields so
> > that it can find that flag if a variable has it set (which I added).
>
> Thanks for the hints, but actually, that part looks good to me.
>
> So, what I pointed was the part of update_var_execname(). Below diff
> is what I intended.
> This moves HIST_FIELD_FL_EXECNAME setup in the create_hist_field()
> as same as other flags, and removed the add-hoc update_var_execname()
> fixup function.
>
> I confirmed it passed the ftracetest trigger testcases and your
> example code.
>
> Thank you,
>

I found a bug in this change.

[..]
> @@ -1682,6 +1703,16 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
> goto out;
> }
>
> + if ((flags & HIST_FIELD_FL_EXECNAME) && var_name) {
> + flags |= HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR;

Here, we don't need to check 'var_name' and remove HIST_FIELD_FL_VAR, since it must be set in the flag.

if (flags & HIST_FIELD_FL_EXECNAME) {
flags |= HIST_FIELD_FL_STRING;


> + hist_field->size = MAX_FILTER_STR_VAL;
> + hist_field->is_signed = 0;
> +
> + hist_field->type = "char[]";
> + hist_field->fn = hist_field_execname;
> + goto out;
> + }
> +



Thank you,


--
Masami Hiramatsu <[email protected]>

2021-07-25 03:47:43

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Sun, 25 Jul 2021 11:18:30 +0900
Masami Hiramatsu <[email protected]> wrote:

> Hi,
>
> On Sat, 24 Jul 2021 19:31:45 +0900
> Masami Hiramatsu <[email protected]> wrote:
>
> > Hi Steve,
> >
> > On Thu, 22 Jul 2021 21:24:38 -0400
> > Steven Rostedt <[email protected]> wrote:
> >
> > > On Fri, 23 Jul 2021 10:11:33 +0900
> > > Masami Hiramatsu <[email protected]> wrote:
> > >
> > > > I understand. As far as I can see the code, it looks a bit complicated.
> > > > To simplify it, I need to understand the spec for "hist_field"
> > > > for keys and for vars. And maybe need to split both case.
> > >
> > > I'll give you a hint that took me a bit to figure out.
> > >
> > > 1) The execname is saved at the start of the histogram and not by one
> > > of the ->fn() functions.
> > >
> > > It's saved by hist_trigger_elt_data_init() if the elt_data->comm is
> > > allocated. That function is part of the "tracing_map_ops" which gets
> > > assigned by tracing_map_create() (in tracing_map.c) as the "elt_init"
> > > function, which is called when getting a new elt element by
> > > get_free_elt().
> > >
> > > 2) That elt_data->comm is only allocated if it finds a "hist_field"
> > > that has HIST_FIELD_FL_EXECNAME flag set. It currently only looks for
> > > that flag in the "keys" fields, which means that .execname is useless
> > > for everything else. This patch changed it to search all hist_fields so
> > > that it can find that flag if a variable has it set (which I added).
> >
> > Thanks for the hints, but actually, that part looks good to me.
> >
> > So, what I pointed was the part of update_var_execname(). Below diff
> > is what I intended.
> > This moves HIST_FIELD_FL_EXECNAME setup in the create_hist_field()
> > as same as other flags, and removed the add-hoc update_var_execname()
> > fixup function.
> >
> > I confirmed it passed the ftracetest trigger testcases and your
> > example code.
> >
> > Thank you,
> >
>
> I found a bug in this change.
>
> [..]
> > @@ -1682,6 +1703,16 @@ static struct hist_field *create_hist_field(struct hist_trigger_data *hist_data,
> > goto out;
> > }
> >
> > + if ((flags & HIST_FIELD_FL_EXECNAME) && var_name) {
> > + flags |= HIST_FIELD_FL_STRING | HIST_FIELD_FL_VAR;
>
> Here, we don't need to check 'var_name' and remove HIST_FIELD_FL_VAR, since it must be set in the flag.
>
> if (flags & HIST_FIELD_FL_EXECNAME) {
> flags |= HIST_FIELD_FL_STRING;

And with this change, hist trigger can correctly detect a string type in
the operand in the expression and rejects it.

Thank you,

From 5280d1efe4415a621cf69a1dc4861ab928b0ff1c Mon Sep 17 00:00:00 2001
From: Masami Hiramatsu <[email protected]>
Date: Sun, 25 Jul 2021 12:34:00 +0900
Subject: [PATCH] tracing: Reject string operand in the histogram expression

Since the string type can not be the target of the addition / subtraction
operation, it must be rejected. Without this fix, the string type silently
converted to digits.

Signed-off-by: Masami Hiramatsu <[email protected]>
---
kernel/trace/trace_events_hist.c | 20 +++++++++++++++++++-
1 file changed, 19 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 76e3100a4840..3eea60e2da48 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -65,7 +65,8 @@
C(INVALID_SORT_MODIFIER,"Invalid sort modifier"), \
C(EMPTY_SORT_FIELD, "Empty sort field"), \
C(TOO_MANY_SORT_FIELDS, "Too many sort fields (Max = 2)"), \
- C(INVALID_SORT_FIELD, "Sort field must be a key or a val"),
+ C(INVALID_SORT_FIELD, "Sort field must be a key or a val"), \
+ C(INVALID_STR_OPERAND, "String type can not be an operand in expression"),

#undef C
#define C(a, b) HIST_ERR_##a
@@ -2183,6 +2184,13 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
ret = PTR_ERR(operand1);
goto free;
}
+ if (operand1->flags & HIST_FIELD_FL_STRING) {
+ /* String type can not be the operand of unary operator. */
+ hist_err(file->tr, HIST_ERR_INVALID_STR_OPERAND, errpos(str));
+ destroy_hist_field(operand1, 0);
+ ret = -EINVAL;
+ goto free;
+ }

expr->flags |= operand1->flags &
(HIST_FIELD_FL_TIMESTAMP | HIST_FIELD_FL_TIMESTAMP_USECS);
@@ -2284,6 +2292,11 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
operand1 = NULL;
goto free;
}
+ if (operand1->flags & HIST_FIELD_FL_STRING) {
+ hist_err(file->tr, HIST_ERR_INVALID_STR_OPERAND, errpos(operand1_str));
+ ret = -EINVAL;
+ goto free;
+ }

/* rest of string could be another expression e.g. b+c in a+b+c */
operand_flags = 0;
@@ -2293,6 +2306,11 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
operand2 = NULL;
goto free;
}
+ if (operand2->flags & HIST_FIELD_FL_STRING) {
+ hist_err(file->tr, HIST_ERR_INVALID_STR_OPERAND, errpos(str));
+ ret = -EINVAL;
+ goto free;
+ }

ret = check_expr_operands(file->tr, operand1, operand2);
if (ret)
--
2.25.1



--
Masami Hiramatsu <[email protected]>

2021-07-26 13:29:47

by Steven Rostedt

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Sun, 25 Jul 2021 12:45:02 +0900
Masami Hiramatsu <[email protected]> wrote:

> And with this change, hist trigger can correctly detect a string type in
> the operand in the expression and rejects it.
>
> Thank you,
>
> >From 5280d1efe4415a621cf69a1dc4861ab928b0ff1c Mon Sep 17 00:00:00 2001
> From: Masami Hiramatsu <[email protected]>
> Date: Sun, 25 Jul 2021 12:34:00 +0900
> Subject: [PATCH] tracing: Reject string operand in the histogram expression
>
> Since the string type can not be the target of the addition / subtraction
> operation, it must be rejected. Without this fix, the string type silently
> converted to digits.

Masami, can you send this as a normal patch. My scripts do not work
(nor do I plan on having them ever do so) with patches embedded in
threads or non-patch emails.

Thanks,

-- Steve

2021-07-27 22:56:38

by Masami Hiramatsu

[permalink] [raw]
Subject: Re: [PATCH v2 2/2] tracing: Allow execnames to be passed as args for synthetic events

On Mon, 26 Jul 2021 09:28:18 -0400
Steven Rostedt <[email protected]> wrote:

> On Sun, 25 Jul 2021 12:45:02 +0900
> Masami Hiramatsu <[email protected]> wrote:
>
> > And with this change, hist trigger can correctly detect a string type in
> > the operand in the expression and rejects it.
> >
> > Thank you,
> >
> > >From 5280d1efe4415a621cf69a1dc4861ab928b0ff1c Mon Sep 17 00:00:00 2001
> > From: Masami Hiramatsu <[email protected]>
> > Date: Sun, 25 Jul 2021 12:34:00 +0900
> > Subject: [PATCH] tracing: Reject string operand in the histogram expression
> >
> > Since the string type can not be the target of the addition / subtraction
> > operation, it must be rejected. Without this fix, the string type silently
> > converted to digits.
>
> Masami, can you send this as a normal patch. My scripts do not work
> (nor do I plan on having them ever do so) with patches embedded in
> threads or non-patch emails.

OK, let me resend it.

Thanks,

--
Masami Hiramatsu <[email protected]>