@@ -183,16 +183,36 @@
They are:
common_timestamp u64 - timestamp (from ring buffer) associated
with the event, in nanoseconds. May be
modified by .usecs to have timestamps
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
---------------------------
The first set of examples creates aggregations using the kmalloc
event. The fields that can be used for the hist trigger are listed
in the kmalloc event's format file:
# cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
@@ -346,16 +346,75 @@ struct action_data {
char *fn_name;
unsigned int max_var_ref_idx;
struct hist_field *max_var;
struct hist_field *var;
} onmax;
};
};
+
+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);
struct synth_trace_event {
struct trace_entry ent;
u64 fields[];
};
@@ -1443,18 +1502,20 @@ static struct trace_event_file *find_var_file(struct trace_array *tr,
list_for_each_entry(var_data, &tr->hist_vars, list) {
var_hist_data = var_data->hist_data;
file = var_hist_data->event_file;
if (file == found)
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;
}
}
return found;
}
@@ -1493,16 +1554,17 @@ find_match_var(struct hist_trigger_data *hist_data, char *var_name)
char *event_name = data->onmatch.match_event;
file = find_var_file(tr, system, event_name, var_name);
if (!file)
continue;
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);
}
found = hist_field;
}
}
}
return found;
@@ -1776,16 +1838,17 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs)
ret = map_bits;
goto out;
}
attrs->map_bits = map_bits;
} else {
char *assignment;
if (attrs->n_assignments == TRACING_MAP_VARS_MAX) {
+ hist_err("Too many variables defined: ", str);
ret = -EINVAL;
goto out;
}
assignment = kstrdup(str, GFP_KERNEL);
if (!assignment) {
ret = -ENOMEM;
goto out;
@@ -2330,16 +2393,20 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
return NULL;
var_name++;
var_field = find_event_var(hist_data, system, event_name, var_name);
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;
}
static struct ftrace_event_field *
parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,
char *field_str, unsigned long *flags)
{
struct ftrace_event_field *field = NULL;
@@ -2489,16 +2556,17 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,
struct hist_field *operand1, *expr = NULL;
unsigned long operand_flags;
int ret = 0;
char *s;
/* we support only -(xxx) i.e. explicit parens required */
if (level > 3) {
+ hist_err("Too many subexpressions (3 max): ", str);
ret = -EINVAL;
goto free;
}
str++; /* skip leading '-' */
s = strchr(str, '(');
if (s)
@@ -2570,34 +2638,38 @@ static int check_expr_operands(struct hist_field *operand1,
var = find_var_field(operand2->var.hist_data, operand2->name);
if (!var)
return -EINVAL;
operand2_flags = var->flags;
}
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;
}
static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,
struct trace_event_file *file,
char *str, unsigned long flags,
char *var_name, unsigned int level)
{
struct hist_field *operand1 = NULL, *operand2 = NULL, *expr = NULL;
unsigned long operand_flags;
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);
if (field_op == FIELD_OP_NONE)
return parse_atom(hist_data, file, str, &flags, var_name);
if (field_op == FIELD_OP_UNARY_MINUS)
return parse_unary(hist_data, file, str, flags, var_name, ++level);
@@ -2821,35 +2893,43 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
unsigned int i, n, first = true;
struct field_var_hist *var_hist;
struct trace_event_file *file;
struct hist_field *key_field;
char *saved_filter;
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);
}
/*
* Look for a histogram compatible with target. We'll use the
* found histogram specification to create a new matching
* histogram with our variable on it. target_hist_data is not
* 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,
event_name, field_name);
if (!IS_ERR_OR_NULL(event_var))
return event_var;
var_hist = kzalloc(sizeof(*var_hist), GFP_KERNEL);
@@ -2898,27 +2978,31 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,
/* Create the new histogram with our variable */
ret = event_hist_trigger_func(&trigger_hist_cmd, file,
"", "hist", cmd);
if (ret) {
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);
}
kfree(cmd);
/* If we can't find the variable, something went wrong */
event_var = find_synthetic_field_var(target_hist_data, subsys_name,
event_name, field_name);
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);
}
n = target_hist_data->n_field_var_hists;
target_hist_data->field_var_hists[n] = var_hist;
target_hist_data->n_field_var_hists++;
return event_var;
@@ -3045,28 +3129,31 @@ static struct field_var *create_field_var(struct hist_trigger_data *hist_data,
char *field_name)
{
struct hist_field *val = NULL, *var = NULL;
unsigned long flags = HIST_FIELD_FL_VAR;
struct field_var *field_var;
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;
}
field_var = kzalloc(sizeof(struct field_var), GFP_KERNEL);
if (!field_var) {
kfree(val);
@@ -3199,23 +3286,27 @@ static int onmax_create(struct hist_trigger_data *hist_data,
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] != '$')
+ 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);
if (!ref_field)
return -ENOMEM;
if (init_var_ref(ref_field, var_field, NULL, NULL)) {
destroy_hist_field(ref_field, 0);
@@ -3225,30 +3316,32 @@ static int onmax_create(struct hist_trigger_data *hist_data,
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)) {
+ hist_err("onmax: Couldn't create onmax variable: ", "max");
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)) {
+ hist_err("onmax: Couldn't create field variable: ", param);
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++;
@@ -3271,16 +3364,17 @@ static int parse_action_params(char *params, struct action_data *data)
param = strsep(¶ms, ",");
if (!param) {
ret = -EINVAL;
goto out;
}
param = strstrip(param);
if (strlen(param) < 2) {
+ hist_err("Invalid action param: ", param);
ret = -EINVAL;
goto out;
}
saved_param = kstrdup(param, GFP_KERNEL);
if (!saved_param) {
ret = -ENOMEM;
goto out;
@@ -3446,16 +3540,19 @@ onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data,
if (!system) {
system = data->onmatch.match_event_system;
event = data->onmatch.match_event;
}
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;
}
static struct hist_field *
onmatch_create_field_var(struct hist_trigger_data *hist_data,
struct action_data *data, char *system,
char *event, char *var)
{
@@ -3513,16 +3610,17 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
unsigned int i, var_ref_idx;
unsigned int field_pos = 0;
struct synth_event *event;
int ret = 0;
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;
}
event->ref++;
mutex_unlock(&synth_event_mutex);
var_ref_idx = hist_data->n_var_refs;
@@ -3572,22 +3670,25 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
}
save_synth_var_ref(hist_data, var_ref);
field_pos++;
kfree(p);
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;
}
data->fn = action_trace;
data->onmatch.synth_event = event;
data->onmatch.var_ref_idx = var_ref_idx;
out:
@@ -3607,55 +3708,68 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str)
struct action_data *data;
int ret = -EINVAL;
data = kzalloc(sizeof(*data), GFP_KERNEL);
if (!data)
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) {
ret = -ENOMEM;
goto free;
}
data->onmatch.match_event_system = kstrdup(match_event_system, GFP_KERNEL);
if (!data->onmatch.match_event_system) {
ret = -ENOMEM;
goto free;
}
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) {
ret = -ENOMEM;
goto free;
}
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)
goto free;
out:
return data;
free:
onmatch_destroy(data);
@@ -3720,17 +3834,19 @@ static int create_var_field(struct hist_trigger_data *hist_data,
unsigned int val_idx,
struct trace_event_file *file,
char *var_name, char *expr_str)
{
unsigned long flags = 0;
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;
}
flags |= HIST_FIELD_FL_VAR;
hist_data->n_vars++;
if (WARN_ON(hist_data->n_vars > TRACING_MAP_VARS_MAX))
return -EINVAL;
@@ -3801,16 +3917,17 @@ static int create_key_field(struct hist_trigger_data *hist_data,
hist_field = parse_expr(hist_data, file, field_str, flags,
NULL, 0);
if (IS_ERR(hist_field)) {
ret = PTR_ERR(hist_field);
goto out;
}
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;
}
key_size = hist_field->size;
}
@@ -3914,21 +4031,23 @@ static int parse_var_defs(struct hist_trigger_data *hist_data)
str = hist_data->attrs->assignment_str[i];
for (j = 0; j < TRACING_MAP_VARS_MAX; j++) {
field_str = strsep(&str, ",");
if (!field_str)
break;
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;
}
s = kstrdup(var_name, GFP_KERNEL);
if (!s) {
ret = -ENOMEM;
goto free;
@@ -4670,16 +4789,21 @@ static int hist_show(struct seq_file *m, void *v)
goto out_unlock;
}
list_for_each_entry_rcu(data, &event_file->triggers, list) {
if (data->cmd_ops->trigger_type == ETT_EVENT_HIST)
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);
return ret;
}
static int event_hist_open(struct inode *inode, struct file *file)
{
@@ -5034,16 +5158,17 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
struct event_trigger_data *test, *named_data = NULL;
int ret = 0;
if (hist_data->attrs->name) {
named_data = find_named_trigger(hist_data->attrs->name);
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;
}
}
}
if (hist_data->attrs->name && !named_data)
goto new;
@@ -5053,23 +5178,26 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,
if (!hist_trigger_match(data, test, named_data, false))
continue;
if (hist_data->attrs->pause)
test->paused = true;
else if (hist_data->attrs->cont)
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;
}
if (hist_data->attrs->pause)
data->paused = true;
if (named_data) {
@@ -5246,16 +5374,21 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
struct event_trigger_ops *trigger_ops;
struct hist_trigger_data *hist_data;
struct synth_event *se;
const char *se_name;
bool remove = false;
char *trigger, *p;
int ret = 0;
+ if (glob && strlen(glob)) {
+ last_cmd_set(param);
+ hist_err_clear();
+ }
+
if (!param)
return -EINVAL;
if (glob[0] == '!')
remove = true;
/*
* separate the trigger from the filter (k:v [if filter])
@@ -5384,16 +5517,19 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
se = find_synth_event(se_name);
if (se)
se->ref++;
mutex_unlock(&synth_event_mutex);
/* 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);
out_free:
if (cmd_ops->set_filter)
cmd_ops->set_filter(NULL, trigger_data, NULL);
remove_hist_vars(hist_data);