[PATCH 0/6] tracing: trace event error_log and inter-event bugfixes

[PATCH 0/6] tracing: trace event error_log and inter-event bugfixes

[Tom Zanussi]

Hi Steve,

Here are a few patches that should be applied on top of the
'Inter-event (e.g. latency) support v9' patchset.

The first fixes another problem I noticed when printing flags.

The rest implement the tracing/events/error_log suggested by Masami,
and update the inter-event code to use it (and remove the old hist
file error mechanism).

Thanks,

Tom

The following changes since commit 404bb11b24fb9a592023c077b878d30ad6da4322:

  tracing: Enforce passing in filter=NULL to create_filter() (2018-04-11 11:18:42 -0400)

are available in the git repository at:

  https://github.com/tzanussi/linux-trace-inter-event.git tzanussi/inter-event-update2
  https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-update2

Tom Zanussi (6):
  tracing: Restore proper field flag printing when displaying triggers
  tracing: Add trace event error log
  tracing: Save the last hist command's associated event name
  tracing: Use trace event error_log with hist triggers
  tracing: Add field parsing trace event errors for hist triggers
  selftests: ftrace: Fix extended error support testcase

 kernel/trace/trace.h                               |   3 +
 kernel/trace/trace_events.c                        | 172 +++++++++++++++++++
 kernel/trace/trace_events_hist.c                   | 188 +++++++++++----------
 .../inter-event/trigger-extended-error-support.tc  |   2 +-
 4 files changed, 274 insertions(+), 91 deletions(-)

-- 
1.9.3

[PATCH 1/6] tracing: Restore proper field flag printing when displaying triggers

[Tom Zanussi]

The flag-printing code used when displaying hist triggers somehow got
dropped during refactoring of the inter-event patchset.  This restores
it.

Below are a couple examples - in the first case, .usecs wasn't being
displayed properly for common_timestamps and the second illustrates
the same for other flags such as .execname.

Before:

  # echo 'hist:key=common_pid.execname:val=count:sort=count' > /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
  # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
  hist:keys=common_pid:vals=hitcount,count:sort=count:size=2048 [active]

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  hist:keys=pid:vals=hitcount:ts0=common_timestamp:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

After:

  # echo 'hist:key=common_pid.execname:val=count:sort=count' > /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
  # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
  hist:keys=common_pid.execname:vals=hitcount,count:sort=count:size=2048 [active]

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  hist:keys=pid:vals=hitcount:ts0=common_timestamp.usecs:sort=hitcount:size=2048:clock=global if comm=="cyclictest" [active]

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 0d7b3ff..66c87be 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -4913,6 +4913,16 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field)
 		seq_printf(m, "%s", field_name);
 	} else if (hist_field->flags & HIST_FIELD_FL_TIMESTAMP)
 		seq_puts(m, "common_timestamp");
+
+	if (hist_field->flags) {
+		if (!(hist_field->flags & HIST_FIELD_FL_VAR_REF) &&
+		    !(hist_field->flags & HIST_FIELD_FL_EXPR)) {
+			const char *flags = get_hist_field_flags(hist_field);
+
+			if (flags)
+				seq_printf(m, ".%s", flags);
+		}
+	}
 }
 
 static int event_hist_trigger_print(struct seq_file *m,
-- 
1.9.3

[PATCH 2/6] tracing: Add trace event error log

[Tom Zanussi]

Introduce a new trace event file, tracing/events/error_log, for trace
event commands to log non-critical 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 trace event error, call the event_log_err() function with the
event_mutex held, passing it a location string describing where it
came from e.g. kprobe_events or system:event, the command that caused
the error, and a format string and variable-length number of
corresponding snprintf args.

Reading the log displays the last (currently) 8 errors logged in the
following format:

  ERROR(<loc>): <error text ala snprintf>
    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 > error_log.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Suggested-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/trace/trace.h        |   3 +
 kernel/trace/trace_events.c | 172 ++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 175 insertions(+)

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6fb46a0..f2dc7e6 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
+			  ...);
+
 /*
  * Normal trace_printk() and friends allocates special buffers
  * to do the manipulation, as well as saves the print formats
diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
index 05c7172..fd02e22 100644
--- a/kernel/trace/trace_events.c
+++ b/kernel/trace/trace_events.c
@@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
 	return ret;
 }
 
+#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))
+#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)
+
+struct event_log_err {
+	char			err[MAX_FILTER_STR_VAL];
+	char			cmd[MAX_FILTER_STR_VAL];
+};
+
+static char *event_err_log;
+static unsigned int event_err_log_tail;
+
+struct event_log_err *get_event_log_err(void)
+{
+	struct event_log_err *err;
+	char *errpos;
+
+	if (!event_err_log) {
+		event_err_log = (char *)get_zeroed_page(GFP_KERNEL);
+		if (!event_err_log)
+			return NULL;
+	}
+
+	errpos = event_err_log + event_err_log_tail * sizeof(*err);
+	err = (struct event_log_err *)errpos;
+
+	event_err_log_tail = (event_err_log_tail + 1) & EVENT_ERR_LOG_MASK;
+
+	return err;
+}
+
+/**
+ * event_log_err - write an error to the trace event error log
+ * @loc: A string describing where the error occurred
+ * @cmd: The trace event command that caused the error
+ * @fmt: snprintf format string
+ * @...: variable length list of snprintf args
+ *
+ * Writes an error into tracing/events/error_log of the form:
+ *
+ * ERROR(<loc>): <error text ala snprintf>
+ *   Command: <command that caused the error>
+ *
+ * tracing/events/error_log is a small log file containing the last
+ * EVENT_LOG_ERRS_MAX errors (8).  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 i.e. echo > error_log.
+ *
+ * Must be called with event_mutex held.
+ */
+void event_log_err(const char *loc, const char *cmd, const char *fmt, ...)
+{
+	struct event_log_err *err;
+	va_list args;
+	int len;
+
+	err = get_event_log_err();
+	if (!err)
+		return;
+
+	snprintf(err->cmd, MAX_FILTER_STR_VAL,"\n  Command: %s\n", cmd);
+
+	len = snprintf(err->err, MAX_FILTER_STR_VAL, "ERROR(%s): ", loc);
+	if (len >= MAX_FILTER_STR_VAL)
+		return;
+
+	va_start(args, fmt);
+	vsnprintf(err->err + len, MAX_FILTER_STR_VAL - len, fmt, args);
+	va_end(args);
+}
+
+static void clear_event_err_log(void)
+{
+	free_page((long unsigned int)event_err_log);
+	event_err_log_tail = 0;
+	event_err_log = NULL;
+}
+
+static void *event_err_log_inc(loff_t *pos)
+{
+	struct event_log_err *err = NULL;
+	char *errpos = NULL;
+	int i = *pos;
+
+	++*pos;
+
+	if (i >= EVENT_LOG_ERRS_MAX)
+		return NULL;
+
+	i += event_err_log_tail;
+	i &= EVENT_ERR_LOG_MASK;
+
+	errpos = event_err_log + (i * sizeof(*err));
+	err = (struct event_log_err *)errpos;
+
+	return err;
+}
+
+static void *event_err_log_seq_start(struct seq_file *m, loff_t *pos)
+{
+	mutex_lock(&event_mutex);
+
+	return event_err_log_inc(pos);
+}
+
+static void *event_err_log_seq_next(struct seq_file *m, void *v, loff_t *pos)
+{
+	return event_err_log_inc(pos);
+}
+
+static void event_err_log_seq_stop(struct seq_file *m, void *v)
+{
+	mutex_unlock(&event_mutex);
+}
+
+static int event_err_log_seq_show(struct seq_file *m, void *v)
+{
+	struct event_log_err *err = v;
+
+	if (err)
+		seq_printf(m, "%s%s", err->err, err->cmd);
+
+	return 0;
+}
+
+static const struct seq_operations event_err_log_seq_op = {
+	.start  = event_err_log_seq_start,
+	.next   = event_err_log_seq_next,
+	.stop   = event_err_log_seq_stop,
+	.show   = event_err_log_seq_show
+};
+
+static int event_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, &event_err_log_seq_op);
+}
+
+static ssize_t event_err_log_write(struct file *file,
+				   const char __user *buffer,
+				   size_t count, loff_t *ppos)
+{
+	if (count == 1)
+		clear_event_err_log();
+	else
+		return -EINVAL;
+
+	*ppos += count;
+
+	return count;
+}
+
 static int ftrace_event_avail_open(struct inode *inode, struct file *file);
 static int ftrace_event_set_open(struct inode *inode, struct file *file);
 static int ftrace_event_set_pid_open(struct inode *inode, struct file *file);
@@ -1767,6 +1925,13 @@ static void ignore_task_cpu(void *data)
 	.release = subsystem_release,
 };
 
+static const struct file_operations ftrace_event_err_log_fops = {
+	.open           = event_err_log_open,
+	.write		= event_err_log_write,
+	.read           = seq_read,
+	.llseek         = seq_lseek,
+};
+
 static const struct file_operations ftrace_show_header_fops = {
 	.open = tracing_open_generic,
 	.read = show_header,
@@ -2927,6 +3092,13 @@ static __init int setup_trace_event(char *str)
 		return -ENOMEM;
 	}
 
+	entry = trace_create_file("error_log", 0644, d_events,
+				  tr, &ftrace_event_err_log_fops);
+	if (!entry) {
+		pr_warn("Could not create tracefs 'error_log' entry\n");
+		return -ENOMEM;
+	}
+
 	/* There are not as crucial, just warn if they are not created */
 
 	entry = tracefs_create_file("set_event_pid", 0644, parent,
-- 
1.9.3

[PATCH 3/6] tracing: Save the last hist command's associated event name

[Tom Zanussi]

In preparation for making use of the new trace event 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 | 24 ++++++++++++++++++++++--
 1 file changed, 22 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 66c87be..4a42df4 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -354,14 +354,32 @@ struct action_data {
 
 
 static char last_hist_cmd[MAX_FILTER_STR_VAL];
+static char last_hist_cmd_event[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);
+
+	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_hist_cmd_event, MAX_FILTER_STR_VAL, "%s:%s", system, name);
 }
 
 static void hist_err(char *str, char *var)
@@ -401,6 +419,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_hist_cmd[0] = '\0';
+	last_hist_cmd_event[0] = '\0';
 }
 
 static bool have_hist_err(void)
@@ -5478,8 +5498,8 @@ static int event_hist_trigger_func(struct event_command *cmd_ops,
 	int ret = 0;
 
 	if (glob && strlen(glob)) {
-		last_cmd_set(param);
 		hist_err_clear();
+		last_cmd_set(file, param);
 	}
 
 	if (!param)
-- 
1.9.3

[PATCH 4/6] tracing: Use trace event error_log with hist triggers

[Tom Zanussi]

Replace hist_err() and hist_err_event() with event_log_err() from the
new trace event 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 the tracing/events/error_log
for the same information.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 kernel/trace/trace_events_hist.c | 161 ++++++++++++++++-----------------------
 1 file changed, 66 insertions(+), 95 deletions(-)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 4a42df4..08424ff 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -355,7 +355,26 @@ struct action_data {
 
 static char last_hist_cmd[MAX_FILTER_STR_VAL];
 static char last_hist_cmd_event[MAX_FILTER_STR_VAL];
-static char hist_err_str[MAX_FILTER_STR_VAL];
+
+#define log_err(fmt, ...)			\
+	event_log_err(last_hist_cmd_event, last_hist_cmd, fmt, ##__VA_ARGS__)
+
+static char *fqvar(char *system, char *event_name, char *var_name, bool ref)
+{
+	static char fqvar[MAX_FILTER_STR_VAL];
+	char *fmt = ref ? "%s.%s.$%s" : "%s.%s.%s";
+
+	if (system && event_name && var_name) {
+		fmt = ref ? "%s.%s.$%s" : "%s.%s.%s";
+		snprintf(fqvar, MAX_FILTER_STR_VAL, fmt, system, event_name);
+	} else if (var_name) {
+		fmt = ref ? "$%s" : "%s";
+		snprintf(fqvar, MAX_FILTER_STR_VAL, fmt, var_name);
+	} else
+		return NULL;
+
+	return fqvar;
+}
 
 static void last_cmd_set(struct trace_event_file *file, char *str)
 {
@@ -382,55 +401,12 @@ static void last_cmd_set(struct trace_event_file *file, char *str)
 		snprintf(last_hist_cmd_event, MAX_FILTER_STR_VAL, "%s:%s", system, name);
 }
 
-static void hist_err(char *str, char *var)
-{
-	int maxlen = MAX_FILTER_STR_VAL - 1;
-
-	if (!str)
-		return;
-
-	if (strlen(hist_err_str))
-		return;
-
-	if (!var)
-		var = "";
-
-	if (strlen(hist_err_str) + strlen(str) + strlen(var) > maxlen)
-		return;
-
-	strcat(hist_err_str, str);
-	strcat(hist_err_str, var);
-}
-
-static void hist_err_event(char *str, char *system, char *event, char *var)
-{
-	char err[MAX_FILTER_STR_VAL];
-
-	if (system && var)
-		snprintf(err, MAX_FILTER_STR_VAL, "%s.%s.%s", system, event, var);
-	else if (system)
-		snprintf(err, MAX_FILTER_STR_VAL, "%s.%s", system, event);
-	else
-		strncpy(err, var, MAX_FILTER_STR_VAL);
-
-	hist_err(str, err);
-}
-
 static void hist_err_clear(void)
 {
-	hist_err_str[0] = '\0';
 	last_hist_cmd[0] = '\0';
 	last_hist_cmd_event[0] = '\0';
 }
 
-static bool have_hist_err(void)
-{
-	if (strlen(hist_err_str))
-		return true;
-
-	return false;
-}
-
 static LIST_HEAD(synth_event_list);
 static DEFINE_MUTEX(synth_event_mutex);
 
@@ -1539,7 +1515,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);
+				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
 				return NULL;
 			}
 
@@ -1590,7 +1566,7 @@ static struct hist_field *find_file_var(struct trace_event_file *file,
 			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);
+					log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
 					return ERR_PTR(-EINVAL);
 				}
 
@@ -1887,7 +1863,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);
+			log_err("Too many variables defined: %s", str);
 			ret = -EINVAL;
 			goto out;
 		}
@@ -2451,8 +2427,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
 		ref_field = create_var_ref(var_field, system, event_name);
 
 	if (!ref_field)
-		hist_err_event("Couldn't find variable: $",
-			       system, event_name, var_name);
+		log_err("Couldn't find variable: %s", fqvar(system, event_name, var_name, true));
 
 	return ref_field;
 }
@@ -2613,7 +2588,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);
+		log_err("Too many subexpressions (3 max): %s", str);
 		ret = -EINVAL;
 		goto free;
 	}
@@ -2696,7 +2671,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);
+		log_err("Timestamp units in expression don't match");
 		return -EINVAL;
 	}
 
@@ -2714,7 +2689,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);
+		log_err("Too many subexpressions (3 max): %s", str);
 		return ERR_PTR(-EINVAL);
 	}
 
@@ -2952,16 +2927,16 @@ static struct trace_event_file *event_file(struct trace_array *tr,
 	int ret;
 
 	if (target_hist_data->n_field_var_hists >= SYNTH_FIELDS_MAX) {
-		hist_err_event("onmatch: Too many field variables defined: ",
-			       subsys_name, event_name, field_name);
+		log_err("onmatch: Too many field variables defined: %s",
+			fqvar(subsys_name, event_name, field_name, false));
 		return ERR_PTR(-EINVAL);
 	}
 
 	file = event_file(tr, subsys_name, event_name);
 
 	if (IS_ERR(file)) {
-		hist_err_event("onmatch: Event file not found: ",
-			       subsys_name, event_name, field_name);
+		log_err("onmatch: Event file not found: %s",
+			fqvar(subsys_name, event_name, field_name, false));
 		ret = PTR_ERR(file);
 		return ERR_PTR(ret);
 	}
@@ -2974,8 +2949,8 @@ static struct trace_event_file *event_file(struct trace_array *tr,
 	 */
 	hist_data = find_compatible_hist(target_hist_data, file);
 	if (!hist_data) {
-		hist_err_event("onmatch: Matching event histogram not found: ",
-			       subsys_name, event_name, field_name);
+		log_err("onmatch: Matching event histogram not found: %s",
+			fqvar(subsys_name, event_name, field_name, false));
 		return ERR_PTR(-EINVAL);
 	}
 
@@ -3036,8 +3011,8 @@ static struct trace_event_file *event_file(struct trace_array *tr,
 		kfree(cmd);
 		kfree(var_hist->cmd);
 		kfree(var_hist);
-		hist_err_event("onmatch: Couldn't create histogram for field: ",
-			       subsys_name, event_name, field_name);
+		log_err("onmatch: Couldn't create histogram for field: %s",
+			fqvar(subsys_name, event_name, field_name, false));
 		return ERR_PTR(ret);
 	}
 
@@ -3049,8 +3024,8 @@ static struct trace_event_file *event_file(struct trace_array *tr,
 	if (IS_ERR_OR_NULL(event_var)) {
 		kfree(var_hist->cmd);
 		kfree(var_hist);
-		hist_err_event("onmatch: Couldn't find synthetic variable: ",
-			       subsys_name, event_name, field_name);
+		log_err("onmatch: Couldn't find synthetic variable: %s",
+			fqvar(subsys_name, event_name, field_name, false));
 		return ERR_PTR(-EINVAL);
 	}
 
@@ -3187,21 +3162,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);
+		log_err("Too many field variables defined: %s", 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);
+		log_err("Couldn't parse field variable: %s", 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);
+		log_err("Couldn't create or find variable: %s", field_name);
 		kfree(val);
 		ret = PTR_ERR(var);
 		goto err;
@@ -3345,14 +3320,14 @@ static int onmax_create(struct hist_trigger_data *hist_data,
 
 	onmax_var_str = data->onmax.var_str;
 	if (onmax_var_str[0] != '$') {
-		hist_err("onmax: For onmax(x), x must be a variable: ", onmax_var_str);
+		log_err("onmax: For onmax(x), x must be a variable: %s", onmax_var_str);
 		return -EINVAL;
 	}
 	onmax_var_str++;
 
 	var_field = find_target_event_var(hist_data, NULL, NULL, onmax_var_str);
 	if (!var_field) {
-		hist_err("onmax: Couldn't find onmax variable: ", onmax_var_str);
+		log_err("onmax: Couldn't find onmax variable: %s", onmax_var_str);
 		return -EINVAL;
 	}
 
@@ -3374,7 +3349,7 @@ static int onmax_create(struct hist_trigger_data *hist_data,
 	data->onmax.max_var_ref_idx = var_ref_idx;
 	max_var = create_var(hist_data, file, "max", sizeof(u64), "u64");
 	if (IS_ERR(max_var)) {
-		hist_err("onmax: Couldn't create onmax variable: ", "max");
+		log_err("onmax: Couldn't create onmax variable: max");
 		ret = PTR_ERR(max_var);
 		goto out;
 	}
@@ -3389,7 +3364,7 @@ static int onmax_create(struct hist_trigger_data *hist_data,
 
 		field_var = create_target_field_var(hist_data, NULL, NULL, param);
 		if (IS_ERR(field_var)) {
-			hist_err("onmax: Couldn't create field variable: ", param);
+			log_err("onmax: Couldn't create field variable: %s", param);
 			ret = PTR_ERR(field_var);
 			kfree(param);
 			goto out;
@@ -3422,7 +3397,7 @@ static int parse_action_params(char *params, struct action_data *data)
 
 		param = strstrip(param);
 		if (strlen(param) < 2) {
-			hist_err("Invalid action param: ", param);
+			log_err("Invalid action param: %s", param);
 			ret = -EINVAL;
 			goto out;
 		}
@@ -3599,7 +3574,8 @@ static int check_synth_field(struct synth_event *event,
 	}
 
 	if (!hist_field)
-		hist_err_event("onmatch: Couldn't find onmatch param: $", system, event, var);
+		log_err("onmatch: Couldn't find onmatch param: %s",
+			fqvar(system, event, var, true));
 
 	return hist_field;
 }
@@ -3668,7 +3644,7 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
 	mutex_lock(&synth_event_mutex);
 	event = find_synth_event(data->onmatch.synth_event_name);
 	if (!event) {
-		hist_err("onmatch: Couldn't find synthetic event: ", data->onmatch.synth_event_name);
+		log_err("onmatch: Couldn't find synthetic event: %s", data->onmatch.synth_event_name);
 		mutex_unlock(&synth_event_mutex);
 		return -EINVAL;
 	}
@@ -3728,15 +3704,15 @@ static int onmatch_create(struct hist_trigger_data *hist_data,
 			continue;
 		}
 
-		hist_err_event("onmatch: Param type doesn't match synthetic event field type: ",
-			       system, event_name, param);
+		log_err("onmatch: Param type doesn't match synthetic event field type: %s",
+			fqvar(system, event_name, param, false));
 		kfree(p);
 		ret = -EINVAL;
 		goto err;
 	}
 
 	if (field_pos != event->n_fields) {
-		hist_err("onmatch: Param count doesn't match synthetic event field count: ", event->name);
+		log_err("onmatch: Param count doesn't match synthetic event field count: %s", event->name);
 		ret = -EINVAL;
 		goto err;
 	}
@@ -3767,19 +3743,19 @@ 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);
+		log_err("onmatch: Missing closing paren: %s", match_event);
 		goto free;
 	}
 
 	match_event_system = strsep(&match_event, ".");
 	if (!match_event) {
-		hist_err("onmatch: Missing subsystem for match event: ", match_event_system);
+		log_err("onmatch: Missing subsystem for match event: %s", 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);
+		log_err("onmatch: Invalid subsystem or event name: %s.%s",
+			match_event_system, match_event);
 		goto free;
 	}
 
@@ -3797,13 +3773,13 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str)
 
 	strsep(&str, ".");
 	if (!str) {
-		hist_err("onmatch: Missing . after onmatch(): ", str);
+		log_err("onmatch: Missing . after onmatch(): %s", str);
 		goto free;
 	}
 
 	synth_event_name = strsep(&str, "(");
 	if (!synth_event_name || !str) {
-		hist_err("onmatch: Missing opening paramlist paren: ", synth_event_name);
+		log_err("onmatch: Missing opening paramlist paren: %s", synth_event_name);
 		goto free;
 	}
 
@@ -3815,7 +3791,7 @@ static struct action_data *onmatch_parse(struct trace_array *tr, char *str)
 
 	params = strsep(&str, ")");
 	if (!params || !str || (str && strlen(str))) {
-		hist_err("onmatch: Missing closing paramlist paren: ", params);
+		log_err("onmatch: Missing closing paramlist paren: %s", params);
 		goto free;
 	}
 
@@ -3894,7 +3870,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);
+		log_err("Variable already defined: %s", var_name);
 		return -EINVAL;
 	}
 
@@ -3975,7 +3951,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);
+			log_err("Using variable references as keys not supported: %s", field_str);
 			destroy_hist_field(hist_field, 0);
 			ret = -EINVAL;
 			goto out;
@@ -4089,13 +4065,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);
+				log_err("Malformed assignment: %s", var_name);
 				ret = -EINVAL;
 				goto free;
 			}
 
 			if (n_vars == TRACING_MAP_VARS_MAX) {
-				hist_err("Too many variables defined: ", var_name);
+				log_err("Too many variables defined: %s", var_name);
 				ret = -EINVAL;
 				goto free;
 			}
@@ -4894,11 +4870,6 @@ static int hist_show(struct seq_file *m, void *v)
 			hist_trigger_show(m, data, n++);
 	}
 
-	if (have_hist_err()) {
-		seq_printf(m, "\nERROR: %s\n", hist_err_str);
-		seq_printf(m, "  Last command: %s\n", last_hist_cmd);
-	}
-
  out_unlock:
 	mutex_unlock(&event_mutex);
 
@@ -5270,7 +5241,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);
+				log_err("Named hist trigger doesn't match existing named trigger (includes variables): %s", hist_data->attrs->name);
 				ret = -EINVAL;
 				goto out;
 			}
@@ -5291,7 +5262,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);
+				log_err("Hist trigger already exists");
 				ret = -EEXIST;
 			}
 			goto out;
@@ -5299,7 +5270,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);
+		log_err("Can't clear or continue a nonexistent hist trigger");
 		ret = -ENOENT;
 		goto out;
 	}
@@ -5324,7 +5295,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);
+			log_err("Couldn't set trace_clock: %s", clock);
 			goto out;
 		}
 
-- 
1.9.3

[PATCH 5/6] tracing: Add field parsing trace event errors for hist triggers

[Tom Zanussi]

Log errors to the tracing/events/error_log for nonexistent fields and
modifiers specified in hist triggers.

Also screen out variable references, which shouldn't be looked up as
fields.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
Reported-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/trace/trace_events_hist.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 08424ff..d223fd6 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -2461,6 +2461,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
 		else if (strcmp(modifier, "usecs") == 0)
 			*flags |= HIST_FIELD_FL_TIMESTAMP_USECS;
 		else {
+			log_err("Invalid field modifier: %s", modifier);
 			field = ERR_PTR(-EINVAL);
 			goto out;
 		}
@@ -2476,6 +2477,7 @@ static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data,
 	else {
 		field = trace_find_event_field(file->event_call, field_name);
 		if (!field || !field->size) {
+			log_err("Couldn't find field: %s", field_name);
 			field = ERR_PTR(-EINVAL);
 			goto out;
 		}
@@ -2553,6 +2555,11 @@ static struct hist_field *parse_atom(struct hist_trigger_data *hist_data,
 	} else
 		str = s;
 
+	if (is_var_ref(str)) {
+		ret = -EINVAL;
+		goto out;
+	}
+
 	field = parse_field(hist_data, file, str, flags);
 	if (IS_ERR(field)) {
 		ret = PTR_ERR(field);
-- 
1.9.3

[PATCH 6/6] selftests: ftrace: Fix extended error support testcase

[Tom Zanussi]

Hist trigger errors are now sent to tracing/events/error_log rather
than the individual event hist files - have the testcase reflect that.

Signed-off-by: Tom Zanussi <tom.zanussi@linux.intel.com>
---
 .../ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
index 786dce7..2fd10ee 100644
--- a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
+++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc
@@ -30,7 +30,7 @@ do_reset
 echo "Test extended error support"
 echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger
 echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger &>/dev/null
-if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then
+if ! grep -q "ERROR(" events/error_log; then
     fail "Failed to generate extended error in histogram"
 fi
 
-- 
1.9.3

Re: [PATCH 2/6] tracing: Add trace event error log

[Steven Rostedt]

On Thu, 12 Apr 2018 10:13:17 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 6fb46a0..f2dc7e6 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
> +			  ...);
> +
>  /*
>   * Normal trace_printk() and friends allocates special buffers
>   * to do the manipulation, as well as saves the print formats
> diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> index 05c7172..fd02e22 100644
> --- a/kernel/trace/trace_events.c
> +++ b/kernel/trace/trace_events.c
> @@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
>  	return ret;
>  }
>  
> +#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))

> +#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)

BTW, the above only works if EVENT_LOG_ERRS_MAX is a power of two,
which it's not guaranteed to be.

> +
> +struct event_log_err {
> +	char			err[MAX_FILTER_STR_VAL];
> +	char			cmd[MAX_FILTER_STR_VAL];
> +};

I like the event_log_err idea, but the above can be shrunk to:

struct err_info {
	u8	type; /* I can only imagine 254 types */
	u8	pos;  /* MAX_FILTER_STR_VAR = 256 */
};

struct event_log_err {
	struct err_info		info;
	char			cmd[MAX_FILTER_STR_VAL];
};

There's no reason to put in a bunch of text that's going to be static
anyway. Have a lookup table like we do for filters.

+				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));


Instead of making the fqvar, find the location of the variable, and add:

 blah blah $var blah blah
            ^
  Variable name not unique, need to use fully qualified name for variable

> +
> +static char *event_err_log;
> +static unsigned int event_err_log_tail;
> +
> +struct event_log_err *get_event_log_err(void)
> +{
> +	struct event_log_err *err;
> +	char *errpos;
> +
> +	if (!event_err_log) {
> +		event_err_log = (char *)get_zeroed_page(GFP_KERNEL);
> +		if (!event_err_log)
> +			return NULL;
> +	}
> +
> +	errpos = event_err_log + event_err_log_tail * sizeof(*err);
> +	err = (struct event_log_err *)errpos;
> +
> +	event_err_log_tail = (event_err_log_tail + 1) & EVENT_ERR_LOG_MASK;

So you add errors one after the other:

First error:

 err1,NULL,NULL,NULL,...
      ^
     tail

Second error:

 err1,err2,NULL,NULL,...
           ^
          tail

Third error:

 err1,err2,err3,NULL,
                ^
               tail

> +
> +	return err;
> +}
> +
> +/**
> + * event_log_err - write an error to the trace event error log
> + * @loc: A string describing where the error occurred
> + * @cmd: The trace event command that caused the error
> + * @fmt: snprintf format string
> + * @...: variable length list of snprintf args
> + *
> + * Writes an error into tracing/events/error_log of the form:
> + *
> + * ERROR(<loc>): <error text ala snprintf>
> + *   Command: <command that caused the error>
> + *
> + * tracing/events/error_log is a small log file containing the last
> + * EVENT_LOG_ERRS_MAX errors (8).  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 i.e. echo > error_log.
> + *
> + * Must be called with event_mutex held.
> + */
> +void event_log_err(const char *loc, const char *cmd, const char *fmt, ...)
> +{
> +	struct event_log_err *err;
> +	va_list args;
> +	int len;
> +
> +	err = get_event_log_err();
> +	if (!err)
> +		return;
> +
> +	snprintf(err->cmd, MAX_FILTER_STR_VAL,"\n  Command: %s\n", cmd);
> +
> +	len = snprintf(err->err, MAX_FILTER_STR_VAL, "ERROR(%s): ", loc);
> +	if (len >= MAX_FILTER_STR_VAL)
> +		return;
> +
> +	va_start(args, fmt);
> +	vsnprintf(err->err + len, MAX_FILTER_STR_VAL - len, fmt, args);
> +	va_end(args);
> +}
> +
> +static void clear_event_err_log(void)
> +{
> +	free_page((long unsigned int)event_err_log);
> +	event_err_log_tail = 0;
> +	event_err_log = NULL;
> +}
> +
> +static void *event_err_log_inc(loff_t *pos)
> +{
> +	struct event_log_err *err = NULL;
> +	char *errpos = NULL;
> +	int i = *pos;
> +
> +	++*pos;
> +
> +	if (i >= EVENT_LOG_ERRS_MAX)
> +		return NULL;
> +
> +	i += event_err_log_tail;
> +	i &= EVENT_ERR_LOG_MASK;
> +
> +	errpos = event_err_log + (i * sizeof(*err));
> +	err = (struct event_log_err *)errpos;

Now I'm confused. i += tail, so on *pos = 0, and tail = 3, we have 
i = 3 (or i = tail)

 err1,err2,err3,NULL,...
                ^
               tail
                i

How do we return anything when the buffer isn't full yet?

What did I miss?

Wouldn't this need to go backwards?

	i = event_err_log_tail - (i + 1);
	if (i < 0)
		i = EVENT_ERROR_LOG - 1;

-- Steve

> +
> +	return err;
> +}
> +
> +static void *event_err_log_seq_start(struct seq_file *m, loff_t *pos)
> +{
> +	mutex_lock(&event_mutex);
> +
> +	return event_err_log_inc(pos);
> +}
> +
> +static void *event_err_log_seq_next(struct seq_file *m, void *v, loff_t *pos)
> +{
> +	return event_err_log_inc(pos);
> +}
> +
> +static void event_err_log_seq_stop(struct seq_file *m, void *v)
> +{
> +	mutex_unlock(&event_mutex);
> +}
> +
> +static int event_err_log_seq_show(struct seq_file *m, void *v)
> +{
> +	struct event_log_err *err = v;
> +
> +	if (err)
> +		seq_printf(m, "%s%s", err->err, err->cmd);
> +
> +	return 0;
> +}
> +
> +static const struct seq_operations event_err_log_seq_op = {
> +	.start  = event_err_log_seq_start,
> +	.next   = event_err_log_seq_next,
> +	.stop   = event_err_log_seq_stop,
> +	.show   = event_err_log_seq_show
> +};
> +
> +static int event_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, &event_err_log_seq_op);
> +}
> +
> +static ssize_t event_err_log_write(struct file *file,
> +				   const char __user *buffer,
> +				   size_t count, loff_t *ppos)
> +{
> +	if (count == 1)
> +		clear_event_err_log();
> +	else
> +		return -EINVAL;
> +
> +	*ppos += count;
> +
> +	return count;
> +}
> +
>  static int ftrace_event_avail_open(struct inode *inode, struct file *file);
>  static int ftrace_event_set_open(struct inode *inode, struct file *file);
>  static int ftrace_event_set_pid_open(struct inode *inode, struct file *file);
> @@ -1767,6 +1925,13 @@ static void ignore_task_cpu(void *data)
>  	.release = subsystem_release,
>  };
>  
> +static const struct file_operations ftrace_event_err_log_fops = {
> +	.open           = event_err_log_open,
> +	.write		= event_err_log_write,
> +	.read           = seq_read,
> +	.llseek         = seq_lseek,
> +};
> +
>  static const struct file_operations ftrace_show_header_fops = {
>  	.open = tracing_open_generic,
>  	.read = show_header,
> @@ -2927,6 +3092,13 @@ static __init int setup_trace_event(char *str)
>  		return -ENOMEM;
>  	}
>  
> +	entry = trace_create_file("error_log", 0644, d_events,
> +				  tr, &ftrace_event_err_log_fops);
> +	if (!entry) {
> +		pr_warn("Could not create tracefs 'error_log' entry\n");
> +		return -ENOMEM;
> +	}
> +
>  	/* There are not as crucial, just warn if they are not created */
>  
>  	entry = tracefs_create_file("set_event_pid", 0644, parent,

Re: [PATCH 2/6] tracing: Add trace event error log

[Tom Zanussi]

Hi Steve,

On Thu, 2018-04-12 at 18:20 -0400, Steven Rostedt wrote:
> On Thu, 12 Apr 2018 10:13:17 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > index 6fb46a0..f2dc7e6 100644
> > --- a/kernel/trace/trace.h
> > +++ b/kernel/trace/trace.h
> > @@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
> > +			  ...);
> > +
> >  /*
> >   * Normal trace_printk() and friends allocates special buffers
> >   * to do the manipulation, as well as saves the print formats
> > diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> > index 05c7172..fd02e22 100644
> > --- a/kernel/trace/trace_events.c
> > +++ b/kernel/trace/trace_events.c
> > @@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
> >  	return ret;
> >  }
> >  
> > +#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))
> 
> > +#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)
> 
> BTW, the above only works if EVENT_LOG_ERRS_MAX is a power of two,
> which it's not guaranteed to be.
> 

My assumption was that we'd only ever need a page or two for the
error_log and so would always would be a power of two, since the size of
the struct event_log_err is 512.

Anyway, I should probably have put comments about all this in the code,
and I will, but the way it works kind of assumes a very small number of
errors - it's replacing a simple 'last error' facility for the hist
triggers and making it a common facility for other things that have
similar needs like Masami's kprobe_events errors.  For those purposes, I
assumed it would suffice to simply be able to show that last 8 or some
similar small number of errors and constantly recycle the slots.

Basically it just splits the page into 16 strings, 2 per error, one for
the actual error text, the other for the command the user entered.  The
struct event_log_err just overlays a struct on top of 2 strings just to
make it easier to manage.

Anyway, because it is such a small number, and we start with a zeroed
page, whenever we print the error log, we print all 16 strings even if
we only have one error (2 strings).  The rest are NULL and print
nothing.  We start with the tail, which could also be thought of as the
'oldest' or the 'first' error in the buffer and just cycle through them
all.  Hope that clears up some of the other questions you had about how
a non-full log gets printed, etc... 

> > +
> > +struct event_log_err {
> > +	char			err[MAX_FILTER_STR_VAL];
> > +	char			cmd[MAX_FILTER_STR_VAL];
> > +};
> 
> I like the event_log_err idea, but the above can be shrunk to:
> 
> struct err_info {
> 	u8	type; /* I can only imagine 254 types */
> 	u8	pos;  /* MAX_FILTER_STR_VAR = 256 */
> };
> 
> struct event_log_err {
> 	struct err_info		info;
> 	char			cmd[MAX_FILTER_STR_VAL];
> };
> 
> There's no reason to put in a bunch of text that's going to be static
> anyway. Have a lookup table like we do for filters.
> 
> +				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
> 

Hmm, most of the log_errs use printf strings that get expanded, so need
a destination buffer, the event_log_err->err string, but I think I see
what you're getting at - that we can get rid of the format strings
altogether and make them static strings if we use the method of simply
printing the static string and putting a caret where the error is as
below.

> 
> Instead of making the fqvar, find the location of the variable, and add:
> 
>  blah blah $var blah blah
>             ^
>   Variable name not unique, need to use fully qualified name for variable
> 

OK, if we can do this for every error type, then we can use the lookup
table and the caret position instead of format strings.  Which means
getting rid of the simple ring of strings, but whatever..

> > +
> > +static char *event_err_log;
> > +static unsigned int event_err_log_tail;
> > +
> > +struct event_log_err *get_event_log_err(void)
> > +{
> > +	struct event_log_err *err;
> > +	char *errpos;
> > +
> > +	if (!event_err_log) {
> > +		event_err_log = (char *)get_zeroed_page(GFP_KERNEL);
> > +		if (!event_err_log)
> > +			return NULL;
> > +	}
> > +
> > +	errpos = event_err_log + event_err_log_tail * sizeof(*err);
> > +	err = (struct event_log_err *)errpos;
> > +
> > +	event_err_log_tail = (event_err_log_tail + 1) & EVENT_ERR_LOG_MASK;
> 
> So you add errors one after the other:
> 
> First error:
> 
>  err1,NULL,NULL,NULL,...
>       ^
>      tail
> 
> Second error:
> 
>  err1,err2,NULL,NULL,...
>            ^
>           tail
> 
> Third error:
> 
>  err1,err2,err3,NULL,
>                 ^
>                tail
> 

Yeah, in each case we print all the NULL strings first, which result in
no output, and then wrap around and print the errors in order.

> > +
> > +	return err;
> > +}
> > +
> > +/**
> > + * event_log_err - write an error to the trace event error log
> > + * @loc: A string describing where the error occurred
> > + * @cmd: The trace event command that caused the error
> > + * @fmt: snprintf format string
> > + * @...: variable length list of snprintf args
> > + *
> > + * Writes an error into tracing/events/error_log of the form:
> > + *
> > + * ERROR(<loc>): <error text ala snprintf>
> > + *   Command: <command that caused the error>
> > + *
> > + * tracing/events/error_log is a small log file containing the last
> > + * EVENT_LOG_ERRS_MAX errors (8).  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 i.e. echo > error_log.
> > + *
> > + * Must be called with event_mutex held.
> > + */
> > +void event_log_err(const char *loc, const char *cmd, const char *fmt, ...)
> > +{
> > +	struct event_log_err *err;
> > +	va_list args;
> > +	int len;
> > +
> > +	err = get_event_log_err();
> > +	if (!err)
> > +		return;
> > +
> > +	snprintf(err->cmd, MAX_FILTER_STR_VAL,"\n  Command: %s\n", cmd);
> > +
> > +	len = snprintf(err->err, MAX_FILTER_STR_VAL, "ERROR(%s): ", loc);
> > +	if (len >= MAX_FILTER_STR_VAL)
> > +		return;
> > +
> > +	va_start(args, fmt);
> > +	vsnprintf(err->err + len, MAX_FILTER_STR_VAL - len, fmt, args);
> > +	va_end(args);
> > +}
> > +
> > +static void clear_event_err_log(void)
> > +{
> > +	free_page((long unsigned int)event_err_log);
> > +	event_err_log_tail = 0;
> > +	event_err_log = NULL;
> > +}
> > +
> > +static void *event_err_log_inc(loff_t *pos)
> > +{
> > +	struct event_log_err *err = NULL;
> > +	char *errpos = NULL;
> > +	int i = *pos;
> > +
> > +	++*pos;
> > +
> > +	if (i >= EVENT_LOG_ERRS_MAX)
> > +		return NULL;
> > +
> > +	i += event_err_log_tail;
> > +	i &= EVENT_ERR_LOG_MASK;
> > +
> > +	errpos = event_err_log + (i * sizeof(*err));
> > +	err = (struct event_log_err *)errpos;
> 
> Now I'm confused. i += tail, so on *pos = 0, and tail = 3, we have 
> i = 3 (or i = tail)
> 
>  err1,err2,err3,NULL,...
>                 ^
>                tail
>                 i
> 
> How do we return anything when the buffer isn't full yet?
> 
> What did I miss?
> 

Just that we're actually printing starting with those NULL strings and
wrapping around.  It's not a big deal because we only have a handful so
simplicity over efficiency. ;-)

Tom

> Wouldn't this need to go backwards?
> 
> 	i = event_err_log_tail - (i + 1);
> 	if (i < 0)
> 		i = EVENT_ERROR_LOG - 1;
> 
> -- Steve
> 

Re: [PATCH 2/6] tracing: Add trace event error log

[Steven Rostedt]

On Thu, 12 Apr 2018 18:52:13 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Hi Steve,
> 
> On Thu, 2018-04-12 at 18:20 -0400, Steven Rostedt wrote:
> > On Thu, 12 Apr 2018 10:13:17 -0500
> > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> >   
> > > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > > index 6fb46a0..f2dc7e6 100644
> > > --- a/kernel/trace/trace.h
> > > +++ b/kernel/trace/trace.h
> > > @@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
> > > +			  ...);
> > > +
> > >  /*
> > >   * Normal trace_printk() and friends allocates special buffers
> > >   * to do the manipulation, as well as saves the print formats
> > > diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> > > index 05c7172..fd02e22 100644
> > > --- a/kernel/trace/trace_events.c
> > > +++ b/kernel/trace/trace_events.c
> > > @@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
> > >  	return ret;
> > >  }
> > >  
> > > +#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))  
> >   
> > > +#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)  
> > 
> > BTW, the above only works if EVENT_LOG_ERRS_MAX is a power of two,
> > which it's not guaranteed to be.
> >   
> 
> My assumption was that we'd only ever need a page or two for the
> error_log and so would always would be a power of two, since the size of
> the struct event_log_err is 512.

Assumptions are not what we want to rely on. There should be something
like:

	BUILD_BUG_ON(EVENT_LOG_ERRS_MAX & EVENT_ERR_LOG_MASK);

Which would guarantee that your assumption is correct otherwise the
kernel wont build.


> 
> Anyway, I should probably have put comments about all this in the code,
> and I will, but the way it works kind of assumes a very small number of
> errors - it's replacing a simple 'last error' facility for the hist
> triggers and making it a common facility for other things that have
> similar needs like Masami's kprobe_events errors.  For those purposes, I
> assumed it would suffice to simply be able to show that last 8 or some
> similar small number of errors and constantly recycle the slots.

The errors are still in the files that have the errors right? Perhaps
just have a file that lists the files that contain errors. That way if
something goes wrong, you can examine that file and then look at the
file that contains the error?

And I'm not sure it being in the events directory is the best place
either, especially, if you plan to have it handle kprobe_events because
that's not in the events directory.

> 
> Basically it just splits the page into 16 strings, 2 per error, one for
> the actual error text, the other for the command the user entered.  The
> struct event_log_err just overlays a struct on top of 2 strings just to
> make it easier to manage.
> 
> Anyway, because it is such a small number, and we start with a zeroed
> page, whenever we print the error log, we print all 16 strings even if
> we only have one error (2 strings).  The rest are NULL and print
> nothing.  We start with the tail, which could also be thought of as the
> 'oldest' or the 'first' error in the buffer and just cycle through them
> all.  Hope that clears up some of the other questions you had about how
> a non-full log gets printed, etc...

OK, I was thinking a NULL entry would return NULL, but we are
returning a pointer to NULL. That's where I missed it.
 
> 
> > > +
> > > +struct event_log_err {
> > > +	char			err[MAX_FILTER_STR_VAL];
> > > +	char			cmd[MAX_FILTER_STR_VAL];
> > > +};  
> > 
> > I like the event_log_err idea, but the above can be shrunk to:
> > 
> > struct err_info {
> > 	u8	type; /* I can only imagine 254 types */
> > 	u8	pos;  /* MAX_FILTER_STR_VAR = 256 */
> > };
> > 
> > struct event_log_err {
> > 	struct err_info		info;
> > 	char			cmd[MAX_FILTER_STR_VAL];
> > };
> > 
> > There's no reason to put in a bunch of text that's going to be static
> > anyway. Have a lookup table like we do for filters.
> > 
> > +				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
> >   
> 
> Hmm, most of the log_errs use printf strings that get expanded, so need
> a destination buffer, the event_log_err->err string, but I think I see
> what you're getting at - that we can get rid of the format strings
> altogether and make them static strings if we use the method of simply
> printing the static string and putting a caret where the error is as
> below.
> 
> > 
> > Instead of making the fqvar, find the location of the variable, and add:
> > 
> >  blah blah $var blah blah
> >             ^
> >   Variable name not unique, need to use fully qualified name for variable
> >   
> 
> OK, if we can do this for every error type, then we can use the lookup
> table and the caret position instead of format strings.  Which means
> getting rid of the simple ring of strings, but whatever..

I still don't know about this change. It feels rather hacky and quickly
thrown together. This is going to be something we will have to support
indefinitely, and I want to have a bit more thought in it before we do
anything.

This isn't something I want to push into this merge window. Let's think
about it more. Is this really the best way to show errors?

-- Steve


> 
> > > +
> > > +static char *event_err_log;
> > > +static unsigned int event_err_log_tail;
> > > +
> > > +struct event_log_err *get_event_log_err(void)
> > > +{
> > > +	struct event_log_err *err;
> > > +	char *errpos;
> > > +
> > > +	if (!event_err_log) {
> > > +		event_err_log = (char *)get_zeroed_page(GFP_KERNEL);
> > > +		if (!event_err_log)
> > > +			return NULL;
> > > +	}
> > > +
> > > +	errpos = event_err_log + event_err_log_tail * sizeof(*err);
> > > +	err = (struct event_log_err *)errpos;
> > > +
> > > +	event_err_log_tail = (event_err_log_tail + 1) & EVENT_ERR_LOG_MASK;  
> >

Re: [PATCH 2/6] tracing: Add trace event error log

[Tom Zanussi]

Hi Steve,

On Fri, 2018-04-13 at 09:45 -0400, Steven Rostedt wrote:
> On Thu, 12 Apr 2018 18:52:13 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > Hi Steve,
> > 
> > On Thu, 2018-04-12 at 18:20 -0400, Steven Rostedt wrote:
> > > On Thu, 12 Apr 2018 10:13:17 -0500
> > > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> > >   
> > > > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > > > index 6fb46a0..f2dc7e6 100644
> > > > --- a/kernel/trace/trace.h
> > > > +++ b/kernel/trace/trace.h
> > > > @@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
> > > > +			  ...);
> > > > +
> > > >  /*
> > > >   * Normal trace_printk() and friends allocates special buffers
> > > >   * to do the manipulation, as well as saves the print formats
> > > > diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> > > > index 05c7172..fd02e22 100644
> > > > --- a/kernel/trace/trace_events.c
> > > > +++ b/kernel/trace/trace_events.c
> > > > @@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
> > > >  	return ret;
> > > >  }
> > > >  
> > > > +#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))  
> > >   
> > > > +#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)  
> > > 
> > > BTW, the above only works if EVENT_LOG_ERRS_MAX is a power of two,
> > > which it's not guaranteed to be.
> > >   
> > 
> > My assumption was that we'd only ever need a page or two for the
> > error_log and so would always would be a power of two, since the size of
> > the struct event_log_err is 512.
> 
> Assumptions are not what we want to rely on. There should be something
> like:
> 
> 	BUILD_BUG_ON(EVENT_LOG_ERRS_MAX & EVENT_ERR_LOG_MASK);
> 
> Which would guarantee that your assumption is correct otherwise the
> kernel wont build.
> 

OK.

> 
> > 
> > Anyway, I should probably have put comments about all this in the code,
> > and I will, but the way it works kind of assumes a very small number of
> > errors - it's replacing a simple 'last error' facility for the hist
> > triggers and making it a common facility for other things that have
> > similar needs like Masami's kprobe_events errors.  For those purposes, I
> > assumed it would suffice to simply be able to show that last 8 or some
> > similar small number of errors and constantly recycle the slots.
> 
> The errors are still in the files that have the errors right? Perhaps
> just have a file that lists the files that contain errors. That way if
> something goes wrong, you can examine that file and then look at the
> file that contains the error?
> 

No, that's part of the motivation for this change - currently there is
just one last 'last error', the output tacked onto whichever event's
hist file you read (normally this would be the one you just got the
error for, but doesn't have to be) - there isn't a last error per event.
Masami of course found this unintuitive, which it is, I agree, and
wanted a single file (error_log) to look into for the last error.  In
addition, it should have a logging interface that any trace event
command could use, such as kprobe_events.

> And I'm not sure it being in the events directory is the best place
> either, especially, if you plan to have it handle kprobe_events because
> that's not in the events directory.
> 

Yeah, I put it there because it's associated with trace events - putting
it in tracing/ would imply that it's meant for ftrace in general (which
maybe it should be but this isn't).  Actually I'm not sure kprobe_events
shouldn't be in tracing/events too..

> > 
> > Basically it just splits the page into 16 strings, 2 per error, one for
> > the actual error text, the other for the command the user entered.  The
> > struct event_log_err just overlays a struct on top of 2 strings just to
> > make it easier to manage.
> > 
> > Anyway, because it is such a small number, and we start with a zeroed
> > page, whenever we print the error log, we print all 16 strings even if
> > we only have one error (2 strings).  The rest are NULL and print
> > nothing.  We start with the tail, which could also be thought of as the
> > 'oldest' or the 'first' error in the buffer and just cycle through them
> > all.  Hope that clears up some of the other questions you had about how
> > a non-full log gets printed, etc...
> 
> OK, I was thinking a NULL entry would return NULL, but we are
> returning a pointer to NULL. That's where I missed it.
>  
> > 
> > > > +
> > > > +struct event_log_err {
> > > > +	char			err[MAX_FILTER_STR_VAL];
> > > > +	char			cmd[MAX_FILTER_STR_VAL];
> > > > +};  
> > > 
> > > I like the event_log_err idea, but the above can be shrunk to:
> > > 
> > > struct err_info {
> > > 	u8	type; /* I can only imagine 254 types */
> > > 	u8	pos;  /* MAX_FILTER_STR_VAR = 256 */
> > > };
> > > 
> > > struct event_log_err {
> > > 	struct err_info		info;
> > > 	char			cmd[MAX_FILTER_STR_VAL];
> > > };
> > > 
> > > There's no reason to put in a bunch of text that's going to be static
> > > anyway. Have a lookup table like we do for filters.
> > > 
> > > +				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
> > >   
> > 
> > Hmm, most of the log_errs use printf strings that get expanded, so need
> > a destination buffer, the event_log_err->err string, but I think I see
> > what you're getting at - that we can get rid of the format strings
> > altogether and make them static strings if we use the method of simply
> > printing the static string and putting a caret where the error is as
> > below.
> > 
> > > 
> > > Instead of making the fqvar, find the location of the variable, and add:
> > > 
> > >  blah blah $var blah blah
> > >             ^
> > >   Variable name not unique, need to use fully qualified name for variable
> > >   
> > 
> > OK, if we can do this for every error type, then we can use the lookup
> > table and the caret position instead of format strings.  Which means
> > getting rid of the simple ring of strings, but whatever..
> 
> I still don't know about this change. It feels rather hacky and quickly
> thrown together. This is going to be something we will have to support
> indefinitely, and I want to have a bit more thought in it before we do
> anything.
> 
> This isn't something I want to push into this merge window. Let's think
> about it more. Is this really the best way to show errors?
> 

Yeah, I agree - I'd rather get it right than get it in now.  I thought
this made sense, and was based on input from Masami, which I may have
misinterpreted, but I'll wait for some more ideas about the best way to
do this.

Thanks,

Tom

> -- Steve
> 
> 
> > 
> > > > +
> > > > +static char *event_err_log;
> > > > +static unsigned int event_err_log_tail;
> > > > +
> > > > +struct event_log_err *get_event_log_err(void)
> > > > +{
> > > > +	struct event_log_err *err;
> > > > +	char *errpos;
> > > > +
> > > > +	if (!event_err_log) {
> > > > +		event_err_log = (char *)get_zeroed_page(GFP_KERNEL);
> > > > +		if (!event_err_log)
> > > > +			return NULL;
> > > > +	}
> > > > +
> > > > +	errpos = event_err_log + event_err_log_tail * sizeof(*err);
> > > > +	err = (struct event_log_err *)errpos;
> > > > +
> > > > +	event_err_log_tail = (event_err_log_tail + 1) & EVENT_ERR_LOG_MASK;  
> > >

Re: [PATCH 2/6] tracing: Add trace event error log

[Steven Rostedt]

On Fri, 13 Apr 2018 09:24:34 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Yeah, I agree - I'd rather get it right than get it in now.  I thought
> this made sense, and was based on input from Masami, which I may have
> misinterpreted, but I'll wait for some more ideas about the best way to
> do this.

Too bad we are not closer to November, as this would actually be a good
Plumbers topic. Maybe it's not that important and we should wait until
then. I'd like to get some brain storming ideas out before we decide on
anything, and this is something I believe is better done face to face
than over email.

-- Steve

Re: [PATCH 2/6] tracing: Add trace event error log

[Masami Hiramatsu]

On Thu, 12 Apr 2018 18:52:13 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Hi Steve,
> 
> On Thu, 2018-04-12 at 18:20 -0400, Steven Rostedt wrote:
> > On Thu, 12 Apr 2018 10:13:17 -0500
> > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> > 
> > > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> > > index 6fb46a0..f2dc7e6 100644
> > > --- a/kernel/trace/trace.h
> > > +++ b/kernel/trace/trace.h
> > > @@ -1765,6 +1765,9 @@ 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 void event_log_err(const char *loc, const char *cmd, const char *fmt,
> > > +			  ...);
> > > +
> > >  /*
> > >   * Normal trace_printk() and friends allocates special buffers
> > >   * to do the manipulation, as well as saves the print formats
> > > diff --git a/kernel/trace/trace_events.c b/kernel/trace/trace_events.c
> > > index 05c7172..fd02e22 100644
> > > --- a/kernel/trace/trace_events.c
> > > +++ b/kernel/trace/trace_events.c
> > > @@ -1668,6 +1668,164 @@ static void ignore_task_cpu(void *data)
> > >  	return ret;
> > >  }
> > >  
> > > +#define EVENT_LOG_ERRS_MAX	(PAGE_SIZE / sizeof(struct event_log_err))
> > 
> > > +#define EVENT_ERR_LOG_MASK	(EVENT_LOG_ERRS_MAX - 1)
> > 
> > BTW, the above only works if EVENT_LOG_ERRS_MAX is a power of two,
> > which it's not guaranteed to be.
> > 
> 
> My assumption was that we'd only ever need a page or two for the
> error_log and so would always would be a power of two, since the size of
> the struct event_log_err is 512.
> 
> Anyway, I should probably have put comments about all this in the code,
> and I will, but the way it works kind of assumes a very small number of
> errors - it's replacing a simple 'last error' facility for the hist
> triggers and making it a common facility for other things that have
> similar needs like Masami's kprobe_events errors.  For those purposes, I
> assumed it would suffice to simply be able to show that last 8 or some
> similar small number of errors and constantly recycle the slots.

Correct. I don't think the error log entry size over 16, it is too much
errors occur. User must check it before that. Or, we should push it
printk buffer.

> 
> Basically it just splits the page into 16 strings, 2 per error, one for
> the actual error text, the other for the command the user entered.  The
> struct event_log_err just overlays a struct on top of 2 strings just to
> make it easier to manage.
> 
> Anyway, because it is such a small number, and we start with a zeroed
> page, whenever we print the error log, we print all 16 strings even if
> we only have one error (2 strings).  The rest are NULL and print
> nothing.  We start with the tail, which could also be thought of as the
> 'oldest' or the 'first' error in the buffer and just cycle through them
> all.  Hope that clears up some of the other questions you had about how
> a non-full log gets printed, etc... 
> 
> > > +
> > > +struct event_log_err {
> > > +	char			err[MAX_FILTER_STR_VAL];
> > > +	char			cmd[MAX_FILTER_STR_VAL];
> > > +};
> > 
> > I like the event_log_err idea, but the above can be shrunk to:
> > 
> > struct err_info {
> > 	u8	type; /* I can only imagine 254 types */
> > 	u8	pos;  /* MAX_FILTER_STR_VAR = 256 */
> > };
> > 
> > struct event_log_err {
> > 	struct err_info		info;
> > 	char			cmd[MAX_FILTER_STR_VAL];
> > };
> > 
> > There's no reason to put in a bunch of text that's going to be static
> > anyway. Have a lookup table like we do for filters.
> > 
> > +				log_err("Variable name not unique, need to use fully qualified name (%s) for variable: ", fqvar(system, event_name, var_name, true));
> > 
> 
> Hmm, most of the log_errs use printf strings that get expanded, so need
> a destination buffer, the event_log_err->err string, but I think I see
> what you're getting at - that we can get rid of the format strings
> altogether and make them static strings if we use the method of simply
> printing the static string and putting a caret where the error is as
> below.
> 
> > 
> > Instead of making the fqvar, find the location of the variable, and add:
> > 
> >  blah blah $var blah blah
> >             ^
> >   Variable name not unique, need to use fully qualified name for variable
> > 
> 
> OK, if we can do this for every error type, then we can use the lookup
> table and the caret position instead of format strings.  Which means
> getting rid of the simple ring of strings, but whatever..

>From the viewpoint of kprobe events, I'm OK for either way.
I'll rewrite parser to get parsing position correctly.

Thanks!


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH 2/6] tracing: Add trace event error log

[Masami Hiramatsu]

On Fri, 13 Apr 2018 10:44:32 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 13 Apr 2018 09:24:34 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > Yeah, I agree - I'd rather get it right than get it in now.  I thought
> > this made sense, and was based on input from Masami, which I may have
> > misinterpreted, but I'll wait for some more ideas about the best way to
> > do this.
> 
> Too bad we are not closer to November, as this would actually be a good
> Plumbers topic. Maybe it's not that important and we should wait until
> then. I'd like to get some brain storming ideas out before we decide on
> anything, and this is something I believe is better done face to face
> than over email.

OK, sounds good for me too :)
My point was that printk buffer is not good place for the parser error
of ftrace, nor each sub-features (like hist, trigger, probe_events etc.) 
has different place to show it. I just want to unify the user experience
over the ftrace UI.

Thanks,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH 2/6] tracing: Add trace event error log

[Steven Rostedt]

On Wed, 18 Apr 2018 18:34:34 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> On Fri, 13 Apr 2018 10:44:32 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Fri, 13 Apr 2018 09:24:34 -0500
> > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> >   
> > > Yeah, I agree - I'd rather get it right than get it in now.  I thought
> > > this made sense, and was based on input from Masami, which I may have
> > > misinterpreted, but I'll wait for some more ideas about the best way to
> > > do this.  
> > 
> > Too bad we are not closer to November, as this would actually be a good
> > Plumbers topic. Maybe it's not that important and we should wait until
> > then. I'd like to get some brain storming ideas out before we decide on
> > anything, and this is something I believe is better done face to face
> > than over email.  
> 
> OK, sounds good for me too :)
> My point was that printk buffer is not good place for the parser error
> of ftrace, nor each sub-features (like hist, trigger, probe_events etc.) 
> has different place to show it. I just want to unify the user experience
> over the ftrace UI.

I totally agree. I just want to make sure that whatever we come up with
will be well thought out. Perhaps we can wait till November to talk
about it.

-- Steve

Re: [PATCH 2/6] tracing: Add trace event error log

[Namhyung Kim]

Hi guys, :)

On Wed, Apr 18, 2018 at 09:49:24AM -0400, Steven Rostedt wrote:
> On Wed, 18 Apr 2018 18:34:34 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > On Fri, 13 Apr 2018 10:44:32 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Fri, 13 Apr 2018 09:24:34 -0500
> > > Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> > >   
> > > > Yeah, I agree - I'd rather get it right than get it in now.  I thought
> > > > this made sense, and was based on input from Masami, which I may have
> > > > misinterpreted, but I'll wait for some more ideas about the best way to
> > > > do this.  
> > > 
> > > Too bad we are not closer to November, as this would actually be a good
> > > Plumbers topic. Maybe it's not that important and we should wait until
> > > then. I'd like to get some brain storming ideas out before we decide on
> > > anything, and this is something I believe is better done face to face
> > > than over email.  
> > 
> > OK, sounds good for me too :)
> > My point was that printk buffer is not good place for the parser error
> > of ftrace, nor each sub-features (like hist, trigger, probe_events etc.) 
> > has different place to show it. I just want to unify the user experience
> > over the ftrace UI.
> 
> I totally agree. I just want to make sure that whatever we come up with
> will be well thought out. Perhaps we can wait till November to talk
> about it.

I'm not sure I can go to LPC this year, but definitely interested in
improving error logging for tracing.

Thanks,
Namhyung

Re: [PATCH 2/6] tracing: Add trace event error log

[Steven Rostedt]

On Thu, 19 Apr 2018 09:40:33 +0900
Namhyung Kim <namhyung@kernel.org> wrote:

> > I totally agree. I just want to make sure that whatever we come up with
> > will be well thought out. Perhaps we can wait till November to talk
> > about it.  
> 
> I'm not sure I can go to LPC this year, but definitely interested in
> improving error logging for tracing.

Feel free to send any ideas to us that you would like for us to add to
this discussion.

-- Steve

Re: [PATCH 0/6] tracing: trace event error_log and inter-event bugfixes

[Steven Rostedt]

Hi Tom,

This thread sorta died and appears to be forgotten. Is there follow up
patches on this?

Thanks!

-- Steve


On Thu, 12 Apr 2018 10:13:15 -0500
Tom Zanussi <tom.zanussi@linux.intel.com> wrote:

> Hi Steve,
> 
> Here are a few patches that should be applied on top of the
> 'Inter-event (e.g. latency) support v9' patchset.
> 
> The first fixes another problem I noticed when printing flags.
> 
> The rest implement the tracing/events/error_log suggested by Masami,
> and update the inter-event code to use it (and remove the old hist
> file error mechanism).
> 
> Thanks,
> 
> Tom
> 
> The following changes since commit 404bb11b24fb9a592023c077b878d30ad6da4322:
> 
>   tracing: Enforce passing in filter=NULL to create_filter() (2018-04-11 11:18:42 -0400)
> 
> are available in the git repository at:
> 
>   https://github.com/tzanussi/linux-trace-inter-event.git tzanussi/inter-event-update2
>   https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-update2
> 
> Tom Zanussi (6):
>   tracing: Restore proper field flag printing when displaying triggers
>   tracing: Add trace event error log
>   tracing: Save the last hist command's associated event name
>   tracing: Use trace event error_log with hist triggers
>   tracing: Add field parsing trace event errors for hist triggers
>   selftests: ftrace: Fix extended error support testcase
> 
>  kernel/trace/trace.h                               |   3 +
>  kernel/trace/trace_events.c                        | 172 +++++++++++++++++++
>  kernel/trace/trace_events_hist.c                   | 188 +++++++++++----------
>  .../inter-event/trigger-extended-error-support.tc  |   2 +-
>  4 files changed, 274 insertions(+), 91 deletions(-)
> 

Re: [PATCH 0/6] tracing: trace event error_log and inter-event bugfixes

[Tom Zanussi]

Hi Steve,

On Tue, 2019-01-15 at 22:31 -0500, Steven Rostedt wrote:
> Hi Tom,
> 
> This thread sorta died and appears to be forgotten. Is there follow
> up
> patches on this?
> 

No, there wasn't a followup v2 for this - the last suggestion was that
we'd discuss this face-to-face at Plumbers, but I didn't get to go to
Plumbers...

Anyway, there were some good suggestions in the thread - let me spin up
a v2 that incorporates them, and we can go from there.

Tom

> Thanks!
> 
> -- Steve
> 
> 
> On Thu, 12 Apr 2018 10:13:15 -0500
> Tom Zanussi <tom.zanussi@linux.intel.com> wrote:
> 
> > Hi Steve,
> > 
> > Here are a few patches that should be applied on top of the
> > 'Inter-event (e.g. latency) support v9' patchset.
> > 
> > The first fixes another problem I noticed when printing flags.
> > 
> > The rest implement the tracing/events/error_log suggested by
> > Masami,
> > and update the inter-event code to use it (and remove the old hist
> > file error mechanism).
> > 
> > Thanks,
> > 
> > Tom
> > 
> > The following changes since commit
> > 404bb11b24fb9a592023c077b878d30ad6da4322:
> > 
> >   tracing: Enforce passing in filter=NULL to create_filter() (2018-
> > 04-11 11:18:42 -0400)
> > 
> > are available in the git repository at:
> > 
> >   https://github.com/tzanussi/linux-trace-inter-event.git
> > tzanussi/inter-event-update2
> >   
> > https://github.com/tzanussi/linux-trace-inter-event/tree/tzanussi/inter-event-update2
> > 
> > Tom Zanussi (6):
> >   tracing: Restore proper field flag printing when displaying
> > triggers
> >   tracing: Add trace event error log
> >   tracing: Save the last hist command's associated event name
> >   tracing: Use trace event error_log with hist triggers
> >   tracing: Add field parsing trace event errors for hist triggers
> >   selftests: ftrace: Fix extended error support testcase
> > 
> >  kernel/trace/trace.h                               |   3 +
> >  kernel/trace/trace_events.c                        | 172
> > +++++++++++++++++++
> >  kernel/trace/trace_events_hist.c                   | 188
> > +++++++++++----------
> >  .../inter-event/trigger-extended-error-support.tc  |   2 +-
> >  4 files changed, 274 insertions(+), 91 deletions(-)
> > 
> 
>