Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751758AbdGZDEb (ORCPT ); Tue, 25 Jul 2017 23:04:31 -0400 Received: from LGEAMRELO13.lge.com ([156.147.23.53]:39473 "EHLO lgeamrelo13.lge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751540AbdGZDEa (ORCPT ); Tue, 25 Jul 2017 23:04:30 -0400 X-Original-SENDERIP: 156.147.1.151 X-Original-MAILFROM: namhyung@kernel.org X-Original-SENDERIP: 10.177.227.17 X-Original-MAILFROM: namhyung@kernel.org Date: Wed, 26 Jul 2017 12:04:27 +0900 From: Namhyung Kim To: Tom Zanussi Cc: rostedt@goodmis.org, tglx@linutronix.de, mhiramat@kernel.org, vedang.patel@intel.com, linux-kernel@vger.kernel.org, linux-rt-users@vger.kernel.org, kernel-team@lge.com Subject: Re: [PATCH 24/32] tracing: Add 'onmax' hist trigger action support Message-ID: <20170726030427.GB32043@sejong> References: MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.8.3 (2017-05-23) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 5640 Lines: 179 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 > --- > 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; > +}