[RFC PATCH v3 0/5] tracing: common error_log for ftrace

[RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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/cover.1523545519.git.tom.zanussi@linux.intel.com/
[2] https://lore.kernel.org/lkml/20180406105309.b50ea1a21d2cbd9b0e39dbfd@kernel.org/
[3] https://lore.kernel.org/lkml/e885d1fd02e76f121d6cc2bb28e58b523e2434a7.camel@linux.intel.com/
[4] https://lore.kernel.org/lkml/cover.1549403369.git.tom.zanussi@linux.intel.com/


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(-)

-- 
2.14.1

[RFC PATCH v3 1/5] tracing: Add tracing error log

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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 <tom.zanussi@linux.intel.com>
Suggested-by: Masami Hiramatsu <mhiramat@kernel.org>
Improvements-suggested-by: Steve Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace.c | 217 +++++++++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace.h |   4 +
 2 files changed, 221 insertions(+)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 3835f7ed3293..8b677af1dd77 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -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);
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index d80cee49e0eb..b711edbef7e7 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -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
-- 
2.14.1

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

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 33 +++++++++++++++++++++++++++------
 1 file changed, 27 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 66386ba1425f..231f9e4379d2 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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)
-- 
2.14.1

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

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++-------------------
 1 file changed, 104 insertions(+), 102 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 231f9e4379d2..562306265c9d 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -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;
 		}
 
-- 
2.14.1

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

[Masami Hiramatsu]

On Mon,  4 Mar 2019 17:36:46 -0600
Tom Zanussi <zanussi@kernel.org> wrote:

> From: Tom Zanussi <tom.zanussi@linux.intel.com>
> 
> 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,

> 
> Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
> ---
>  kernel/trace/trace_events_hist.c | 206 ++++++++++++++++++++-------------------
>  1 file changed, 104 insertions(+), 102 deletions(-)
> 
> diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
> index 231f9e4379d2..562306265c9d 100644
> --- a/kernel/trace/trace_events_hist.c
> +++ b/kernel/trace/trace_events_hist.c
> @@ -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;
>  		}
>  
> -- 
> 2.14.1
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

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

[Tom Zanussi]

Hi Masami,

On Wed, 2019-03-13 at 00:46 +0900, Masami Hiramatsu wrote:
> On Mon,  4 Mar 2019 17:36:46 -0600
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > From: Tom Zanussi <tom.zanussi@linux.intel.com>
> > 
> > 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.
> 

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

Thanks,

Tom

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

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_probe.c | 24 ++++++++++++++++++++----
 1 file changed, 20 insertions(+), 4 deletions(-)

diff --git a/kernel/trace/trace_probe.c b/kernel/trace/trace_probe.c
index 89da34b326e3..5da08c1972af 100644
--- a/kernel/trace/trace_probe.c
+++ b/kernel/trace/trace_probe.c
@@ -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;
 	}
 
-- 
2.14.1

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

[Tom Zanussi]

From: Tom Zanussi <tom.zanussi@linux.intel.com>

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 <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_filter.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_filter.c b/kernel/trace/trace_events_filter.c
index ade606c33231..3a1ed8631aa0 100644
--- a/kernel/trace/trace_events_filter.c
+++ b/kernel/trace/trace_events_filter.c
@@ -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);
-- 
2.14.1

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Masami Hiramatsu]

On Mon,  4 Mar 2019 17:36:43 -0600
Tom Zanussi <zanussi@kernel.org> wrote:

> From: Tom Zanussi <tom.zanussi@linux.intel.com>
> 
> 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.

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

That's very good too me, thank you!


Thank you,


> 
> 
> 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/cover.1523545519.git.tom.zanussi@linux.intel.com/
> [2] https://lore.kernel.org/lkml/20180406105309.b50ea1a21d2cbd9b0e39dbfd@kernel.org/
> [3] https://lore.kernel.org/lkml/e885d1fd02e76f121d6cc2bb28e58b523e2434a7.camel@linux.intel.com/
> [4] https://lore.kernel.org/lkml/cover.1549403369.git.tom.zanussi@linux.intel.com/
> 
> 
> 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(-)
> 
> -- 
> 2.14.1
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Masami Hiramatsu]

Hi Tom,

On Tue, 5 Mar 2019 23:06:46 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Mon,  4 Mar 2019 17:36:43 -0600

> > 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,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Tom Zanussi]

Hi Masami,

On Tue, 2019-03-12 at 15:26 +0900, Masami Hiramatsu wrote:
> Hi Tom,
> 
> On Tue, 5 Mar 2019 23:06:46 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > On Mon,  4 Mar 2019 17:36:43 -0600
> > > 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
>                ^
> =============
> 
> 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

> =============
> /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,
> 

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Masami Hiramatsu]

On Tue, 12 Mar 2019 11:49:11 -0500
Tom Zanussi <zanussi@kernel.org> wrote:

> Hi Masami,
> 
> On Tue, 2019-03-12 at 15:26 +0900, Masami Hiramatsu wrote:
> > Hi Tom,
> > 
> > On Tue, 5 Mar 2019 23:06:46 +0900
> > Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > 
> > > On Mon,  4 Mar 2019 17:36:43 -0600
> > > > 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
> >                ^
> > =============
> > 
> > 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.

> 
> 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,



-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Tom Zanussi]

Hi Masami,

On Wed, 2019-03-13 at 22:03 +0900, Masami Hiramatsu wrote:
> On Tue, 12 Mar 2019 11:49:11 -0500
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > Hi Masami,
> > 
> > On Tue, 2019-03-12 at 15:26 +0900, Masami Hiramatsu wrote:
> > > Hi Tom,
> > > 
> > > On Tue, 5 Mar 2019 23:06:46 +0900
> > > Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > > 
> > > > On Mon,  4 Mar 2019 17:36:43 -0600
> > > > > 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
> > >                ^
> > > =============
> > > 
> > > 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.
> 
> > 
> > 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?
> 

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

Thanks,

Tom 

> Thank you,
> 
> 
> 

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Steven Rostedt]

On Mon,  4 Mar 2019 17:36:43 -0600
Tom Zanussi <zanussi@kernel.org> wrote:

> From: Tom Zanussi <tom.zanussi@linux.intel.com>
> 
> 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
> 
>

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

Re: [RFC PATCH v3 0/5] tracing: common error_log for ftrace

[Tom Zanussi]

Hi Steve,

On Tue, 2019-03-05 at 16:58 -0500, Steven Rostedt wrote:
> On Mon,  4 Mar 2019 17:36:43 -0600
> Tom Zanussi <zanussi@kernel.org> wrote:
> 
> > From: Tom Zanussi <tom.zanussi@linux.intel.com>
> > 
> > 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
> > 
> > 
> 
> 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?
> 

Sure, will do.

Thanks,

Tom

> Thanks!
> 
> -- Steve