tracing: common error_log for ftrace

RFC PATCH Superseded Tom Zanussi 3 participants 15 messages Mar 4, 2019 – Mar 13, 2019 Tracing

lore

Share & tools

lore

Tom Zanussi

author

2019-03-04 23:36 UTC #0 lore raw

v3 cover tracing: common error_log for ftrace

From: Tom Zanussi <[email protected]>

Hi,

This is v3 of the frace error_log RFC patchset, which is the same as the previous version but adds the numbering Masami suggested before each item in the log. Masami also said he was going to take over the kprobe events patch, but I left it in for now for completeness as it still provides a useful example of possible usage, for evaluation of the overall scheme. I'll remove it when it's no longer an RFC.

Changes from v2:

- Added [n] numbering as suggested by Masami

Text from original post:

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
[1] 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
  [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()
                                       ^

  # 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
  [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
             ^
  [4] 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
  [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
             ^
  [4] event filter parse error: error: Invalid operator
    Command: comm="cyclictest"
                  ^
  [5] 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 9e5a36a3371f48fef0ebea6826d1d66f6201c522:

tracing: Fix spelling mistake: "analagous" -> "analogous" (2019-02-20 13:51:08 -0500)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/error_log_v3

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

Tom Zanussi

author

2019-03-04 23:37 UTC #1 lore raw

RFC PATCH v3 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:

[n] <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.

Signed-off-by Tom Zanussi <[email protected]>

Improvements-suggested-by Steve Rostedt <[email protected]>

---
 kernel/trace/trace.c | 217 +++++++++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h |   4 +
 2 files changed, 221 insertions(+)

kernel/trace/trace.c +217 -0

index 3835f7ed3293..8b677af1dd77 100644
@@ -6873,6 +6873,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, "[%llu] %s%s", m->index + 1, 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;

@@ -8256,6 +8470,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

index d80cee49e0eb..b711edbef7e7 100644
@@ -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

Tom Zanussi

author

2019-03-04 23:37 UTC #2 lore raw

RFC PATCH v3 2/5 tracing: Save the last hist command's associated event name

In reply to Tom Zanussi

From: 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.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 33 +++++++++++++++++++++++++++------
 1 file changed, 27 insertions(+), 6 deletions(-)

kernel/trace/trace_events_hist.c +27 -6

index 66386ba1425f..231f9e4379d2 100644
@@ -535,15 +535,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)

@@ -583,6 +602,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)

@@ -5438,8 +5459,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:

@@ -6043,8 +6064,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

Tom Zanussi

author

2019-03-04 23:37 UTC #3 lore raw

RFC PATCH v3 3/5 tracing: Use tracing error_log with hist triggers

In reply to Tom Zanussi

From: 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.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++-------------------
 1 file changed, 104 insertions(+), 102 deletions(-)

kernel/trace/trace_events_hist.c +104 ~~-102~~

index 231f9e4379d2..562306265c9d 100644
@@ -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,

@@ -538,7 +589,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)
 {

@@ -565,55 +619,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[];

@@ -1740,7 +1756,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;
 			}

@@ -1791,7 +1807,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);
 				}

@@ -2023,7 +2039,6 @@ static int parse_action(char *str, struct hist_trigger_attrs *attrs)
 		attrs->n_actions++;
 		ret = 0;
 	}
-
 	return ret;
 }

@@ -2083,7 +2098,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;
 		}

@@ -2681,8 +2696,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;
 }

@@ -2716,7 +2730,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;
 		}

@@ -2732,7 +2746,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;
 		}

@@ -2843,7 +2857,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;
 	}

@@ -2926,7 +2940,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;
 	}

@@ -2944,7 +2958,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);
 	}

@@ -3182,16 +3196,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);
 	}

@@ -3204,8 +3216,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);
 	}

@@ -3266,8 +3277,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);
 	}

@@ -3279,8 +3289,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);
 	}

@@ -3417,21 +3426,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;

@@ -3764,14 +3773,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;
 	}

@@ -3784,7 +3793,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;
 	}

@@ -3792,7 +3801,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;
 	}

@@ -3811,20 +3820,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(&params, ",");
 		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;
 		}

@@ -3856,14 +3865,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;
 	}

@@ -3872,7 +3881,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;
 		}

@@ -3886,7 +3895,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;
 		}

@@ -3898,7 +3907,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;
 		}

@@ -3908,7 +3917,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;
 		}

@@ -4061,7 +4070,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;
 }

@@ -4136,7 +4145,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;
 	}

@@ -4197,15 +4206,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;
 	}

@@ -4251,7 +4259,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;
 		}

@@ -4264,7 +4272,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;

@@ -4298,19 +4306,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;
 	}

@@ -4401,7 +4408,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;
 	}

@@ -4482,7 +4489,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;

@@ -4596,13 +4603,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;
 			}

@@ -5458,11 +5465,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);

@@ -5834,7 +5836,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;
 			}

@@ -5855,7 +5857,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;

@@ -5863,7 +5865,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;
 	}

@@ -5888,7 +5890,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

Masami Hiramatsu

maintainer

2019-03-12 15:46 UTC #4 lore raw

Re: [RFC PATCH v3 3/5] tracing: Use tracing error_log with hist triggers

Quoted 11 lines · On Mon, 4 Mar 2019 17:36:46 -0600 Tom Zanussi <[email protected]> wrote:

From: 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.

Could you also add a patch which update its testcase?

test.d/trigger/inter-event/trigger-extended-error-support.tc

will fail after this patch.

Thank you,

Quoted 576 lines

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++-------------------
 1 file changed, 104 insertions(+), 102 deletions(-)

kernel/trace/trace_events_hist.c +104 ~~-102~~

index 231f9e4379d2..562306265c9d 100644
@@ -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,

@@ -538,7 +589,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)
 {

@@ -565,55 +619,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[];

@@ -1740,7 +1756,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;
 			}

@@ -1791,7 +1807,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);
 				}

@@ -2023,7 +2039,6 @@ static int parse_action(char *str, struct hist_trigger_attrs *attrs)
 		attrs->n_actions++;
 		ret = 0;
 	}
-
 	return ret;
 }

@@ -2083,7 +2098,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;
 		}

@@ -2681,8 +2696,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;
 }

@@ -2716,7 +2730,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;
 		}

@@ -2732,7 +2746,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;
 		}

@@ -2843,7 +2857,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;
 	}

@@ -2926,7 +2940,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;
 	}

@@ -2944,7 +2958,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);
 	}

@@ -3182,16 +3196,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);
 	}

@@ -3204,8 +3216,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);
 	}

@@ -3266,8 +3277,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);
 	}

@@ -3279,8 +3289,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);
 	}

@@ -3417,21 +3426,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;

@@ -3764,14 +3773,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;
 	}

@@ -3784,7 +3793,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;
 	}

@@ -3792,7 +3801,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;
 	}

@@ -3811,20 +3820,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(&params, ",");
 		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;
 		}

@@ -3856,14 +3865,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;
 	}

@@ -3872,7 +3881,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;
 		}

@@ -3886,7 +3895,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;
 		}

@@ -3898,7 +3907,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;
 		}

@@ -3908,7 +3917,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;
 		}

@@ -4061,7 +4070,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;
 }

@@ -4136,7 +4145,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;
 	}

@@ -4197,15 +4206,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;
 	}

@@ -4251,7 +4259,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;
 		}

@@ -4264,7 +4272,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;

@@ -4298,19 +4306,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;
 	}

@@ -4401,7 +4408,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;
 	}

@@ -4482,7 +4489,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;

@@ -4596,13 +4603,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;
 			}

@@ -5458,11 +5465,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);

@@ -5834,7 +5836,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;
 			}

@@ -5855,7 +5857,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;

@@ -5863,7 +5865,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;
 	}

@@ -5888,7 +5890,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

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2019-03-12 16:50 UTC #5 lore raw

Re: [RFC PATCH v3 3/5] tracing: Use tracing error_log with hist triggers

Hi Masami,

Quoted 18 lines · Masami Hiramatsu

Quoted 9 lines · On Mon, 4 Mar 2019 17:36:46 -0600 Tom Zanussi <[email protected]> wrote:
From: 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.
Quoted 5 lines
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.

Quoted 6 lines

Could you also add a patch which update its testcase?
test.d/trigger/inter-event/trigger-extended-error-support.tc
will fail after this patch.

Yeah, good point, will do (and documentation too).

Thanks,

Tom

Tom Zanussi

author

2019-03-04 23:37 UTC #6 lore raw

RFC PATCH v3 4/5 tracing: Use tracing error_log with kprobe events (incomplete)

In reply to Tom Zanussi

From: 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.

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

index 89da34b326e3..5da08c1972af 100644
@@ -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",

@@ -385,7 +401,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);

@@ -444,7 +460,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;
 		}

@@ -559,8 +576,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

Tom Zanussi

author

2019-03-04 23:37 UTC #7 lore raw

RFC PATCH v3 5/5 tracing: Use tracing error_log with trace event filters

In reply to Tom Zanussi

From: 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.

Signed-off-by Tom Zanussi <[email protected]>

---
 kernel/trace/trace_events_filter.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

kernel/trace/trace_events_filter.c +5 -2

index ade606c33231..3a1ed8631aa0 100644
@@ -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)

@@ -947,8 +948,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

Masami Hiramatsu

maintainer

2019-03-05 14:06 UTC #8 lore raw

In reply to Tom Zanussi

Quoted 10 lines · On Mon, 4 Mar 2019 17:36:43 -0600 Tom Zanussi <[email protected]> wrote:

From: Tom Zanussi <[email protected]>
Hi,
This is v3 of the frace error_log RFC patchset, which is the same as the previous version but adds the numbering Masami suggested before each item in the log. Masami also said he was going to take over the kprobe events patch, but I left it in for now for completeness as it still provides a useful example of possible usage, for evaluation of the overall scheme. I'll remove it when it's no longer an RFC.

Ahh, sorry, I'm forcusing on fixing user-space access issue. I'll take a look.

Quoted 4 lines

Changes from v2:
- Added [n] numbering as suggested by Masami

That's very good too me, thank you!

Thank you,

Quoted 131 lines

Text from original post:
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
[1] 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
  [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()
                                       ^
  # 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
  [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
             ^
  [4] 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
  [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
             ^
  [4] event filter parse error: error: Invalid operator
    Command: comm="cyclictest"
                  ^
  [5] 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 9e5a36a3371f48fef0ebea6826d1d66f6201c522:
tracing: Fix spelling mistake: "analagous" -> "analogous" (2019-02-20 13:51:08 -0500)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/error_log_v3
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

Signature · 1 line

Masami Hiramatsu <[email protected]>

Masami Hiramatsu

maintainer

2019-03-12 06:26 UTC #9 lore raw

Hi Tom,

Quoted 6 lines · On Tue, 5 Mar 2019 23:06:46 +0900 Masami Hiramatsu <[email protected]> wrote:

On Mon, 4 Mar 2019 17:36:43 -0600
Quoted 3 lines
Changes from v2:
- Added [n] numbering as suggested by Masami

Hmm, this seems a bit different what I suggested.

I'm trying to port probe event's error report on
your error log, and I found that the number is
just shifted as below.

When I filled the log with errors.
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Invalid unsigned integer string
Command: r10aa00:foo/bar vfs

...

[7] trace_kprobe: error: Group name must follow C naming convention
Command: p:a-b/bar vfs_read

[8] trace_kprobe: error: Event name is too long
Command: p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr vfs_read
=============

And do one more error,

=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs

....

[7] trace_kprobe: error: Event name is too long
Command: p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr vfs_read

               ^
[8] trace_kprobe: error: Event name must follow C naming convention
  Command: p:a/bar.c vfs_read
               ^

=============

The number of logs are changed :( This can confuse users. I think it is better to keep the number as a unique number for each entry as below.

=============
/sys/kernel/debug/tracing # cat error_log
[2] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs

....

[8] trace_kprobe: error: Event name is too long
Command: p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr vfs_read

               ^
[9] trace_kprobe: error: Event name must follow C naming convention
  Command: p:a/bar.c vfs_read
               ^

=============

Thank you,

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2019-03-12 16:49 UTC #10 lore raw

Hi Masami,

Quoted 50 lines · Masami Hiramatsu

Hi Tom,
Quoted 4 lines · On Tue, 5 Mar 2019 23:06:46 +0900 Masami Hiramatsu <[email protected]> wrote:
On Mon, 4 Mar 2019 17:36:43 -0600
Quoted 3 lines
Changes from v2:
- Added [n] numbering as suggested by Masami
Hmm, this seems a bit different what I suggested.
I'm trying to port probe event's error report on
your error log, and I found that the number is
just shifted as below.
When I filled the log with errors.
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Invalid unsigned integer string
Command: r10aa00:foo/bar vfs
            ^
...
[7] trace_kprobe: error: Group name must follow C naming convention
Command: p:a-b/bar vfs_read
             ^
[8] trace_kprobe: error: Event name is too long
Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrrrrrrrrr vfs_read
=============
And do one more error,
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs
....
[7] trace_kprobe: error: Event name is too long
Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrrrrrrrrr vfs_read
               ^
[8] trace_kprobe: error: Event name must follow C naming convention
  Command: p:a/bar.c vfs_read
               ^

Quoted 6 lines

=============
The number of logs are changed :( This can confuse users. I think it is better to keep the number as a unique number for each entry as below.

Hmm, that makes sense, but I wonder if that will also confuse users, when the log wraps around and no longer starts at [1] and there's no way to retrieve the previous errors.

I took your suggestion as a way mainly to clearly delineate each error, since without the [number] or something similar, they all kind of run together.

Not sure what advantage numbering itself provides - would some other non-numbered separator work?

Thanks,

Tom

Quoted 19 lines

=============
/sys/kernel/debug/tracing # cat error_log
[2] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs
....
[8] trace_kprobe: error: Event name is too long
Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrrrrrrrrr vfs_read
               ^
[9] trace_kprobe: error: Event name must follow C naming convention
  Command: p:a/bar.c vfs_read
               ^
=============
Thank you,

Masami Hiramatsu

maintainer

2019-03-13 13:03 UTC #11 lore raw

Quoted 55 lines · On Tue, 12 Mar 2019 11:49:11 -0500 Tom Zanussi <[email protected]> wrote:

Hi Masami,
Quoted 52 lines · Masami Hiramatsu
Hi Tom,
Quoted 4 lines · On Tue, 5 Mar 2019 23:06:46 +0900 Masami Hiramatsu <[email protected]> wrote:
On Mon, 4 Mar 2019 17:36:43 -0600
Quoted 3 lines
Changes from v2:
- Added [n] numbering as suggested by Masami
Hmm, this seems a bit different what I suggested.
I'm trying to port probe event's error report on
your error log, and I found that the number is
just shifted as below.
When I filled the log with errors.
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Invalid unsigned integer string
Command: r10aa00:foo/bar vfs
            ^
...
[7] trace_kprobe: error: Group name must follow C naming convention
Command: p:a-b/bar vfs_read
             ^
[8] trace_kprobe: error: Event name is too long
Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrrrrrrrrr vfs_read
=============
And do one more error,
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs
....
[7] trace_kprobe: error: Event name is too long
Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrrrrrrrrr vfs_read
               ^
[8] trace_kprobe: error: Event name must follow C naming convention
  Command: p:a/bar.c vfs_read
               ^
=============

Quoted 8 lines

Quoted 4 lines
The number of logs are changed :( This can confuse users. I think it is better to keep the number as a unique number for each entry as below.
Hmm, that makes sense, but I wonder if that will also confuse users, when the log wraps around and no longer starts at [1] and there's no way to retrieve the previous errors.

It is OK, that is same as dmesg. If user needs to keep watching it, it should be dumped to disk by a daemon.

Quoted 7 lines

I took your suggestion as a way mainly to clearly delineate each error, since without the [number] or something similar, they all kind of run together.
Not sure what advantage numbering itself provides - would some other non-numbered separator work?

What about timestamp, similar to dmesg?

Thank you,

Signature · 1 line

Masami Hiramatsu <[email protected]>

Tom Zanussi

author

2019-03-13 14:09 UTC #12 lore raw

Hi Masami,

Quoted 83 lines · Masami Hiramatsu

Quoted 64 lines · On Tue, 12 Mar 2019 11:49:11 -0500 Tom Zanussi <[email protected]> wrote:
Hi Masami,
Quoted 54 lines · Masami Hiramatsu
Hi Tom,
Quoted 4 lines · On Tue, 5 Mar 2019 23:06:46 +0900 Masami Hiramatsu <[email protected]> wrote:
On Mon, 4 Mar 2019 17:36:43 -0600
Quoted 3 lines
Changes from v2:
- Added [n] numbering as suggested by Masami
Hmm, this seems a bit different what I suggested.
I'm trying to port probe event's error report on
your error log, and I found that the number is
just shifted as below.
When I filled the log with errors.
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Invalid unsigned integer string
Command: r10aa00:foo/bar vfs
            ^
...
[7] trace_kprobe: error: Group name must follow C naming convention
Command: p:a-b/bar vfs_read
             ^
[8] trace_kprobe: error: Event name is too long Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrr
rrrrrrrrrrr vfs_read
=============
And do one more error,
=============
/sys/kernel/debug/tracing # cat error_log
[1] trace_kprobe: error: Maxactive is too big
Command: r0xaa00:foo/bar vfs
....
[7] trace_kprobe: error: Event name is too long Command:
p:a/barrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrrr rrrr
rrrrrrrrrrr vfs_read
               ^
[8] trace_kprobe: error: Event name must follow C naming
convention
  Command: p:a/bar.c vfs_read
               ^
Quoted 6 lines
=============
The number of logs are changed :( This can confuse users. I think it is better to keep the number as a unique number for each entry as below.
Quoted 5 lines
Hmm, that makes sense, but I wonder if that will also confuse users,
when the log wraps around and no longer starts at [1] and there's no
way to retrieve the previous errors.
It is OK, that is same as dmesg. If user needs to keep watching it, it should be dumped to disk by a daemon.
Quoted 7 lines
I took your suggestion as a way mainly to clearly delineate each error,
since without the [number] or something similar, they all kind of run
together.

Quoted 6 lines

Quoted 3 lines
Not sure what advantage numbering itself provides - would some other
non-numbered separator work?
What about timestamp, similar to dmesg?

Yeah, I think that makes more sense - unlike the counter, there's no sense that you may be missing some prior messages.

Thanks,

Tom

Quoted 4 lines

Thank you,

Steven Rostedt

maintainer

2019-03-05 21:58 UTC #13 lore raw

In reply to Tom Zanussi

Quoted 11 lines · On Mon, 4 Mar 2019 17:36:43 -0600 Tom Zanussi <[email protected]> wrote:

From: Tom Zanussi <[email protected]>
Hi,
This is v3 of the frace error_log RFC patchset, which is the same as the previous version but adds the numbering Masami suggested before each item in the log. Masami also said he was going to take over the kprobe events patch, but I left it in for now for completeness as it still provides a useful example of possible usage, for evaluation of the overall scheme. I'll remove it when it's no longer an RFC.

Quoted 5 lines

Changes from v2:
- Added [n] numbering as suggested by Masami

Hi Tom,

Thanks for doing this!

Note, I'm marking this as TODO, as the merge window has opened and this will have to wait till it closes. But that means it may get buried by other patches and such marked as TODO. :-p

Can you send me a friendly reminder in two weeks if you don't hear from me?

Thanks!

-- Steve

Tom Zanussi

author

2019-03-05 22:05 UTC #14 lore raw

Hi Steve,

Quoted 28 lines · Steven Rostedt

Quoted 15 lines · On Mon, 4 Mar 2019 17:36:43 -0600 Tom Zanussi <[email protected]> wrote:
From: Tom Zanussi <[email protected]>
Hi,
This is v3 of the frace error_log RFC patchset, which is the same as
the previous version but adds the numbering Masami suggested before each item in the log. Masami also said he was going to take over the
kprobe events patch, but I left it in for now for completeness as it
still provides a useful example of possible usage, for evaluation of
the overall scheme. I'll remove it when it's no longer an RFC.
Quoted 5 lines
Changes from v2:
- Added [n] numbering as suggested by Masami
Hi Tom,
Thanks for doing this!

Quoted 9 lines

Note, I'm marking this as TODO, as the merge window has opened and this
will have to wait till it closes. But that means it may get buried by other patches and such marked as TODO. :-p
Can you send me a friendly reminder in two weeks if you don't hear from
me?

Sure, will do.

Thanks,

Tom

Quoted 3 lines

Thanks!
-- Steve