diff mbox series

[33/54] tracing: Add 'onmax' hist trigger action support

Message ID TY1PR01MB1692FA44B7C69CBA1B776C5496090@TY1PR01MB1692.jpnprd01.prod.outlook.com (mailing list archive)
State New, archived
Headers show
Series None | expand

Commit Message

Motai.Hirotaka@aj.MitsubishiElectric.co.jp Aug. 29, 2018, 12:17 p.m. UTC
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

Link: http://lkml.kernel.org/r/006907f71b1e839bb059337ec3c496f84fcb71de.1516069914.git.tom.zanussi@linux.intel.com

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
(cherry picked from commit 50450603ec9cb808d39b1461fe67a81d82b37129)
Signed-off-by: Hirotaka MOTAI <Motai.Hirotaka@aj.MitsubishiElectric.co.jp>
---
 kernel/trace/trace_events_hist.c | 331 +++++++++++++++++++++++++++----
 1 file changed, 296 insertions(+), 35 deletions(-)
diff mbox series

Patch

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 9ac6089b..7bcc32a7 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -287,16 +287,20 @@  struct hist_trigger_data {
 
 	struct hist_field               *synth_var_refs[SYNTH_FIELDS_MAX];
 	unsigned int                    n_synth_var_refs;
 	struct field_var		*field_vars[SYNTH_FIELDS_MAX];
 	unsigned int			n_field_vars;
 	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 {
 	char *type;
 	char *name;
 	size_t size;
 	bool is_signed;
 	bool is_string;
@@ -329,16 +333,24 @@  struct action_data {
 	union {
 		struct {
 			unsigned int		var_ref_idx;
 			char			*match_event;
 			char			*match_event_system;
 			char			*synth_event_name;
 			struct synth_event	*synth_event;
 		} onmatch;
+
+		struct {
+			char			*var_str;
+			char			*fn_name;
+			unsigned int		max_var_ref_idx;
+			struct hist_field	*max_var;
+			struct hist_field	*var;
+		} onmax;
 	};
 };
 
 static LIST_HEAD(synth_event_list);
 static DEFINE_MUTEX(synth_event_mutex);
 
 struct synth_trace_event {
 	struct trace_entry	ent;
@@ -1692,17 +1704,18 @@  static void destroy_hist_trigger_attrs(struct hist_trigger_attrs *attrs)
 
 static int parse_action(char *str, struct hist_trigger_attrs *attrs)
 {
 	int ret = -EINVAL;
 
 	if (attrs->n_actions >= HIST_ACTIONS_MAX)
 		return ret;
 
-	if ((strncmp(str, "onmatch(", strlen("onmatch(")) == 0)) {
+	if ((strncmp(str, "onmatch(", strlen("onmatch(")) == 0) ||
+	    (strncmp(str, "onmax(", strlen("onmax(")) == 0)) {
 		attrs->action_str[attrs->n_actions] = kstrdup(str, GFP_KERNEL);
 		if (!attrs->action_str[attrs->n_actions]) {
 			ret = -ENOMEM;
 			return ret;
 		}
 		attrs->n_actions++;
 		ret = 0;
 	}
@@ -1864,17 +1877,17 @@  static int hist_trigger_elt_data_alloc(struct tracing_map_elt *elt)
 			if (!elt_data->comm) {
 				kfree(elt_data);
 				return -ENOMEM;
 			}
 			break;
 		}
 	}
 
-	n_str = hist_data->n_field_var_str;
+	n_str = hist_data->n_field_var_str + hist_data->n_max_var_str;
 
 	size = STR_VAR_LEN_MAX;
 
 	for (i = 0; i < n_str; i++) {
 		elt_data->field_var_str[i] = kzalloc(size, GFP_KERNEL);
 		if (!elt_data->field_var_str[i]) {
 			hist_elt_data_free(elt_data);
 			return -ENOMEM;
@@ -2889,16 +2902,25 @@  static void update_field_vars(struct hist_trigger_data *hist_data,
 			      struct tracing_map_elt *elt,
 			      struct ring_buffer_event *rbe,
 			      void *rec)
 {
 	__update_field_vars(elt, rbe, rec, hist_data->field_vars,
 			    hist_data->n_field_vars, 0);
 }
 
+static void update_max_vars(struct hist_trigger_data *hist_data,
+			    struct tracing_map_elt *elt,
+			    struct ring_buffer_event *rbe,
+			    void *rec)
+{
+	__update_field_vars(elt, rbe, rec, hist_data->max_vars,
+			    hist_data->n_max_vars, hist_data->n_field_var_str);
+}
+
 static struct hist_field *create_var(struct hist_trigger_data *hist_data,
 				     struct trace_event_file *file,
 				     char *name, int size, const char *type)
 {
 	struct hist_field *var;
 	int idx;
 
 	if (find_var(hist_data, file, name) && !hist_data->remove) {
@@ -3018,16 +3040,237 @@  create_target_field_var(struct hist_trigger_data *target_hist_data,
 
 		if (strcmp(event_name, trace_event_name(call)) != 0)
 			return NULL;
 	}
 
 	return create_field_var(target_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->onmax.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: %-32s", save_var->var.name,
+				   (char *)(uintptr_t)(val));
+		} else
+			seq_printf(m, "  %s: %10llu", save_var->var.name, val);
+	}
+}
+
+static void onmax_save(struct hist_trigger_data *hist_data,
+		       struct tracing_map_elt *elt, void *rec,
+		       struct ring_buffer_event *rbe,
+		       struct action_data *data, u64 *var_ref_vals)
+{
+	unsigned int max_idx = data->onmax.max_var->var.idx;
+	unsigned int max_var_ref_idx = data->onmax.max_var_ref_idx;
+
+	u64 var_val, max_val;
+
+	var_val = var_ref_vals[max_var_ref_idx];
+	max_val = tracing_map_read_var(elt, max_idx);
+
+	if (var_val <= max_val)
+		return;
+
+	tracing_map_set_var(elt, max_idx, var_val);
+
+	update_max_vars(hist_data, elt, rbe, rec);
+}
+
+static void onmax_destroy(struct action_data *data)
+{
+	unsigned int i;
+
+	destroy_hist_field(data->onmax.max_var, 0);
+	destroy_hist_field(data->onmax.var, 0);
+
+	kfree(data->onmax.var_str);
+	kfree(data->onmax.fn_name);
+
+	for (i = 0; i < data->n_params; i++)
+		kfree(data->params[i]);
+
+	kfree(data);
+}
+
+static int onmax_create(struct hist_trigger_data *hist_data,
+			struct action_data *data)
+{
+	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;
+	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++;
+
+	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;
+
+	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;
+}
+
+static int parse_action_params(char *params, struct action_data *data)
+{
+	char *param, *saved_param;
+	int ret = 0;
+
+	while (params) {
+		if (data->n_params >= SYNTH_FIELDS_MAX)
+			goto out;
+
+		param = strsep(&params, ",");
+		if (!param) {
+			ret = -EINVAL;
+			goto out;
+		}
+
+		param = strstrip(param);
+		if (strlen(param) < 2) {
+			ret = -EINVAL;
+			goto out;
+		}
+
+		saved_param = kstrdup(param, GFP_KERNEL);
+		if (!saved_param) {
+			ret = -ENOMEM;
+			goto out;
+		}
+
+		data->params[data->n_params++] = saved_param;
+	}
+ out:
+	return ret;
+}
+
+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) {
+		ret = -EINVAL;
+		goto free;
+	}
+
+	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;
+}
+
 static void onmatch_destroy(struct action_data *data)
 {
 	unsigned int i;
 
 	mutex_lock(&synth_event_mutex);
 
 	kfree(data->onmatch.match_event);
 	kfree(data->onmatch.match_event_system);
@@ -3102,49 +3345,16 @@  static int check_synth_field(struct synth_event *event,
 	field = event->fields[field_pos];
 
 	if (strcmp(field->type, hist_field->type) != 0)
 		return -EINVAL;
 
 	return 0;
 }
 
-static int parse_action_params(char *params, struct action_data *data)
-{
-	char *param, *saved_param;
-	int ret = 0;
-
-	while (params) {
-		if (data->n_params >= SYNTH_FIELDS_MAX)
-			goto out;
-
-		param = strsep(&params, ",");
-		if (!param) {
-			ret = -EINVAL;
-			goto out;
-		}
-
-		param = strstrip(param);
-		if (strlen(param) < 2) {
-			ret = -EINVAL;
-			goto out;
-		}
-
-		saved_param = kstrdup(param, GFP_KERNEL);
-		if (!saved_param) {
-			ret = -ENOMEM;
-			goto out;
-		}
-
-		data->params[data->n_params++] = saved_param;
-	}
- out:
-	return ret;
-}
-
 static struct hist_field *
 onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data,
 		 char *system, char *event, char *var)
 {
 	struct hist_field *hist_field;
 
 	var++; /* skip '$' */
 
@@ -3791,16 +4001,18 @@  static void destroy_actions(struct hist_trigger_data *hist_data)
 {
 	unsigned int i;
 
 	for (i = 0; i < hist_data->n_actions; i++) {
 		struct action_data *data = hist_data->actions[i];
 
 		if (data->fn == action_trace)
 			onmatch_destroy(data);
+		else if (data->fn == onmax_save)
+			onmax_destroy(data);
 		else
 			kfree(data);
 	}
 }
 
 static int parse_actions(struct hist_trigger_data *hist_data)
 {
 	struct trace_array *tr = hist_data->event_file->tr;
@@ -3816,16 +4028,25 @@  static int parse_actions(struct hist_trigger_data *hist_data)
 			char *action_str = str + strlen("onmatch(");
 
 			data = onmatch_parse(tr, action_str);
 			if (IS_ERR(data)) {
 				ret = PTR_ERR(data);
 				break;
 			}
 			data->fn = action_trace;
+		} else if (strncmp(str, "onmax(", strlen("onmax(")) == 0) {
+			char *action_str = str + strlen("onmax(");
+
+			data = onmax_parse(action_str);
+			if (IS_ERR(data)) {
+				ret = PTR_ERR(data);
+				break;
+			}
+			data->fn = onmax_save;
 		} else {
 			ret = -EINVAL;
 			break;
 		}
 
 		hist_data->actions[hist_data->n_actions++] = data;
 	}
 
@@ -3841,22 +4062,58 @@  static int create_actions(struct hist_trigger_data *hist_data,
 
 	for (i = 0; i < hist_data->attrs->n_actions; i++) {
 		data = hist_data->actions[i];
 
 		if (data->fn == action_trace) {
 			ret = onmatch_create(hist_data, file, data);
 			if (ret)
 				return ret;
+		} else if (data->fn == onmax_save) {
+			ret = onmax_create(hist_data, data);
+			if (ret)
+				return ret;
 		}
 	}
 
 	return ret;
 }
 
+static void print_actions(struct seq_file *m,
+			  struct hist_trigger_data *hist_data,
+			  struct tracing_map_elt *elt)
+{
+	unsigned int i;
+
+	for (i = 0; i < hist_data->n_actions; i++) {
+		struct action_data *data = hist_data->actions[i];
+
+		if (data->fn == onmax_save)
+			onmax_print(m, hist_data, elt, data);
+	}
+}
+
+static void print_onmax_spec(struct seq_file *m,
+			     struct hist_trigger_data *hist_data,
+			     struct action_data *data)
+{
+	unsigned int i;
+
+	seq_puts(m, ":onmax(");
+	seq_printf(m, "%s", data->onmax.var_str);
+	seq_printf(m, ").%s(", data->onmax.fn_name);
+
+	for (i = 0; i < hist_data->n_max_vars; i++) {
+		seq_printf(m, "%s", hist_data->max_vars[i]->var->var.name);
+		if (i < hist_data->n_max_vars - 1)
+			seq_puts(m, ",");
+	}
+	seq_puts(m, ")");
+}
+
 static void print_onmatch_spec(struct seq_file *m,
 			       struct hist_trigger_data *hist_data,
 			       struct action_data *data)
 {
 	unsigned int i;
 
 	seq_printf(m, ":onmatch(%s.%s).", data->onmatch.match_event_system,
 		   data->onmatch.match_event);
@@ -3877,16 +4134,18 @@  static void print_actions_spec(struct seq_file *m,
 {
 	unsigned int i;
 
 	for (i = 0; i < hist_data->n_actions; i++) {
 		struct action_data *data = hist_data->actions[i];
 
 		if (data->fn == action_trace)
 			print_onmatch_spec(m, hist_data, data);
+		else if (data->fn == onmax_save)
+			print_onmax_spec(m, hist_data, data);
 	}
 }
 
 static void destroy_field_var_hists(struct hist_trigger_data *hist_data)
 {
 	unsigned int i;
 
 	for (i = 0; i < hist_data->n_field_var_hists; i++) {
@@ -4258,16 +4517,18 @@  hist_trigger_entry_print(struct seq_file *m,
 			seq_printf(m, "  %s: %10llx", field_name,
 				   tracing_map_read_sum(elt, i));
 		} else {
 			seq_printf(m, "  %s: %10llu", field_name,
 				   tracing_map_read_sum(elt, i));
 		}
 	}
 
+	print_actions(m, hist_data, elt);
+
 	seq_puts(m, "\n");
 }
 
 static int print_entries(struct seq_file *m,
 			 struct hist_trigger_data *hist_data)
 {
 	struct tracing_map_sort_entry **sort_entries = NULL;
 	struct tracing_map *map = hist_data->map;