patches/0039-tracing-Add-last-error-error-facility-for-hist-trigg.patch

From: Tom Zanussi <tom.zanussi@linux.intel.com>
Date: Mon, 15 Jan 2018 20:52:05 -0600
Subject: [PATCH 39/48] tracing: Add 'last error' error facility for hist
 triggers

With the addition of variables and actions, it's become necessary to
provide more detailed error information to users about syntax errors.

Add a 'last error' facility accessible via the erroring event's 'hist'
file.  Reading the hist file after an error will display more detailed
information about what went wrong, if information is available.  This
extended error information will be available until the next hist
trigger command for that event.

  # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  echo: write error: Invalid argument

  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist

  ERROR: Couldn't yyy: zzz
  Last command: xxx

Also add specific error messages for variable and action errors.

Link: http://lkml.kernel.org/r/64e9c422fc8aeafcc2f7a3b4328c0cffe7969129.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 215016863b5ec1ee5db5e20f32ffe015a497209f)
Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>
---
 Documentation/trace/histogram.txt |   20 ++++
 kernel/trace/trace_events_hist.c  |  164 ++++++++++++++++++++++++++++++++++----
 2 files changed, 170 insertions(+), 14 deletions(-)

--- a/Documentation/trace/histogram.txt
+++ b/Documentation/trace/histogram.txt
@@ -188,6 +188,26 @@
 				 interpreted as microseconds.
     cpu                    int - the cpu on which the event occurred.
 
+  Extended error information
+  --------------------------
+
+  For some error conditions encountered when invoking a hist trigger
+  command, extended error information is available via the
+  corresponding event's 'hist' file.  Reading the hist file after an
+  error will display more detailed information about what went wrong,
+  if information is available.  This extended error information will
+  be available until the next hist trigger command for that event.
+
+  If available for a given error condition, the extended error
+  information and usage takes the following form:
+
+    # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
+    echo: write error: Invalid argument
+
+    # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist
+    ERROR: Couldn't yyy: zzz
+      Last command: xxx
+
 6.2 'hist' trigger examples
 ---------------------------
 
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -351,6 +351,65 @@ struct action_data {
 	};
 };
 
+
+static char last_hist_cmd[MAX_FILTER_STR_VAL];
+static char hist_err_str[MAX_FILTER_STR_VAL];
+
+static void last_cmd_set(char *str)
+{
+	if (!str)
+		return;
+
+	strncpy(last_hist_cmd, str, MAX_FILTER_STR_VAL - 1);
+}
+
+static void hist_err(char *str, char *var)
+{
+	int maxlen = MAX_FILTER_STR_VAL - 1;
+
+	if (!str)
+		return;
+
+	if (strlen(hist_err_str))
+		return;
+
+	if (!var)
+		var = "";
+
+	if (strlen(hist_err_str) + strlen(str) + strlen(var) > maxlen)
+		return;
+
+	strcat(hist_err_str, str);
+	strcat(hist_err_str, var);
+}
+
+static void hist_err_event(char *str, char *system, char *event, char *var)
+{
+	char err[MAX_FILTER_STR_VAL];
+
+	if (system && var)
+		snprintf(err, MAX_FILTER_STR_VAL, "%s.%s.%s", system, event, var);
+	else if (system)
+		snprintf(err, MAX_FILTER_STR_VAL, "%s.%s", system, event);
+	else
+		strncpy(err, var, MAX_FILTER_STR_VAL);
+
+	hist_err(str, err);
+}
+
+static void hist_err_clear(void)
+{
+	hist_err_str[0] = '\0';
+}
+
+static bool have_hist_err(void)
+{
+	if (strlen(hist_err_str))
+		return true;
+
+	return false;
+}
+
 static LIST_HEAD(synth_event_list);
 static DEFINE_MUTEX(synth_event_mutex);
 
@@ -1448,8 +1507,10 @@ static struct trace_event_file *find_var
 			continue;
 
 		if (find_var_field(var_hist_data, var_name)) {
-			if (found)
+			if (found) {
+				hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name);
 				return NULL;
+			}
 
 			found = file;
 		}
@@ -1498,6 +1559,7 @@ find_match_var(struct hist_trigger_data
 			hist_field = find_file_var(file, var_name);
 			if (hist_field) {
 				if (found) {
+					hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name);
 					return ERR_PTR(-EINVAL);
 				}
 
@@ -1781,6 +1843,7 @@ static int parse_assignment(char *str, s
 		char *assignment;
 
 		if (attrs->n_assignments == TRACING_MAP_VARS_MAX) {
+			hist_err("Too many variables defined: ", str);
 			ret = -EINVAL;
 			goto out;
 		}
@@ -2335,6 +2398,10 @@ static struct hist_field *parse_var_ref(
 	if (var_field)
 		ref_field = create_var_ref(var_field, system, event_name);
 
+	if (!ref_field)
+		hist_err_event("Couldn't find variable: $",
+			       system, event_name, var_name);
+
 	return ref_field;
 }
 
@@ -2494,6 +2561,7 @@ static struct hist_field *parse_unary(st
 	// we support only -(xxx) i.e. explicit parens required
 
 	if (level > 3) {
+		hist_err("Too many subexpressions (3 max): ", str);
 		ret = -EINVAL;
 		goto free;
 	}
@@ -2575,8 +2643,10 @@ static int check_expr_operands(struct hi
 	}
 
 	if ((operand1_flags & HIST_FIELD_FL_TIMESTAMP_USECS) !=
-	    (operand2_flags & HIST_FIELD_FL_TIMESTAMP_USECS))
+	    (operand2_flags & HIST_FIELD_FL_TIMESTAMP_USECS)) {
+		hist_err("Timestamp units in expression don't match", NULL);
 		return -EINVAL;
+	}
 
 	return 0;
 }
@@ -2591,8 +2661,10 @@ static struct hist_field *parse_expr(str
 	int field_op, ret = -EINVAL;
 	char *sep, *operand1_str;
 
-	if (level > 3)
+	if (level > 3) {
+		hist_err("Too many subexpressions (3 max): ", str);
 		return ERR_PTR(-EINVAL);
+	}
 
 	field_op = contains_operator(str);
 
@@ -2826,12 +2898,17 @@ create_field_var_hist(struct hist_trigge
 	char *cmd;
 	int ret;
 
-	if (target_hist_data->n_field_var_hists >= SYNTH_FIELDS_MAX)
+	if (target_hist_data->n_field_var_hists >= SYNTH_FIELDS_MAX) {
+		hist_err_event("onmatch: Too many field variables defined: ",
+			       subsys_name, event_name, field_name);
 		return ERR_PTR(-EINVAL);
+	}
 
 	file = event_file(tr, subsys_name, event_name);
 
 	if (IS_ERR(file)) {
+		hist_err_event("onmatch: Event file not found: ",
+			       subsys_name, event_name, field_name);
 		ret = PTR_ERR(file);
 		return ERR_PTR(ret);
 	}
@@ -2843,8 +2920,11 @@ create_field_var_hist(struct hist_trigge
 	 * yet a registered histogram so we can't use that.
 	 */
 	hist_data = find_compatible_hist(target_hist_data, file);
-	if (!hist_data)
+	if (!hist_data) {
+		hist_err_event("onmatch: Matching event histogram not found: ",
+			       subsys_name, event_name, field_name);
 		return ERR_PTR(-EINVAL);
+	}
 
 	/* See if a synthetic field variable has already been created */
 	event_var = find_synthetic_field_var(target_hist_data, subsys_name,
@@ -2903,6 +2983,8 @@ create_field_var_hist(struct hist_trigge
 		kfree(cmd);
 		kfree(var_hist->cmd);
 		kfree(var_hist);
+		hist_err_event("onmatch: Couldn't create histogram for field: ",
+			       subsys_name, event_name, field_name);
 		return ERR_PTR(ret);
 	}
 
@@ -2914,6 +2996,8 @@ create_field_var_hist(struct hist_trigge
 	if (IS_ERR_OR_NULL(event_var)) {
 		kfree(var_hist->cmd);
 		kfree(var_hist);
+		hist_err_event("onmatch: Couldn't find synthetic variable: ",
+			       subsys_name, event_name, field_name);
 		return ERR_PTR(-EINVAL);
 	}
 
@@ -3050,18 +3134,21 @@ static struct field_var *create_field_va
 	int ret = 0;
 
 	if (hist_data->n_field_vars >= SYNTH_FIELDS_MAX) {
+		hist_err("Too many field variables defined: ", field_name);
 		ret = -EINVAL;
 		goto err;
 	}
 
 	val = parse_atom(hist_data, file, field_name, &flags, NULL);
 	if (IS_ERR(val)) {
+		hist_err("Couldn't parse field variable: ", field_name);
 		ret = PTR_ERR(val);
 		goto err;
 	}
 
 	var = create_var(hist_data, file, field_name, val->size, val->type);
 	if (IS_ERR(var)) {
+		hist_err("Couldn't create or find variable: ", field_name);
 		kfree(val);
 		ret = PTR_ERR(var);
 		goto err;
@@ -3204,13 +3291,17 @@ static int onmax_create(struct hist_trig
 	int ret = 0;
 
 	onmax_var_str = data->onmax.var_str;
-	if (onmax_var_str[0] != '$')
+	if (onmax_var_str[0] != '$') {
+		hist_err("onmax: For onmax(x), x must be a variable: ", onmax_var_str);
 		return -EINVAL;
+	}
 	onmax_var_str++;
 
 	var_field = find_target_event_var(hist_data, NULL, NULL, onmax_var_str);
-	if (!var_field)
+	if (!var_field) {
+		hist_err("onmax: Couldn't find onmax variable: ", onmax_var_str);
 		return -EINVAL;
+	}
 
 	flags = HIST_FIELD_FL_VAR_REF;
 	ref_field = create_hist_field(hist_data, NULL, flags, NULL);
@@ -3230,6 +3321,7 @@ static int onmax_create(struct hist_trig
 	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)) {
+		hist_err("onmax: Couldn't create onmax variable: ", "max");
 		ret = PTR_ERR(max_var);
 		goto out;
 	}
@@ -3244,6 +3336,7 @@ static int onmax_create(struct hist_trig
 
 		field_var = create_target_field_var(hist_data, NULL, NULL, param);
 		if (IS_ERR(field_var)) {
+			hist_err("onmax: Couldn't create field variable: ", param);
 			ret = PTR_ERR(field_var);
 			kfree(param);
 			goto out;
@@ -3276,6 +3369,7 @@ static int parse_action_params(char *par
 
 		param = strstrip(param);
 		if (strlen(param) < 2) {
+			hist_err("Invalid action param: ", param);
 			ret = -EINVAL;
 			goto out;
 		}
@@ -3451,6 +3545,9 @@ onmatch_find_var(struct hist_trigger_dat
 		hist_field = find_event_var(hist_data, system, event, var);
 	}
 
+	if (!hist_field)
+		hist_err_event("onmatch: Couldn't find onmatch param: $", system, event, var);
+
 	return hist_field;
 }
 
@@ -3518,6 +3615,7 @@ static int onmatch_create(struct hist_tr
 	mutex_lock(&synth_event_mutex);
 	event = find_synth_event(data->onmatch.synth_event_name);
 	if (!event) {
+		hist_err("onmatch: Couldn't find synthetic event: ", data->onmatch.synth_event_name);
 		mutex_unlock(&synth_event_mutex);
 		return -EINVAL;
 	}
@@ -3577,12 +3675,15 @@ static int onmatch_create(struct hist_tr
 			continue;
 		}
 
+		hist_err_event("onmatch: Param type doesn't match synthetic event field type: ",
+			       system, event_name, param);
 		kfree(p);
 		ret = -EINVAL;
 		goto err;
 	}
 
 	if (field_pos != event->n_fields) {
+		hist_err("onmatch: Param count doesn't match synthetic event field count: ", event->name);
 		ret = -EINVAL;
 		goto err;
 	}
@@ -3612,15 +3713,22 @@ static struct action_data *onmatch_parse
 		return ERR_PTR(-ENOMEM);
 
 	match_event = strsep(&str, ")");
-	if (!match_event || !str)
+	if (!match_event || !str) {
+		hist_err("onmatch: Missing closing paren: ", match_event);
 		goto free;
+	}
 
 	match_event_system = strsep(&match_event, ".");
-	if (!match_event)
+	if (!match_event) {
+		hist_err("onmatch: Missing subsystem for match event: ", match_event_system);
 		goto free;
+	}
 
-	if (IS_ERR(event_file(tr, match_event_system, match_event)))
+	if (IS_ERR(event_file(tr, match_event_system, match_event))) {
+		hist_err_event("onmatch: Invalid subsystem or event name: ",
+			       match_event_system, match_event, NULL);
 		goto free;
+	}
 
 	data->onmatch.match_event = kstrdup(match_event, GFP_KERNEL);
 	if (!data->onmatch.match_event) {
@@ -3635,12 +3743,16 @@ static struct action_data *onmatch_parse
 	}
 
 	strsep(&str, ".");
-	if (!str)
+	if (!str) {
+		hist_err("onmatch: Missing . after onmatch(): ", str);
 		goto free;
+	}
 
 	synth_event_name = strsep(&str, "(");
-	if (!synth_event_name || !str)
+	if (!synth_event_name || !str) {
+		hist_err("onmatch: Missing opening paramlist paren: ", synth_event_name);
 		goto free;
+	}
 
 	data->onmatch.synth_event_name = kstrdup(synth_event_name, GFP_KERNEL);
 	if (!data->onmatch.synth_event_name) {
@@ -3649,8 +3761,10 @@ static struct action_data *onmatch_parse
 	}
 
 	params = strsep(&str, ")");
-	if (!params || !str || (str && strlen(str)))
+	if (!params || !str || (str && strlen(str))) {
+		hist_err("onmatch: Missing closing paramlist paren: ", params);
 		goto free;
+	}
 
 	ret = parse_action_params(params, data);
 	if (ret)
@@ -3725,7 +3839,9 @@ static int create_var_field(struct hist_
 
 	if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX))
 		return -EINVAL;
+
 	if (find_var(hist_data, file, var_name) && !hist_data->remove) {
+		hist_err("Variable already defined: ", var_name);
 		return -EINVAL;
 	}
 
@@ -3806,6 +3922,7 @@ static int create_key_field(struct hist_
 		}
 
 		if (hist_field->flags & HIST_FIELD_FL_VAR_REF) {
+			hist_err("Using variable references as keys not supported: ", field_str);
 			destroy_hist_field(hist_field, 0);
 			ret = -EINVAL;
 			goto out;
@@ -3919,11 +4036,13 @@ static int parse_var_defs(struct hist_tr
 
 			var_name = strsep(&field_str, "=");
 			if (!var_name || !field_str) {
+				hist_err("Malformed assignment: ", var_name);
 				ret = -EINVAL;
 				goto free;
 			}
 
 			if (n_vars == TRACING_MAP_VARS_MAX) {
+				hist_err("Too many variables defined: ", var_name);
 				ret = -EINVAL;
 				goto free;
 			}
@@ -4677,6 +4796,11 @@ static int hist_show(struct seq_file *m,
 			hist_trigger_show(m, data, n++);
 	}
 
+	if (have_hist_err()) {
+		seq_printf(m, "\nERROR: %s\n", hist_err_str);
+		seq_printf(m, "  Last command: %s\n", last_hist_cmd);
+	}
+
  out_unlock:
 	mutex_unlock(&event_mutex);
 
@@ -5041,6 +5165,7 @@ static int hist_register_trigger(char *g
 		if (named_data) {
 			if (!hist_trigger_match(data, named_data, named_data,
 						true)) {
+				hist_err("Named hist trigger doesn't match existing named trigger (includes variables): ", hist_data->attrs->name);
 				ret = -EINVAL;
 				goto out;
 			}
@@ -5060,13 +5185,16 @@ static int hist_register_trigger(char *g
 				test->paused = false;
 			else if (hist_data->attrs->clear)
 				hist_clear(test);
-			else
+			else {
+				hist_err("Hist trigger already exists", NULL);
 				ret = -EEXIST;
+			}
 			goto out;
 		}
 	}
  new:
 	if (hist_data->attrs->cont || hist_data->attrs->clear) {
+		hist_err("Can't clear or continue a nonexistent hist trigger", NULL);
 		ret = -ENOENT;
 		goto out;
 	}
@@ -5253,6 +5381,11 @@ static int event_hist_trigger_func(struc
 	char *trigger, *p;
 	int ret = 0;
 
+	if (glob && strlen(glob)) {
+		last_cmd_set(param);
+		hist_err_clear();
+	}
+
 	if (!param)
 		return -EINVAL;
 
@@ -5391,6 +5524,9 @@ static int event_hist_trigger_func(struc
 	/* Just return zero, not the number of registered triggers */
 	ret = 0;
  out:
+	if (ret == 0)
+		hist_err_clear();
+
 	return ret;
  out_unreg:
 	cmd_ops->unreg(glob+1, trigger_ops, trigger_data, file);