tracing: common error_log for ftrace
v2 cover tracing: common error_log for ftrace
From: Tom Zanussi <[email protected]>
Last April, I posted an RFC patchset [1] implementing a common error_log interface as suggested by Masami [2]. We were supposed to discuss it at Plumbers but that never happened, and Steve recently asked about patches for a follow-on discussion [3], so here they are.
I incorporated comments from the previous discussion, the most important of which are:
- Incorporated Steve's suggestion of using static strings as in the existing trace event filter code, along with err_info indexing into the string arrays and a position for the error caret.
- Converted all the hist trigger errors and the existing trace event filter parse errors to use the new interface.
- Converted a few kprobe_event errors to the new interface as examples, but these will require more work - I didn't spend much time figuring out how to get the full kprobe command into the error info, for instance.
- Got rid of the custom single-page ring buffer and used standard lists instead.
For now, this is implemented on top of the latest 'hist trigger snapshot and onchange additions' patchset [4].
Below is an example session of a few failed commands and the corresponding error_log contents:
# echo > /sys/kernel/debug/tracing/error_log
# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -su: echo: write error: Invalid argument
# cat /sys/kernel/debug/tracing/error_log
hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^# echo 'hist:key=comm:p=prio:onchange($q).snapshot()' > /sys/kernel/debug/tracing/events/sched/sched_waking/trigger -su: echo: write error: Invalid argument
# cat /sys/kernel/debug/tracing/error_log
hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^
hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
Command: key=comm:p=prio:onchange($q).snapshot()
^# echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger # echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -su: echo: write error: File exists
# echo 'comm="cyclictest"' > /sys/kernel/debug/tracing/events/sched/sched_wakeup/filter -su: echo: write error: Invalid argument
# cat /sys/kernel/debug/tracing/error_log
hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^
hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
Command: key=comm:p=prio:onchange($q).snapshot()
^
hist:sched:sched_wakeup: error: Hist trigger already exists
Command: keys=pid
^
event filter parse error: error: Invalid operator
Command: comm="cyclictest"
^# echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > /sys/kernel/debug/tracing/events/signal/signal_generate/filter -su: echo: write error: Invalid argument
# cat /sys/kernel/debug/tracing/error_log
hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^
hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
Command: key=comm:p=prio:onchange($q).snapshot()
^
hist:sched:sched_wakeup: error: Hist trigger already exists
Command: keys=pid
^
event filter parse error: error: Invalid operator
Command: comm="cyclictest"
^
event filter parse error: error: Field not found
Command: ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
^ Thanks,
Tom
[1] https://lore.kernel.org/lkml/[email protected]/
[2] https://lore.kernel.org/lkml/[email protected]/
[3] https://lore.kernel.org/lkml/[email protected]/
[4] https://lore.kernel.org/lkml/[email protected]/
The following changes since commit 779474478eacb64a1e686a37cf663d8210d88f84:
tracing: Add hist trigger action 'expected fail' test case (2019-02-05 14:53:54 -0600)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/error_log_v2
Tom Zanussi (5):
tracing: Add tracing error log
tracing: Save the last hist command's associated event name
tracing: Use tracing error_log with hist triggers
tracing: Use tracing error_log with kprobe events (incomplete)
tracing: Use tracing error_log with trace event filters
kernel/trace/trace.c | 217 ++++++++++++++++++++++++++++++++++++ kernel/trace/trace.h | 4 + kernel/trace/trace_events_filter.c | 7 +- kernel/trace/trace_events_hist.c | 221 ++++++++++++++++++++----------------- kernel/trace/trace_probe.c | 24 +++- 5 files changed, 368 insertions(+), 105 deletions(-)
Signature · 1 line
2.14.1
RFC PATCH v2 1/5 tracing: Add tracing error log
From: Tom Zanussi <[email protected]>
Introduce a new ftrace file, tracing/error_log, for ftrace commands to log errors. This is useful for allowing more complex commands such as hist trigger and kprobe_event commands to point out specifically where something may have gone wrong without forcing them to resort to more ad hoc methods such as tacking error messages onto existing output files.
To log a tracing error, call the event_log_err() function, passing it a location string describing where it came from e.g. kprobe_events or system:event, the command that caused the error, an array of static error strings describing errors and an index within that array which describes the specific error, along with the position to place the error caret.
Reading the log displays the last (currently) 8 errors logged in the following format:
<loc>: error: <static error text>
Command: <command that caused the error>
^
Memory for the error log isn't allocated unless there has been a trace event error, and the error log can be cleared and have its memory freed by writing the empty string in truncation mode to it:
# echo > tracing/error_log.
--- kernel/trace/trace.c | 217 +++++++++++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace.h | 4 + 2 files changed, 221 insertions(+)
kernel/trace/trace.c +217 -0
@@ -6862,6 +6862,220 @@ static const struct file_operations snapshot_raw_fops = {#endif /* CONFIG_TRACER_SNAPSHOT */ +#define TRACING_LOG_ERRS_MAX 8 +#define TRACING_LOG_LOC_MAX 128 + +#define CMD_PREFIX " Command: " + +struct err_info { +const char **errs;/* ptr to loc-specific array of err strings */ +u8 type;/* index into errs -> specific err string */ +u8 pos;/* MAX_FILTER_STR_VAL = 256 */ +}; + +struct tracing_log_err { +struct list_head list; +struct err_info info; +char loc[TRACING_LOG_LOC_MAX ];/* err location */ +char cmd[MAX_FILTER_STR_VAL ];/* what caused err */ +}; + +static LIST_HEAD (tracing_err_log); +static DEFINE_MUTEX (tracing_err_log_lock); + +static unsigned int n_tracing_err_log_entries; + +struct tracing_log_err *get_tracing_log_err (void ) +{ +struct tracing_log_err *err; + +if (n_tracing_err_log_entries <TRACING_LOG_ERRS_MAX ) { + err =kzalloc (sizeof (*err),GFP_KERNEL ); +if (!err) + err =ERR_PTR (-ENOMEM ); + n_tracing_err_log_entries++; + +return err; + } + + err = list_first_entry(&tracing_err_log, struct tracing_log_err, list); +list_del (&err->list); + +return err; +} + +/** +* err_pos - find the position of a string within a command for error careting +* @cmd: The tracing command that caused the error +* @str: The string to position the caret at within @cmd +* +* Finds the position of the first occurence of @str within @cmd. The +* return value can be passed to tracing_log_err() for caret placement +* within @cmd. +* +* Returns the index within @cmd of the first occurence of @str or 0 +* if @str was not found. +*/ +unsigned int err_pos (char *cmd,const char *str) +{ +char *found; + +if (WARN_ON (!strlen (cmd))) +return 0 ; + + found =strstr (cmd, str); +if (found) +return found - cmd; + +return 0 ; +} + +/** +* tracing_log_err - write an error to the tracing error log +* @loc: A string describing where the error occurred +* @cmd: The tracing command that caused the error +* @errs: The array of loc-specific static error strings +* @type: The index into errs[], which produces the specific static err string +* @pos: The position the caret should be placed in the cmd +* +* Writes an error into tracing/error_log of the form: +* +* <loc>: error: <text> +* Command: <cmd> +* ^ +* +* tracing/error_log is a small log file containing the last +* TRACING_LOG_ERRS_MAX errors (8). Memory for errors isn't allocated +* unless there has been a tracing error, and the error log can be +* cleared and have its memory freed by writing the empty string in +* truncation mode to it i.e. echo > tracing/error_log. +* +* NOTE: the @errs array along with the @type param are used to +* produce a static error string - this string is not copied and saved +* when the error is logged - only a pointer to it is saved. See +* existing callers for examples of how static strings are typically +* defined for use with tracing_log_err(). +*/ +void tracing_log_err (const char *loc,const char *cmd, +const char **errs,u8 type,u8 pos) +{ +struct tracing_log_err *err; + +mutex_lock (&tracing_err_log_lock); + err =get_tracing_log_err (); +if (PTR_ERR (err) == -ENOMEM ) { +mutex_unlock (&tracing_err_log_lock); +return ; + } + +snprintf (err->loc,TRACING_LOG_LOC_MAX ,"%s: error: " , loc); +snprintf (err->cmd,MAX_FILTER_STR_VAL ,"\n" CMD_PREFIX "%s\n" , cmd); + + err->info.errs = errs; + err->info.type = type; + err->info.pos = pos; + +list_add_tail (&err->list, &tracing_err_log); +mutex_unlock (&tracing_err_log_lock); +} + +static void clear_tracing_err_log (void ) +{ +struct tracing_log_err *err, *next; + +mutex_lock (&tracing_err_log_lock); +list_for_each_entry_safe (err, next, &tracing_err_log, list) { +list_del (&err->list); +kfree (err); + } + + n_tracing_err_log_entries =0 ; +mutex_unlock (&tracing_err_log_lock); +} + +static void *tracing_err_log_seq_start (struct seq_file *m,loff_t *pos) +{ +mutex_lock (&tracing_err_log_lock); + +return seq_list_start (&tracing_err_log, *pos); +} + +static void *tracing_err_log_seq_next (struct seq_file *m,void *v,loff_t *pos) +{ +return seq_list_next (v, &tracing_err_log, pos); +} + +static void tracing_err_log_seq_stop (struct seq_file *m,void *v) +{ +mutex_unlock (&tracing_err_log_lock); +} + +static void tracing_err_log_show_pos (struct seq_file *m,u8 pos) +{ +u8 i; + +for (i =0 ; i <sizeof (CMD_PREFIX ) -1 ; i++) +seq_putc (m,' ' ); +for (i =0 ; i < pos; i++) +seq_putc (m,' ' ); +seq_puts (m,"^\n" ); +} + +static int tracing_err_log_seq_show (struct seq_file *m,void *v) +{ +struct tracing_log_err *err = v; + +if (err) { +const char *err_text = err->info.errs[err->info.type]; + +seq_printf (m,"%s%s" , err->loc, err_text); +seq_printf (m,"%s" , err->cmd); +tracing_err_log_show_pos (m, err->info.pos); + } + +return 0 ; +} + +static const struct seq_operations tracing_err_log_seq_ops = { + .start = tracing_err_log_seq_start, + .next = tracing_err_log_seq_next, + .stop = tracing_err_log_seq_stop, + .show = tracing_err_log_seq_show +}; + +static int tracing_err_log_open (struct inode *inode,struct file *file) +{ +if (file->f_mode &FMODE_WRITE ) { +if (file->f_flags &O_TRUNC ) +return 0 ; +else +return -EINVAL ; + } + +return seq_open (file, &tracing_err_log_seq_ops); +} + +static ssize_t tracing_err_log_write (struct file *file, +const char __user *buffer, +size_t count,loff_t *ppos) +{ +if (count ==1 ) +clear_tracing_err_log (); +else +return -EINVAL ; + + *ppos += count; + +return count; +} + +static const struct file_operations tracing_err_log_fops = { + .open = tracing_err_log_open, + .write = tracing_err_log_write, + .read = seq_read, + .llseek = seq_lseek, +}; +static int tracing_buffers_open (struct inode *inode,struct file *filp) {struct trace_array *tr = inode->i_private;
@@ -8245,6 +8459,9 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer) tr, &snapshot_fops);#endif +trace_create_file ("error_log" ,0644 , d_tracer, + tr, &tracing_err_log_fops); +for_each_tracing_cpu (cpu)tracing_init_tracefs_percpu (tr, cpu);
kernel/trace/trace.h +4 -0
@@ -1884,6 +1884,10 @@ extern ssize_t trace_parse_run_command(struct file *file, const char __user *buffer, size_t count, loff_t *ppos, int (*createfn)(int, char**)); +extern unsigned int err_pos (char *cmd,const char *str); +extern void tracing_log_err (const char *loc,const char *cmd, +const char **errs,u8 type,u8 pos); +/* * Normal trace_printk() and friends allocates special buffers * to do the manipulation, as well as saves the print formats
Signature · 1 line
2.14.1
RFC PATCH v2 2/5 tracing: Save the last hist command's associated event name
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
In preparation for making use of the new trace error log, save the subsystem and event name associated with the last hist command - it will be passed as the location param in the event_log_err() calls.
--- kernel/trace/trace_events_hist.c | 33 +++++++++++++++++++++++++++------ 1 file changed, 27 insertions(+), 6 deletions(-)
kernel/trace/trace_events_hist.c +27 -6
@@ -536,15 +536,34 @@ static struct track_data *track_data_alloc(unsigned int key_len,return data; } -static char last_hist_cmd[MAX_FILTER_STR_VAL ]; +static char last_cmd[MAX_FILTER_STR_VAL ]; +static char last_cmd_loc[MAX_FILTER_STR_VAL ]; +static char hist_err_str[MAX_FILTER_STR_VAL ]; -static void last_cmd_set (char *str) +static void last_cmd_set (struct trace_event_file *file,char *str) { +const char *system =NULL , *name =NULL ; +struct trace_event_call *call; +if (!str)return ; -strncpy (last_hist_cmd, str,MAX_FILTER_STR_VAL -1 ); +strncpy (last_cmd, str,MAX_FILTER_STR_VAL -1 ); + +if (file) { + call = file->event_call; + + system = call->class->system; +if (system) { + name =trace_event_name (call); +if (!name) + system =NULL ; + } + } + +if (system) +snprintf (last_cmd_loc,MAX_FILTER_STR_VAL ,"hist:%s:%s" , system, name); }static void hist_err (char *str,char *var)
@@ -584,6 +603,8 @@ static void hist_err_event(char *str, char *system, char *event, char *var)static void hist_err_clear (void ) { hist_err_str[0 ] ='\0' ; + last_cmd[0 ] ='\0' ; + last_cmd_loc[0 ] ='\0' ; }static bool have_hist_err (void )
@@ -5440,8 +5461,8 @@ static int hist_show(struct seq_file *m, void *v) }if (have_hist_err ()) { -seq_printf (m,"\nERROR: %s\n" , hist_err_str); -seq_printf (m," Last command: %s\n" , last_hist_cmd); +seq_printf (m,"\n%s: error: \n" , hist_err_str); +seq_printf (m," Last command: %s\n" , last_cmd); } out_unlock:
@@ -6045,8 +6066,8 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,lockdep_assert_held (&event_mutex);if (glob &&strlen (glob)) { -last_cmd_set (param);hist_err_clear (); +last_cmd_set (file, param); }if (!param)
Signature · 1 line
2.14.1
RFC PATCH v2 3/5 tracing: Use tracing error_log with hist triggers
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Replace hist_err() and hist_err_event() with tracing_log_err() from the new tracing error_log mechanism.
Also add a couple related helper functions and remove most of the old hist_err()-related code.
With this change, users no longer read the hist files for hist trigger error information, but instead look at tracing/error_log for the same information.
--- kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++------------------- 1 file changed, 104 insertions(+), 102 deletions(-)
kernel/trace/trace_events_hist.c +104 -102
@@ -22,6 +22,57 @@#define STR_VAR_LEN_MAX 32/* must be multiple of sizeof(u64) */ +#define ERRORS \ + C(NONE, "No error"), \ + C(DUPLICATE_VAR, "Variable already defined"), \ + C(VAR_NOT_UNIQUE, "Variable name not unique, need to use fully qualified name (subsys.event.var) for variable"), \ + C(TOO_MANY_VARS, "Too many variables defined"), \ + C(MALFORMED_ASSIGNMENT, "Malformed assignment"), \ + C(NAMED_MISMATCH, "Named hist trigger doesn't match existing named trigger (includes variables)"), \ + C(TRIGGER_EEXIST, "Hist trigger already exists"), \ + C(TRIGGER_ENOENT_CLEAR, "Can't clear or continue a nonexistent hist trigger"), \ + C(SET_CLOCK_FAIL, "Couldn't set trace_clock"), \ + C(BAD_FIELD_MODIFIER, "Invalid field modifier"), \ + C(TOO_MANY_SUBEXPR, "Too many subexpressions (3 max)"), \ + C(TIMESTAMP_MISMATCH, "Timestamp units in expression don't match"), \ + C(TOO_MANY_FIELD_VARS, "Too many field variables defined"), \ + C(EVENT_FILE_NOT_FOUND, "Event file not found"), \ + C(HIST_NOT_FOUND, "Matching event histogram not found"), \ + C(HIST_CREATE_FAIL, "Couldn't create histogram for field"), \ + C(SYNTH_VAR_NOT_FOUND, "Couldn't find synthetic variable"), \ + C(SYNTH_EVENT_NOT_FOUND,"Couldn't find synthetic event"), \ + C(SYNTH_TYPE_MISMATCH, "Param type doesn't match synthetic event field type"), \ + C(SYNTH_COUNT_MISMATCH, "Param count doesn't match synthetic event field count"), \ + C(FIELD_VAR_PARSE_FAIL, "Couldn't parse field variable"), \ + C(VAR_CREATE_FIND_FAIL, "Couldn't create or find variable"), \ + C(ONX_NOT_VAR, "For onmax(x) or onchange(x), x must be a variable"), \ + C(ONX_VAR_NOT_FOUND, "Couldn't find onmax or onchange variable"), \ + C(ONX_VAR_CREATE_FAIL, "Couldn't create onmax or onchange variable"), \ + C(FIELD_VAR_CREATE_FAIL,"Couldn't create field variable"), \ + C(TOO_MANY_PARAMS, "Too many action params"), \ + C(PARAM_NOT_FOUND, "Couldn't find param"), \ + C(INVALID_PARAM, "Invalid action param"), \ + C(ACTION_NOT_FOUND, "No action found"), \ + C(NO_SAVE_PARAMS, "No params found for save()"), \ + C(TOO_MANY_SAVE_ACTIONS,"Can't have more than one save() action per hist"), \ + C(ACTION_MISMATCH, "Handler doesn't support action"), \ + C(NO_CLOSING_PAREN, "No closing paren found"), \ + C(SUBSYS_NOT_FOUND, "Missing subsystem"), \ + C(INVALID_SUBSYS_EVENT, "Invalid subsystem or event name"), \ + C(INVALID_REF_KEY, "Using variable references as keys not supported"), \ + C(VAR_NOT_FOUND, "Couldn't find variable"), \ + C(FIELD_NOT_FOUND, "Couldn't find field"), + +#undef C +#define C (a, b) HIST_ERR_##a + +enum {ERRORS }; + +#undef C +#define C (a, b) b + +static const char *err_text[] = {ERRORS }; +struct hist_field ; typedef u64 (*hist_field_fn_t) (struct hist_field *field,
@@ -539,7 +590,10 @@ static struct track_data *track_data_alloc(unsigned int key_len,static char last_cmd[MAX_FILTER_STR_VAL ];static char last_cmd_loc[MAX_FILTER_STR_VAL ]; -static char hist_err_str[MAX_FILTER_STR_VAL ]; +static int errpos (char *str) +{ +return err_pos (last_cmd, str); +}static void last_cmd_set (struct trace_event_file *file,char *str) {
@@ -566,55 +620,17 @@ static void last_cmd_set(struct trace_event_file *file, char *str)snprintf (last_cmd_loc,MAX_FILTER_STR_VAL ,"hist:%s:%s" , system, name); } -static void hist_err (char *str,char *var) +static void hist_err (u8 err_type,u8 err_pos) { -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 -strscpy (err, var,MAX_FILTER_STR_VAL ); - -hist_err (str, err); +tracing_log_err (last_cmd_loc, last_cmd, err_text, err_type, err_pos); }static void hist_err_clear (void ) { - hist_err_str[0 ] ='\0' ; last_cmd[0 ] ='\0' ; last_cmd_loc[0 ] ='\0' ; } -static bool have_hist_err (void ) -{ -if (strlen (hist_err_str)) -return true; - -return false; -} -struct synth_trace_event {struct trace_entry ent;u64 fields[];
@@ -1741,7 +1757,7 @@ static struct trace_event_file *find_var_file(struct trace_array *tr,if (find_var_field (var_hist_data, var_name)) {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); +hist_err (HIST_ERR_VAR_NOT_UNIQUE ,errpos (var_name));return NULL ; }
@@ -1792,7 +1808,7 @@ find_match_var(struct hist_trigger_data *hist_data, char *var_name) 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); +hist_err (HIST_ERR_VAR_NOT_UNIQUE ,errpos (var_name));return ERR_PTR (-EINVAL ); }
@@ -2024,7 +2040,6 @@ static int parse_action(char *str, struct hist_trigger_attrs *attrs) attrs->n_actions++; ret =0 ; } -return ret; }
@@ -2084,7 +2099,7 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs)char *assignment;if (attrs->n_assignments ==TRACING_MAP_VARS_MAX ) { -hist_err ("Too many variables defined: " , str); +hist_err (HIST_ERR_TOO_MANY_VARS ,errpos (str)); ret = -EINVAL ; goto out; }
@@ -2682,8 +2697,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data, system, event_name);if (!ref_field) -hist_err_event ("Couldn't find variable: $" , - system, event_name, var_name); +hist_err (HIST_ERR_VAR_NOT_FOUND ,errpos (var_name));return ref_field; }
@@ -2717,7 +2731,7 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,else if (strcmp (modifier,"usecs" ) ==0 ) *flags |=HIST_FIELD_FL_TIMESTAMP_USECS ;else { -hist_err ("Invalid field modifier: " , modifier); +hist_err (HIST_ERR_BAD_FIELD_MODIFIER ,errpos (modifier)); field =ERR_PTR (-EINVAL ); goto out; }
@@ -2733,7 +2747,7 @@ parse_field(struct hist_trigger_data *hist_data, struct trace_event_file *file,else { field =trace_find_event_field (file->event_call, field_name);if (!field || !field->size) { -hist_err ("Couldn't find field: " , field_name); +hist_err (HIST_ERR_FIELD_NOT_FOUND ,errpos (field_name)); field =ERR_PTR (-EINVAL ); goto out; }
@@ -2844,7 +2858,7 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data,/* we support only -(xxx) i.e. explicit parens required */ if (level >3 ) { -hist_err ("Too many subexpressions (3 max): " , str); +hist_err (HIST_ERR_TOO_MANY_SUBEXPR ,errpos (str)); ret = -EINVAL ; goto free; }
@@ -2927,7 +2941,7 @@ static int check_expr_operands(struct hist_field *operand1,if ((operand1_flags &HIST_FIELD_FL_TIMESTAMP_USECS ) != (operand2_flags &HIST_FIELD_FL_TIMESTAMP_USECS )) { -hist_err ("Timestamp units in expression don't match" ,NULL ); +hist_err (HIST_ERR_TIMESTAMP_MISMATCH ,0 );return -EINVAL ; }
@@ -2945,7 +2959,7 @@ static struct hist_field *parse_expr(struct hist_trigger_data *hist_data,char *sep, *operand1_str;if (level >3 ) { -hist_err ("Too many subexpressions (3 max): " , str); +hist_err (HIST_ERR_TOO_MANY_SUBEXPR ,errpos (str));return ERR_PTR (-EINVAL ); }
@@ -3183,16 +3197,14 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,int ret;if (target_hist_data->n_field_var_hists >=SYNTH_FIELDS_MAX ) { -hist_err_event ("trace action: Too many field variables defined: " , - subsys_name, event_name, field_name); +hist_err (HIST_ERR_TOO_MANY_FIELD_VARS ,errpos (field_name));return ERR_PTR (-EINVAL ); } file =event_file (tr, subsys_name, event_name);if (IS_ERR (file)) { -hist_err_event ("trace action: Event file not found: " , - subsys_name, event_name, field_name); +hist_err (HIST_ERR_EVENT_FILE_NOT_FOUND ,errpos (field_name)); ret =PTR_ERR (file);return ERR_PTR (ret); }
@@ -3205,8 +3217,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,*/ hist_data =find_compatible_hist (target_hist_data, file);if (!hist_data) { -hist_err_event ("trace action: Matching event histogram not found: " , - subsys_name, event_name, field_name); +hist_err (HIST_ERR_HIST_NOT_FOUND ,errpos (field_name));return ERR_PTR (-EINVAL ); }
@@ -3267,8 +3278,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,kfree (cmd);kfree (var_hist->cmd);kfree (var_hist); -hist_err_event ("trace action: Couldn't create histogram for field: " , - subsys_name, event_name, field_name); +hist_err (HIST_ERR_HIST_CREATE_FAIL ,errpos (field_name));return ERR_PTR (ret); }
@@ -3280,8 +3290,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data,if (IS_ERR_OR_NULL (event_var)) {kfree (var_hist->cmd);kfree (var_hist); -hist_err_event ("trace action: Couldn't find synthetic variable: " , - subsys_name, event_name, field_name); +hist_err (HIST_ERR_SYNTH_VAR_NOT_FOUND ,errpos (field_name));return ERR_PTR (-EINVAL ); }
@@ -3418,21 +3427,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); +hist_err (HIST_ERR_TOO_MANY_FIELD_VARS ,errpos (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); +hist_err (HIST_ERR_FIELD_VAR_PARSE_FAIL ,errpos (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); +hist_err (HIST_ERR_VAR_CREATE_FIND_FAIL ,errpos (field_name));kfree (val); ret =PTR_ERR (var); goto err;
@@ -3765,14 +3774,14 @@ static int track_data_create(struct hist_trigger_data *hist_data, track_data_var_str = data->track_data.var_str;if (track_data_var_str[0 ] !='$' ) { -hist_err ("For onmax(x) or onchange(x), x must be a variable: " , track_data_var_str); +hist_err (HIST_ERR_ONX_NOT_VAR ,errpos (track_data_var_str));return -EINVAL ; } track_data_var_str++; var_field =find_target_event_var (hist_data,NULL ,NULL , track_data_var_str);if (!var_field) { -hist_err ("Couldn't find onmax or onchange variable: " , track_data_var_str); +hist_err (HIST_ERR_ONX_VAR_NOT_FOUND ,errpos (track_data_var_str));return -EINVAL ; }
@@ -3785,7 +3794,7 @@ static int track_data_create(struct hist_trigger_data *hist_data,if (data->handler ==HANDLER_ONMAX ) track_var =create_var (hist_data, file,"__max" ,sizeof (u64),"u64" );if (IS_ERR (track_var)) { -hist_err ("Couldn't create onmax variable: " ,"__max" ); +hist_err (HIST_ERR_ONX_VAR_CREATE_FAIL ,0 ); ret =PTR_ERR (track_var); goto out; }
@@ -3793,7 +3802,7 @@ static int track_data_create(struct hist_trigger_data *hist_data,if (data->handler ==HANDLER_ONCHANGE ) track_var =create_var (hist_data, file,"__change" ,sizeof (u64),"u64" );if (IS_ERR (track_var)) { -hist_err ("Couldn't create onchange variable: " ,"__change" ); +hist_err (HIST_ERR_ONX_VAR_CREATE_FAIL ,0 ); ret =PTR_ERR (track_var); goto out; }
@@ -3812,20 +3821,20 @@ static int parse_action_params(char *params, struct action_data *data)while (params) {if (data->n_params >=SYNTH_FIELDS_MAX ) { -hist_err ("Too many action params" ,"" ); +hist_err (HIST_ERR_TOO_MANY_PARAMS ,0 ); goto out; } param =strsep (¶ms,"," );if (!param) { -hist_err ("No action param found" ,"" ); +hist_err (HIST_ERR_PARAM_NOT_FOUND ,0 ); ret = -EINVAL ; goto out; } param =strstrip (param);if (strlen (param) <2 ) { -hist_err ("Invalid action param: " , param); +hist_err (HIST_ERR_INVALID_PARAM ,errpos (param)); ret = -EINVAL ; goto out; }
@@ -3857,14 +3866,14 @@ static int action_parse(char *str, struct action_data *data,strsep (&str,"." );if (!str) { -hist_err ("action parsing: No action found" ,"" ); +hist_err (HIST_ERR_ACTION_NOT_FOUND ,0 ); ret = -EINVAL ; goto out; } action_name =strsep (&str,"(" );if (!action_name || !str) { -hist_err ("action parsing: No action found" ,"" ); +hist_err (HIST_ERR_ACTION_NOT_FOUND ,0 ); ret = -EINVAL ; goto out; }
@@ -3873,7 +3882,7 @@ static int action_parse(char *str, struct action_data *data,char *params =strsep (&str,")" );if (!params) { -hist_err ("action parsing: No params found for %s" ,"save" ); +hist_err (HIST_ERR_NO_SAVE_PARAMS ,0 ); ret = -EINVAL ; goto out; }
@@ -3887,7 +3896,7 @@ static int action_parse(char *str, struct action_data *data,else if (handler ==HANDLER_ONCHANGE ) data->track_data.check_val = check_track_val_changed;else { -hist_err ("action parsing: Handler doesn't support action: " , action_name); +hist_err (HIST_ERR_ACTION_MISMATCH ,errpos (action_name)); ret = -EINVAL ; goto out; }
@@ -3899,7 +3908,7 @@ static int action_parse(char *str, struct action_data *data,char *params =strsep (&str,")" );if (!str) { -hist_err ("action parsing: No closing paren found: %s" , params); +hist_err (HIST_ERR_NO_CLOSING_PAREN ,errpos (params)); ret = -EINVAL ; goto out; }
@@ -3909,7 +3918,7 @@ static int action_parse(char *str, struct action_data *data,else if (handler ==HANDLER_ONCHANGE ) data->track_data.check_val = check_track_val_changed;else { -hist_err ("action parsing: Handler doesn't support action: " , action_name); +hist_err (HIST_ERR_ACTION_MISMATCH ,errpos (action_name)); ret = -EINVAL ; goto out; }
@@ -4062,7 +4071,7 @@ trace_action_find_var(struct hist_trigger_data *hist_data, }if (!hist_field) -hist_err_event ("trace action: Couldn't find param: $" , system, event, var); +hist_err (HIST_ERR_PARAM_NOT_FOUND ,errpos (var));return hist_field; }
@@ -4137,7 +4146,7 @@ static int trace_action_create(struct hist_trigger_data *hist_data, event =find_synth_event (synth_event_name);if (!event) { -hist_err ("trace action: Couldn't find synthetic event: " , synth_event_name); +hist_err (HIST_ERR_SYNTH_EVENT_NOT_FOUND ,errpos (synth_event_name));return -EINVAL ; }
@@ -4198,15 +4207,14 @@ static int trace_action_create(struct hist_trigger_data *hist_data,continue ; } -hist_err_event ("trace action: Param type doesn't match synthetic event field type: " , - system, event_name, param); +hist_err (HIST_ERR_SYNTH_TYPE_MISMATCH ,errpos (param));kfree (p); ret = -EINVAL ; goto err; }if (field_pos != event->n_fields) { -hist_err ("trace action: Param count doesn't match synthetic event field count: " , event->name); +hist_err (HIST_ERR_SYNTH_COUNT_MISMATCH ,errpos (event->name)); ret = -EINVAL ; goto err; }
@@ -4252,7 +4260,7 @@ static int action_create(struct hist_trigger_data *hist_data,if (data->action ==ACTION_SAVE ) {if (hist_data->n_save_vars) { ret = -EEXIST ; -hist_err ("save action: Can't have more than one save() action per hist" ,"" ); +hist_err (HIST_ERR_TOO_MANY_SAVE_ACTIONS ,0 ); goto out; }
@@ -4265,7 +4273,7 @@ static int action_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 ("save action: Couldn't create field variable: " , param); +hist_err (HIST_ERR_FIELD_VAR_CREATE_FAIL ,errpos (param)); ret =PTR_ERR (field_var);kfree (param); goto out;
@@ -4299,19 +4307,18 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str) match_event =strsep (&str,")" );if (!match_event || !str) { -hist_err ("onmatch: Missing closing paren: " , match_event); +hist_err (HIST_ERR_NO_CLOSING_PAREN ,errpos (match_event)); goto free; } match_event_system =strsep (&match_event,"." );if (!match_event) { -hist_err ("onmatch: Missing subsystem for match event: " , match_event_system); +hist_err (HIST_ERR_SUBSYS_NOT_FOUND ,errpos (match_event_system)); goto free; }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 ); +hist_err (HIST_ERR_INVALID_SUBSYS_EVENT ,errpos (match_event)); goto free; }
@@ -4402,7 +4409,7 @@ static int create_var_field(struct hist_trigger_data *hist_data,return -EINVAL ;if (find_var (hist_data, file, var_name) && !hist_data->remove) { -hist_err ("Variable already defined: " , var_name); +hist_err (HIST_ERR_DUPLICATE_VAR ,errpos (var_name));return -EINVAL ; }
@@ -4483,7 +4490,7 @@ static int create_key_field(struct hist_trigger_data *hist_data, }if (hist_field->flags &HIST_FIELD_FL_VAR_REF ) { -hist_err ("Using variable references as keys not supported: " , field_str); +hist_err (HIST_ERR_INVALID_REF_KEY ,errpos (field_str));destroy_hist_field (hist_field,0 ); ret = -EINVAL ; goto out;
@@ -4597,13 +4604,13 @@ static int parse_var_defs(struct hist_trigger_data *hist_data) var_name =strsep (&field_str,"=" );if (!var_name || !field_str) { -hist_err ("Malformed assignment: " , var_name); +hist_err (HIST_ERR_MALFORMED_ASSIGNMENT ,errpos (var_name)); ret = -EINVAL ; goto free; }if (n_vars ==TRACING_MAP_VARS_MAX ) { -hist_err ("Too many variables defined: " , var_name); +hist_err (HIST_ERR_TOO_MANY_VARS ,errpos (var_name)); ret = -EINVAL ; goto free; }
@@ -5460,11 +5467,6 @@ static int hist_show(struct seq_file *m, void *v)hist_trigger_show (m, data, n++); } -if (have_hist_err ()) { -seq_printf (m,"\n%s: error: \n" , hist_err_str); -seq_printf (m," Last command: %s\n" , last_cmd); - } - out_unlock:mutex_unlock (&event_mutex);
@@ -5836,7 +5838,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); +hist_err (HIST_ERR_NAMED_MISMATCH ,errpos (hist_data->attrs->name)); ret = -EINVAL ; goto out; }
@@ -5857,7 +5859,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops,else if (hist_data->attrs->clear)hist_clear (test);else { -hist_err ("Hist trigger already exists" ,NULL ); +hist_err (HIST_ERR_TRIGGER_EEXIST ,0 ); ret = -EEXIST ; } goto out;
@@ -5865,7 +5867,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops, } new:if (hist_data->attrs->cont || hist_data->attrs->clear) { -hist_err ("Can't clear or continue a nonexistent hist trigger" ,NULL ); +hist_err (HIST_ERR_TRIGGER_ENOENT_CLEAR ,0 ); ret = -ENOENT ; goto out; }
@@ -5890,7 +5892,7 @@ static int hist_register_trigger(char *glob, struct event_trigger_ops *ops, ret =tracing_set_clock (file->tr, hist_data->attrs->clock);if (ret) { -hist_err ("Couldn't set trace_clock: " , clock); +hist_err (HIST_ERR_SET_CLOCK_FAIL ,errpos (clock)); goto out; }
Signature · 1 line
2.14.1
RFC PATCH v2 4/5 tracing: Use tracing error_log with kprobe events (incomplete)
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Here are a few examples of replacing kprobe_events error handling with tracing_log_err() from the new tracing error_log mechanism. Only a few example errors are converted, and even these are incomplete, since I didn't know where to get the current command and used a dummy string for those. Also, these are completely untested, just provided for RFC purposes.
With this change, users will find some kprobe_events errors in tracing/error_log instead of dmesg.
TODO: If acceptable, convert all the rest of the kprobe errors and figure out how to get the actual cmd logged along with the error.
--- kernel/trace/trace_probe.c | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-)
kernel/trace/trace_probe.c +20 -4
@@ -13,6 +13,22 @@#include "trace_probe.h" +#define ERRORS \ + C(NONE, "No error"), \ + C(INVALID_STRING_SPEC, "string only accepts memory or address."), \ + C(ARG_TOO_LONG, "Argument is too long."), \ + C(INVALID_ARG_NAME, "Invalid argument name"), + +#undef C +#define C (a, b) KPROBE_ERR_##a + +enum {ERRORS }; + +#undef C +#define C (a, b) b + +static const char *err_text[] = {ERRORS }; +const char *reserved_field_names[] = {"common_type" ,"common_flags" ,
@@ -384,7 +400,7 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,int ret, len;if (strlen (arg) >MAX_ARGSTR_LEN ) { -pr_info ("Argument is too long.: %s\n" , arg); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_ARG_TOO_LONG ,err_pos ("command" , arg));return -ENOSPC ; } parg->comm =kstrdup (arg,GFP_KERNEL );
@@ -443,7 +459,8 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,if (!strcmp (parg->type->name,"string" )) {if (code->op !=FETCH_OP_DEREF && code->op !=FETCH_OP_IMM && code->op !=FETCH_OP_COMM ) { -pr_info ("string only accepts memory or address.\n" ); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_INVALID_STRING_SPEC ,0 ); + ret = -EINVAL ; goto fail; }
@@ -558,8 +575,7 @@ int traceprobe_parse_probe_arg(struct trace_probe *tp, int i, char *arg,return -ENOMEM ;if (!is_good_name (parg->name)) { -pr_info ("Invalid argument[%d] name: %s\n" , - i, parg->name); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_INVALID_ARG_NAME ,err_pos ("cmd" , parg->name));return -EINVAL ; }
Signature · 1 line
2.14.1
Masami Hiramatsu
maintainerRe: [RFC PATCH v2 4/5] tracing: Use tracing error_log with kprobe events (incomplete)
Hi Tom,
Quoted 8 lines · On Wed, 13 Feb 2019 12:17:55 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Here are a few examples of replacing
kprobe_eventserror handling withtracing_log_err()from the new tracingerror_logmechanism. Only a few example errors are converted, and even these are incomplete, since I didn't know where to get the current command and used a dummy string for those. Also, these are completely untested, just provided for RFC purposes.
OK, can I take this over? I would like to try to use this framework.
Quoted 3 lines
With this change, users will find some
kprobe_eventserrors in tracing/error_log instead of dmesg.
Yes, that is much better, especially for ftracetest.
Thank you,
Quoted 68 lines
TODO: If acceptable, convert all the rest of the kprobe errors and figure out how to get the actual cmd logged along with the error.
Signed-off-by Tom Zanussi <[email protected]>--- kernel/trace/trace_probe.c | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-)kernel/trace/trace_probe.c +20
-4@@ -13,6 +13,22 @@#include "trace_probe.h" +#define ERRORS \ + C(NONE, "No error"), \ + C(INVALID_STRING_SPEC, "string only accepts memory or address."), \ + C(ARG_TOO_LONG, "Argument is too long."), \ + C(INVALID_ARG_NAME, "Invalid argument name"), + +#undef C +#define C (a, b) KPROBE_ERR_##a + +enum {ERRORS }; + +#undef C +#define C (a, b) b + +static const char *err_text[] = {ERRORS }; +const char *reserved_field_names[] = {"common_type" ,"common_flags" ,@@ -384,7 +400,7 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,int ret, len;if (strlen (arg) >MAX_ARGSTR_LEN ) { -pr_info ("Argument is too long.: %s\n" , arg); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_ARG_TOO_LONG ,err_pos ("command" , arg));return -ENOSPC ; } parg->comm =kstrdup (arg,GFP_KERNEL );@@ -443,7 +459,8 @@ static int traceprobe_parse_probe_arg_body(char *arg, ssize_t *size,if (!strcmp (parg->type->name,"string" )) {if (code->op !=FETCH_OP_DEREF && code->op !=FETCH_OP_IMM && code->op !=FETCH_OP_COMM ) { -pr_info ("string only accepts memory or address.\n" ); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_INVALID_STRING_SPEC ,0 ); + ret = -EINVAL ; goto fail; }@@ -558,8 +575,7 @@ int traceprobe_parse_probe_arg(struct trace_probe *tp, int i, char *arg,return -ENOMEM ;if (!is_good_name (parg->name)) { -pr_info ("Invalid argument[%d] name: %s\n" , - i, parg->name); +tracing_log_err ("kprobe_events" ,"replace this with command" , err_text,KPROBE_ERR_INVALID_ARG_NAME ,err_pos ("cmd" , parg->name));return -EINVAL ; }Signature · 1 line
2.14.1
Signature · 1 line
Masami Hiramatsu <[email protected]>
Re: [RFC PATCH v2 4/5] tracing: Use tracing error_log with kprobe events (incomplete)
Hi Masami,
Quoted 17 lines · Masami Hiramatsu
Hi Tom,
Quoted 11 lines · On Wed, 13 Feb 2019 12:17:55 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Here are a few examples of replacing
kprobe_eventserror handling withtracing_log_err()from the new tracingerror_logmechanism. Only a few example errors are converted, and even these are incomplete, since
I didn't know where to get the current command and used a dummy string
for those. Also, these are completely untested, just provided for RFC purposes.
Quoted 2 lines
OK, can I take this over? I would like to try to use this framework.
Sure, be my guest. ;-)
Thanks,
Tom
RFC PATCH v2 5/5 tracing: Use tracing error_log with trace event filters
In reply to Tom ZanussiFrom: Tom Zanussi <[email protected]>
Use tracing_log_err() from the new tracing error_log mechanism to send filter parse errors to tracing/error_log.
With this change, users will be able to see filter errors by looking at tracing/error_log.
The same errors will also be available in the filter file, as expected.
--- kernel/trace/trace_events_filter.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-)
kernel/trace/trace_events_filter.c +5 -2
@@ -66,7 +66,8 @@ static const char * ops[] = { OPS };C (INVALID_FILTER ,"Meaningless filter expression" ), \C (IP_FIELD_ONLY ,"Only 'ip' field is supported for function trace" ), \C (INVALID_VALUE ,"Invalid value (did you forget quotes)?" ), \ -C (NO_FILTER ,"No filter found" ), +C (ERRNO ,"Error" ), \ + C(NO_FILTER, "No filter found")#undef C#define C (a, b) FILT_ERR_##a
@@ -76,7 +77,7 @@ enum { ERRORS };#undef C#define C (a, b) b -static char *err_text[] = {ERRORS }; +static const char *err_text[] = {ERRORS };/* Called after a '!' character but "!=" and "!~" are not "not"s */ static bool is_not (const char *str)
@@ -938,8 +939,10 @@ static void append_filter_err(struct filter_parse_error *pe,if (pe->lasterr >0 ) {trace_seq_printf (s,"\n%*s" , pos,"^" );trace_seq_printf (s,"\nparse_error: %s\n" , err_text[pe->lasterr]); +tracing_log_err ("event filter parse error" , filter->filter_string, err_text, pe->lasterr, pe->lasterr_pos); }else {trace_seq_printf (s,"\nError: (%d)\n" , pe->lasterr); +tracing_log_err ("event filter parse error" , filter->filter_string, err_text,FILT_ERR_ERRNO ,0 ); }trace_seq_putc (s,0 ); buf =kmemdup_nul (s->buffer, s->seq.len,GFP_KERNEL );
Signature · 1 line
2.14.1
Steven Rostedt
maintainerQuoted 7 lines · On Wed, 13 Feb 2019 12:17:51 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
For now, this is implemented on top of the latest 'hist trigger snapshot and onchange additions' patchset [4].
Which I'm making it a priority to go and review and apply (if there's no issues) right now ;-)
-- Steve
Masami Hiramatsu
maintainerHi Tom,
Thank you for your great work!
Quoted 77 lines · On Wed, 13 Feb 2019 12:17:51 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Last April, I posted an RFC patchset [1] implementing a common
error_loginterface as suggested by Masami [2]. We were supposed to discuss it at Plumbers but that never happened, and Steve recently asked about patches for a follow-on discussion [3], so here they are.I incorporated comments from the previous discussion, the most important of which are:
- Incorporated Steve's suggestion of using static strings as in the existing trace event filter code, along with
err_infoindexing into the string arrays and a position for the error caret.- Converted all the hist trigger errors and the existing trace event filter parse errors to use the new interface.
- Converted a few
kprobe_eventerrors to the new interface as examples, but these will require more work - I didn't spend much time figuring out how to get the full kprobe command into the error info, for instance.- Got rid of the custom single-page ring buffer and used standard lists instead.
For now, this is implemented on top of the latest 'hist trigger snapshot and onchange additions' patchset [4].
Below is an example session of a few failed commands and the corresponding
error_logcontents:# echo > /sys/kernel/debug/tracing/error_log# echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -su: echo: write error: Invalid argument# cat /sys/kernel/debug/tracing/error_log hist:sched:sched_wakeup: error: Variable already defined Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest" ^# echo 'hist:key=comm:p=prio:onchange($q).snapshot()' > /sys/kernel/debug/tracing/events/sched/sched_waking/trigger -su: echo: write error: Invalid argument# cat /sys/kernel/debug/tracing/error_log hist:sched:sched_wakeup: error: Variable already defined Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest" ^ hist:sched:sched_waking: error: Couldn't find onmax or onchange variable Command: key=comm:p=prio:onchange($q).snapshot() ^# echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger # echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger -su: echo: write error: File exists# echo 'comm="cyclictest"' > /sys/kernel/debug/tracing/events/sched/sched_wakeup/filter -su: echo: write error: Invalid argument# cat /sys/kernel/debug/tracing/error_log hist:sched:sched_wakeup: error: Variable already defined Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest" ^ hist:sched:sched_waking: error: Couldn't find onmax or onchange variable Command: key=comm:p=prio:onchange($q).snapshot() ^ hist:sched:sched_wakeup: error: Hist trigger already exists Command: keys=pid ^ event filter parse error: error: Invalid operator Command: comm="cyclictest" ^# echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > /sys/kernel/debug/tracing/events/signal/signal_generate/filter -su: echo: write error: Invalid argument
Quoted 16 lines
# cat /sys/kernel/debug/tracing/error_log
hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^
hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
Command: key=comm:p=prio:onchange($q).snapshot()
^
hist:sched:sched_wakeup: error: Hist trigger already exists
Command: keys=pid
^
event filter parse error: error: Invalid operator
Command: comm="cyclictest"
^
event filter parse error: error: Field not found
Command: ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
^ I like this very much! One point I would like to comment is to add a kind of entry number tag, so that user distinguish the error message, e.g.
# cat /sys/kernel/debug/tracing/error_log
[1] hist:sched:sched_wakeup: error: Variable already defined
Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
^
[2] hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
Command: key=comm:p=prio:onchange($q).snapshot()
^
[3] hist:sched:sched_wakeup: error: Hist trigger already exists
Command: keys=pid
^
...What would you think?
Thank you,
Signature · 1 line
Masami Hiramatsu <[email protected]>
Hi Masami,
Quoted 3 lines · Masami Hiramatsu
Hi Tom,
Thank you for your great work!
Thanks!
Quoted 14 lines
Quoted 10 lines · On Wed, 13 Feb 2019 12:17:51 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Last April, I posted an RFC patchset [1] implementing a common
error_loginterface as suggested by Masami [2]. We were supposed to
discuss it at Plumbers but that never happened, and Steve recently asked about patches for a follow-on discussion [3], so here they are.
[snip]
Quoted 38 lines
Quoted 11 lines
# cat /sys/kernel/debug/tracing/error_log hist:sched:sched_wakeup: error: Variable already defined Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest" ^ hist:sched:sched_waking: error: Couldn't find onmax or onchange variable Command: key=comm:p=prio:onchange($q).snapshot() ^ hist:sched:sched_wakeup: error: Hist trigger already exists Command: keys=pidQuoted 8 lines
^ event filter parse error: error: Invalid operator Command: comm="cyclictest" ^ event filter parse error: error: Field not found Command: ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash ^I like this very much! One point I would like to comment is to add a kind of
entry number tag, so that user distinguish the error message, e.g.# cat /sys/kernel/debug/tracing/error_log [1] hist:sched:sched_wakeup: error: Variable already defined Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest" ^ [2] hist:sched:sched_waking: error: Couldn't find onmax or onchange variable Command: key=comm:p=prio:onchange($q).snapshot() ^ [3] hist:sched:sched_wakeup: error: Hist trigger already exists Command: keys=pid ^ ...
Quoted 2 lines
What would you think?
I think that makes sense and would be simple to add - will do in the next version.
Thanks,
Tom
Quoted 2 lines
Thank you,