Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1675152
| From | Tom Zanussi <tom.zanussi@linux.intel.com> |
|---|---|
| Newsgroups | linux.kernel |
| Subject | [PATCH 29/32] tracing: Add 'last error' error facility for hist triggers |
| Date | 2017-06-27 01:00 +0200 |
| Message-ID | <tWL97-8u4-9@gated-at.bofh.it> (permalink) |
| References | <tWKZs-8nP-19@gated-at.bofh.it> |
| Organization | linux.* mail to news gateway |
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.
Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
Documentation/trace/events.txt | 19 ++++
kernel/trace/trace_events_hist.c | 181 ++++++++++++++++++++++++++++++++++++---
2 files changed, 188 insertions(+), 12 deletions(-)
diff --git a/Documentation/trace/events.txt b/Documentation/trace/events.txt
index 9717688..f271d87 100644
--- a/Documentation/trace/events.txt
+++ b/Documentation/trace/events.txt
@@ -686,6 +686,25 @@ The following commands are supported:
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
---------------------------
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 799b95e..06049f8 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -288,6 +288,7 @@ struct hist_trigger_data {
struct field_var *max_vars[SYNTH_FIELDS_MAX];
unsigned int n_max_vars;
unsigned int n_max_var_str;
+ char *last_err;
};
struct synth_field {
@@ -332,6 +333,83 @@ struct action_data {
struct hist_field *onmax_var;
};
+
+static char *hist_err_str;
+static char *last_hist_cmd;
+
+static int hist_err_alloc(void)
+{
+ int ret = 0;
+
+ last_hist_cmd = kzalloc(MAX_FILTER_STR_VAL, GFP_KERNEL);
+ hist_err_str = kzalloc(MAX_FILTER_STR_VAL, GFP_KERNEL);
+ if (!last_hist_cmd || !hist_err_str)
+ ret = -ENOMEM;
+
+ return ret;
+}
+
+static void last_cmd_set(char *str)
+{
+ if (!last_hist_cmd || !str)
+ return;
+
+ if (strlen(last_hist_cmd) > MAX_FILTER_STR_VAL - 1)
+ return;
+
+ strcpy(last_hist_cmd, str);
+}
+
+static void hist_err(char *str, char *var)
+{
+ int maxlen = MAX_FILTER_STR_VAL - 1;
+
+ if (strlen(hist_err_str))
+ return;
+
+ if (!hist_err_str || !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)
+ sprintf(err, "%s.%s.%s", system, event, var);
+ else if (system)
+ sprintf(err, "%s.%s", system, event);
+ else
+ strcpy(err, var);
+
+ hist_err(str, err);
+}
+
+static void hist_err_clear(void)
+{
+ if (!hist_err_str)
+ return;
+
+ hist_err_str[0] = '\0';
+}
+
+static bool have_hist_err(void)
+{
+ if (hist_err_str && strlen(hist_err_str))
+ return true;
+
+ return false;
+}
+
static LIST_HEAD(synth_event_list);
static DEFINE_MUTEX(synth_event_mutex);
@@ -1954,12 +2032,21 @@ static struct hist_field *create_var_ref(struct hist_field *var_field)
return ref_field;
}
+static bool is_common_field(char *var_name)
+{
+ if (strncmp(var_name, "$common_timestamp", strlen("$common_timestamp")) == 0)
+ return true;
+
+ return false;
+}
+
static struct hist_field *parse_var_ref(char *system, char *event_name,
char *var_name)
{
struct hist_field *var_field = NULL, *ref_field = NULL;
- if (!var_name || strlen(var_name) < 2 || var_name[0] != '$')
+ if (!var_name || strlen(var_name) < 2 || var_name[0] != '$' ||
+ is_common_field(var_name))
return NULL;
var_name++;
@@ -1968,6 +2055,10 @@ static struct hist_field *parse_var_ref(char *system, char *event_name,
if (var_field)
ref_field = create_var_ref(var_field);
+ if (!ref_field)
+ hist_err_event("Couldn't find variable: $",
+ system, event_name, var_name);
+
return ref_field;
}
@@ -2426,8 +2517,11 @@ static struct trace_event_file *event_file(char *system, char *event_name)
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: ",
+ system, event_name, field_name);
return ERR_PTR(-EINVAL);
+ }
tr = top_trace_array();
if (!tr)
@@ -2435,13 +2529,18 @@ static struct trace_event_file *event_file(char *system, char *event_name)
file = event_file(system, event_name);
if (IS_ERR(file)) {
+ hist_err_event("onmatch: Event file not found: ",
+ system, event_name, field_name);
ret = PTR_ERR(file);
return ERR_PTR(ret);
}
hist_data = find_compatible_hist(target_hist_data, file);
- if (!hist_data)
+ if (!hist_data) {
+ hist_err_event("onmatch: Matching event histogram not found: ",
+ system, event_name, field_name);
return ERR_PTR(-EINVAL);
+ }
var_hist = kzalloc(sizeof(*var_hist), GFP_KERNEL);
if (!var_hist)
@@ -2489,6 +2588,8 @@ static struct trace_event_file *event_file(char *system, char *event_name)
kfree(cmd);
kfree(var_hist->cmd);
kfree(var_hist);
+ hist_err_event("onmatch: Couldn't create histogram for field: ",
+ system, event_name, field_name);
return ERR_PTR(ret);
}
@@ -2500,6 +2601,8 @@ static struct trace_event_file *event_file(char *system, char *event_name)
kfree(cmd);
kfree(var_hist->cmd);
kfree(var_hist);
+ hist_err_event("onmatch: Couldn't find synthetic variable: ",
+ system, event_name, field_name);
return ERR_PTR(-EINVAL);
}
@@ -2636,18 +2739,21 @@ static struct field_var *create_field_var(struct hist_trigger_data *hist_data,
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;
@@ -2772,14 +2878,18 @@ static int onmax_create(struct hist_trigger_data *hist_data,
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++;
event_name = trace_event_name(call);
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);
@@ -2803,6 +2913,7 @@ static int onmax_create(struct hist_trigger_data *hist_data,
data->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;
}
@@ -2815,6 +2926,7 @@ static int onmax_create(struct hist_trigger_data *hist_data,
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;
@@ -2847,6 +2959,7 @@ static int parse_action_params(char *params, struct action_data *data)
param = strstrip(param);
if (strlen(param) < 2) {
+ hist_err("Invalid action param: ", param);
ret = -EINVAL;
goto out;
}
@@ -3004,6 +3117,9 @@ static int check_synth_field(struct synth_event *event,
hist_field = find_event_var(system, event, var);
}
+ if (!hist_field)
+ hist_err_event("onmatch: Couldn't find onmatch param: $", system, event, var);
+
return hist_field;
}
@@ -3055,6 +3171,7 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
event = find_synth_event(data->synth_event_name);
if (!event) {
+ hist_err("onmatch: Couldn't find synthetic event: ", data->synth_event_name);
ret = -EINVAL;
goto out;
}
@@ -3094,6 +3211,7 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
ret = -EINVAL;
goto out;
}
+
if (check_synth_field(event, hist_field, field_pos) == 0) {
var_ref = create_var_ref(hist_field);
if (!var_ref) {
@@ -3108,12 +3226,15 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
continue;
}
+ hist_err_event("onmatch: Param type doesn't match synthetic event field type: ",
+ system, event_name, param);
kfree(p);
ret = -EINVAL;
goto out;
}
if (field_pos != event->n_fields) {
+ hist_err("onmatch: Param count doesn't match synthetic event field count: ", event->name);
ret = -EINVAL;
goto out;
}
@@ -3141,31 +3262,44 @@ static struct action_data *onmatch_parse(char *str)
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(match_event_system, match_event)))
+ if (IS_ERR(event_file(match_event_system, match_event))) {
+ hist_err_event("onmatch: Invalid subsystem or event name: ",
+ match_event_system, match_event, NULL);
goto free;
+ }
data->match_event = kstrdup(match_event, GFP_KERNEL);
data->match_event_system = kstrdup(match_event_system, GFP_KERNEL);
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->synth_event_name = kstrdup(synth_event_name, GFP_KERNEL);
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)
@@ -3217,6 +3351,7 @@ static int create_val_field(struct hist_trigger_data *hist_data,
if (field_str && var_name) {
if (find_var(file, var_name) &&
!hist_data->remove) {
+ hist_err("Variable already defined: ", var_name);
ret = -EINVAL;
goto out;
}
@@ -3224,6 +3359,7 @@ static int create_val_field(struct hist_trigger_data *hist_data,
flags |= HIST_FIELD_FL_VAR;
hist_data->n_vars++;
if (hist_data->n_vars > TRACING_MAP_VARS_MAX) {
+ hist_err("Too many variables defined: ", var_name);
ret = -EINVAL;
goto out;
}
@@ -3234,6 +3370,7 @@ static int create_val_field(struct hist_trigger_data *hist_data,
field_str = var_name;
var_name = NULL;
} else {
+ hist_err("Malformed assignment: ", var_name);
ret = -EINVAL;
goto out;
}
@@ -3248,6 +3385,7 @@ static int create_val_field(struct hist_trigger_data *hist_data,
hist_field = parse_atom(hist_data, file, field_str,
&flags, var_name);
if (IS_ERR(hist_field)) {
+ hist_err("Unable to parse atom: ", field_str);
ret = PTR_ERR(hist_field);
goto out;
}
@@ -4138,6 +4276,11 @@ static int hist_show(struct seq_file *m, void *v)
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);
@@ -4509,6 +4652,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
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;
}
@@ -4528,13 +4672,16 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
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;
}
@@ -4701,6 +4848,11 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
char *trigger, *p;
int ret = 0;
+ if (glob && strlen(glob)) {
+ last_cmd_set(param);
+ hist_err_clear();
+ }
+
if (!param)
return -EINVAL;
@@ -4804,6 +4956,9 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
/* 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);
@@ -5002,6 +5157,8 @@ static __init int trace_events_hist_init(void)
goto err;
}
+ hist_err_alloc();
+
return err;
err:
pr_warn("Could not create tracefs 'synthetic_events' entry\n");
--
1.9.3
Back to linux.kernel | Previous | Next — Previous in thread | Next in thread | Find similar | Unroll thread
[PATCH 00/32] tracing: Inter-event (e.g. latency) support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 00:50 +0200
[PATCH 17/32] tracing: Account for variables in named trigger compatibility Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 02/32] tracing: Reimplement log2 Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 10/32] tracing: Add NO_DISCARD event file flag Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 11/32] tracing: Add post-trigger flag to hist trigger command Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 19/32] tracing: Add variable reference handling to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 29/32] tracing: Add 'last error' error facility for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 04/32] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
Re: [PATCH 04/32] ring-buffer: Redefine the unimplemented RINGBUF_TIME_TIME_STAMP "Joel Fernandes (Google)" <joel.opensrc@gmail.com> - 2017-07-02 11:00 +0200
[PATCH 06/32] tracing: Add ring buffer event param to hist field functions Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 16/32] tracing: Add variable support to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 20/32] tracing: Add support for dynamic tracepoints Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 24/32] tracing: Add 'onmax' hist trigger action support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 03/32] ring-buffer: Add interface for setting absolute time stamps Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 13/32] tracing: Add per-element variable support to tracing_map Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 09/32] tracing: Make traceprobe parsing code reusable Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 28/32] tracing: Add hist trigger support for variable reference aliases Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 32/32] tracing: Add a clock attribute for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 25/32] tracing: Allow whitespace to surround hist trigger filter Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 05/32] tracing: Give event triggers access to ring_buffer_event Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 21/32] tracing: Add hist trigger action hook Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 07/32] tracing: Increase tracing map KEYS_MAX size Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 30/32] tracing: Add inter-event hist trigger Documentation Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 31/32] tracing: Make tracing_set_clock() non-static Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 22/32] tracing: Add support for 'synthetic' events Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 12/32] tracing: Add hist trigger timestamp support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 18/32] tracing: Add simple expression support to hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 08/32] tracing: Break out hist trigger assignment parsing Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 15/32] tracing: Add usecs modifier for hist trigger timestamps Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 23/32] tracing: Add 'onmatch' hist trigger action support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 14/32] tracing: Add hist_data member to hist_field Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 26/32] tracing: Make duplicate count from tracing_map available Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 01/32] tracing: Add hist_field_name() accessor Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
[PATCH 27/32] tracing: Add cpu field for hist triggers Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-27 01:00 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Steven Rostedt <rostedt@goodmis.org> - 2017-06-27 17:10 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Masami Hiramatsu <mhiramat@kernel.org> - 2017-06-28 16:30 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support Tom Zanussi <tom.zanussi@linux.intel.com> - 2017-06-28 21:20 +0200
Re: [PATCH 00/32] tracing: Inter-event (e.g. latency) support "Joel Fernandes (Google)" <joel.opensrc@gmail.com> - 2017-07-01 09:10 +0200
csiph-web