lkml.org 
[lkml]   [2017]   [Jul]   [25]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: [PATCH 24/32] tracing: Add 'onmax' hist trigger action support
    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;
    > +}

    \
     
     \ /
      Last update: 2017-07-26 05:05    [W:6.832 / U:0.056 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site