Re: [PATCH 24/32] tracing: Add 'onmax' hist trigger action support

[Namhyung Kim <namhyung@kernel.org>]

On Mon, Jun 26, 2017 at 05:49:25PM -0500, Tom Zanussi wrote:
> Add an 'onmax(var).save(field,...)' hist trigger action which is
> invoked whenever an event exceeds the current maximum.
> 
> The end result is that the trace event fields or variables specified
> as the onmax.save() params will be saved if 'var' exceeds the current
> maximum for that hist trigger entry.  This allows context from the
> event that exhibited the new maximum to be saved for later reference.
> When the histogram is displayed, additional fields displaying the
> saved values will be printed.
> 
> As an example the below defines a couple of hist triggers, one for
> sched_wakeup and another for sched_switch, keyed on pid.  Whenever a
> sched_wakeup occurs, the timestamp is saved in the entry corresponding
> to the current pid, and when the scheduler switches back to that pid,
> the timestamp difference is calculated.  If the resulting latency
> exceeds the current maximum latency, the specified save() values are
> saved:
> 
>     # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
>         if comm=="cyclictest"' >> \
>       /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
> 
>     # echo 'hist:keys=next_pid:\
>       wakeup_lat=common_timestamp.usecs-$ts0:\
>       onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \
>         if next_comm=="cyclictest"' >> \
>       /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
> 
> When the histogram is displayed, the max value and the saved values
> corresponding to the max are displayed following the rest of the
> fields:
> 
>     # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
>       { next_pid:       2255 } hitcount:        239 \
>         common_timestamp-$ts0:          0

What is this, wakeup_lat?  If so, it'd be better showing the variable name.


>         max:         27  next_comm: cyclictest \
>         prev_pid:          0  prev_prio:        120  prev_comm: swapper/1 \
>       { next_pid:       2256 } hitcount:       2355  common_timestamp-$ts0: 0 \
>       	max:         49  next_comm: cyclictest \
>         prev_pid:          0  prev_prio:        120  prev_comm: swapper/0
> 
>     Totals:
>         Hits: 12970

Why total hits is different than the sum of two?

>         Entries: 2
>         Dropped: 0
> 
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
>  kernel/trace/trace_events_hist.c | 310 ++++++++++++++++++++++++++++++++++-----
>  1 file changed, 276 insertions(+), 34 deletions(-)
> 
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index b1f859c..d191f1a 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -282,6 +282,10 @@ struct hist_trigger_data {
>  	unsigned int			n_field_var_str;
>  	struct field_var_hist		*field_var_hists[SYNTH_FIELDS_MAX];
>  	unsigned int			n_field_var_hists;
> +
> +	struct field_var		*max_vars[SYNTH_FIELDS_MAX];
> +	unsigned int			n_max_vars;
> +	unsigned int			n_max_var_str;
>  };
>  
>  struct synth_field {
> @@ -318,6 +322,12 @@ struct action_data {
>  	char			*match_event_system;
>  	char			*synth_event_name;
>  	struct synth_event	*synth_event;
> +
> +	char			*onmax_var_str;
> +	char			*onmax_fn_name;
> +	unsigned int		max_var_ref_idx;
> +	struct hist_field	*max_var;
> +	struct hist_field	*onmax_var;

Couldn't it be a union?

>  };

[SNIP]
> @@ -2613,6 +2633,222 @@ static struct field_var *create_field_var(struct hist_trigger_data *hist_data,
>  	return create_field_var(hist_data, file, var_name);
>  }
>  
> +static void onmax_print(struct seq_file *m,
> +			struct hist_trigger_data *hist_data,
> +			struct tracing_map_elt *elt,
> +			struct action_data *data)
> +{
> +	unsigned int i, save_var_idx, max_idx = data->max_var->var.idx;
> +
> +	seq_printf(m, "\n\tmax: %10llu", tracing_map_read_var(elt, max_idx));
> +
> +	for (i = 0; i < hist_data->n_max_vars; i++) {
> +		struct hist_field *save_val = hist_data->max_vars[i]->val;
> +		struct hist_field *save_var = hist_data->max_vars[i]->var;
> +		u64 val;
> +
> +		save_var_idx = save_var->var.idx;
> +
> +		val = tracing_map_read_var(elt, save_var_idx);
> +
> +		if (save_val->flags & HIST_FIELD_FL_STRING) {
> +			seq_printf(m, "  %s: %-50s", save_var->var.name,

It seems TASK_COMM_LEN is enough.  Or please define STR_VAR_LEN or
something.


> +				   (char *)(uintptr_t)(val));
> +		} else
> +			seq_printf(m, "  %s: %10llu", save_var->var.name, val);
> +	}
> +}

[SNIP]
> +static struct action_data *onmax_parse(char *str)
> +{
> +	char *onmax_fn_name, *onmax_var_str;
> +	struct action_data *data;
> +	int ret = -EINVAL;
> +
> +	data = kzalloc(sizeof(*data), GFP_KERNEL);
> +	if (!data)
> +		return ERR_PTR(-ENOMEM);
> +
> +	onmax_var_str = strsep(&str, ")");
> +	if (!onmax_var_str || !str)
> +		return ERR_PTR(-EINVAL);
> +	data->onmax_var_str = kstrdup(onmax_var_str, GFP_KERNEL);
> +
> +	strsep(&str, ".");
> +	if (!str)
> +		goto free;
> +
> +	onmax_fn_name = strsep(&str, "(");
> +	if (!onmax_fn_name || !str)
> +		goto free;
> +
> +	if (strncmp(onmax_fn_name, "save", strlen("save")) == 0) {
> +		char *params = strsep(&str, ")");
> +
> +		if (!params)
> +			goto free;
> +
> +		ret = parse_action_params(params, data);
> +		if (ret)
> +			goto free;
> +	}

Hmm.. is it ok to give a function name other than 'save'?

Thanks,
Namhyung


> +	data->onmax_fn_name = kstrdup(onmax_fn_name, GFP_KERNEL);
> +
> +	if (!data->onmax_var_str || !data->onmax_fn_name) {
> +		ret = -ENOMEM;
> +		goto free;
> +	}
> + out:
> +	return data;
> + free:
> +	onmax_destroy(data);
> +	data = ERR_PTR(ret);
> +	goto out;
> +}