Re: [PATCH v6 27/37] tracing: Add 'onmax' hist trigger action support

[Tom Zanussi <tom.zanussi@linux.intel.com>]

Hi Namhyung,

Sorry for the delayed response - was out on vacation..

On Thu, 2017-11-23 at 14:09 +0900, Namhyung Kim wrote:
> On Fri, Nov 17, 2017 at 02:33:06PM -0600, 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:       3728 } hitcount:        199 \
> >         max:        123  next_comm: cyclictest  prev_pid:          0 \
> > 	prev_prio:        120  prev_comm: swapper/3
> >       { next_pid:       3730 } hitcount:       1321 \
> >         max:         15  next_comm: cyclictest  prev_pid:          0 \
> > 	prev_prio:        120  prev_comm: swapper/1
> >       { next_pid:       3729 } hitcount:       1973\
> >         max:         25  next_comm: cyclictest  prev_pid:          0  \
> > 	prev_prio:        120  prev_comm: swapper/0
> > 
> >     Totals:
> >         Hits: 3493
> >         Entries: 3
> > 	Dropped: 0
> > 
> > Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> > ---
> 
> [SNIP]
> > +static int onmax_create(struct hist_trigger_data *hist_data,
> > +			struct action_data *data)
> > +{
> > +	struct trace_event_call *call = hist_data->event_file->event_call;
> > +	struct trace_event_file *file = hist_data->event_file;
> > +	struct hist_field *var_field, *ref_field, *max_var;
> > +	unsigned int var_ref_idx = hist_data->n_var_refs;
> > +	struct field_var *field_var;
> > +	char *onmax_var_str, *param;
> > +	const char *event_name;
> > +	unsigned long flags;
> > +	unsigned int i;
> > +	int ret = 0;
> > +
> > +	onmax_var_str = data->onmax.var_str;
> > +	if (onmax_var_str[0] != '$')
> > +		return -EINVAL;
> > +	onmax_var_str++;
> > +
> > +	event_name = trace_event_name(call);
> 
> It seems not used.
> 
> 
> > +	var_field = find_target_event_var(hist_data, NULL, NULL, onmax_var_str);
> > +	if (!var_field)
> > +		return -EINVAL;
> > +
> > +	flags = HIST_FIELD_FL_VAR_REF;
> > +	ref_field = create_hist_field(hist_data, NULL, flags, NULL);
> > +	if (!ref_field)
> > +		return -ENOMEM;
> > +
> > +	if (init_var_ref(ref_field, var_field, NULL, NULL)) {
> > +		destroy_hist_field(ref_field, 0);
> > +		ret = -ENOMEM;
> > +		goto out;
> > +	}
> > +	hist_data->var_refs[hist_data->n_var_refs] = ref_field;
> > +	ref_field->var_ref_idx = hist_data->n_var_refs++;
> > +	data->onmax.var = ref_field;
> 
> I was confused that this could create a reference to self-variable
> which would prevent a hist from being freed.  IIUC it tries to avoid
> such a self reference by using local field variable and disallowing
> variable of expression, right?
> 
> But it seems that's not the case since the reference is saved in other
> place than hist_data->fields which is used in find_var_ref().
> 

The onmax processing only allows a variable defined on the target to be
used in the onmax(), so yes it can only be a 'self' variable defined on
the same trigger.  But that variable can reference variables in an
expression e.g. where ts0 is a variable on another trigger: 

  wakeup_lat=$common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(...)

The reference to $ts0 prevents that other trigger from going away, just
as a further event referencing $wakeup_lat would prevent the onmax()
trigger from going away - both of these cases are covered by the
find_var_ref() code.

But if the only trigger that accesses the $wakeup_lat is the onmax()
trigger itself, then it's ok to free that trigger.

Hope that answers your question about this..

Thanks,

Tom

> 
> > +
> > +	data->fn = onmax_save;
> > +	data->onmax.max_var_ref_idx = var_ref_idx;
> > +	max_var = create_var(hist_data, file, "max", sizeof(u64), "u64");
> > +	if (IS_ERR(max_var)) {
> > +		ret = PTR_ERR(max_var);
> > +		goto out;
> > +	}
> > +	data->onmax.max_var = max_var;
> > +
> > +	for (i = 0; i < data->n_params; i++) {
> > +		param = kstrdup(data->params[i], GFP_KERNEL);
> > +		if (!param) {
> > +			ret = -ENOMEM;
> > +			goto out;
> > +		}
> > +
> > +		field_var = create_target_field_var(hist_data, NULL, NULL, param);
> > +		if (IS_ERR(field_var)) {
> > +			ret = PTR_ERR(field_var);
> > +			kfree(param);
> > +			goto out;
> > +		}
> > +
> > +		hist_data->max_vars[hist_data->n_max_vars++] = field_var;
> > +		if (field_var->val->flags & HIST_FIELD_FL_STRING)
> > +			hist_data->n_max_var_str++;
> > +
> > +		kfree(param);
> > +	}
> > + out:
> > +	return ret;
> > +}
> > +
> 
> [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' leaked.
> 
> Thanks,
> Namhyung
> 
> 
> > +	data->onmax.var_str = kstrdup(onmax_var_str, GFP_KERNEL);
> > +	if (!data->onmax.var_str) {
> > +		ret = -ENOMEM;
> > +		goto free;
> > +	}
> > +
> > +	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) {
> > +			ret = -EINVAL;
> > +			goto free;
> > +		}
> > +
> > +		ret = parse_action_params(params, data);
> > +		if (ret)
> > +			goto free;
> > +	} else
> > +		goto free;
> > +
> > +	data->onmax.fn_name = kstrdup(onmax_fn_name, GFP_KERNEL);
> > +	if (!data->onmax.fn_name) {
> > +		ret = -ENOMEM;
> > +		goto free;
> > +	}
> > + out:
> > +	return data;
> > + free:
> > +	onmax_destroy(data);
> > +	data = ERR_PTR(ret);
> > +	goto out;
> > +}