[PATCH v2 00/10] tracing/boot: Add histogram syntax support in boot-time tracing

[PATCH v2 00/10] tracing/boot: Add histogram syntax support in boot-time tracing

[Masami Hiramatsu]

Hi,

Here is the 3rd version of boot-time tracing to add histogram
syntax extension with a bugfix related hist-trigger.

In this version, I updated the first bugfix to use IS_ENABLED()
and show error if CONFIG_HIST_TRIGGERS=n ([1/10]), allow the spaces
in the variable expressions ([2/10]), and update ktest bootconfig
testcase ([10/10]).


'Histogram' options
-------------------
Currently, the boot-time tracing only supports per-event actions
for setting trigger actions. This is enough for short actions
like 'traceon', 'traceoff', 'snapshot' etc. However, it is not good
for the 'hist' trigger action because it is usually too long to write
it in a single string especially if it has an 'onmatch' action.

Here is the new syntax.

    ftrace[.instance.INSTANCE].event.GROUP.EVENT.hist[.N] {
         keys = <KEY>[,...]
         values = <VAL>[,...]
         sort = <SORT-KEY>[,...]
         size = <ENTRIES>
         name = <HISTNAME>
         var { <VAR> = <EXPR> ... }
         pause|continue|clear
         onmax|onchange[.M] { var = <VAR>, <ACTION> [= <PARAM>] }
         onmatch[.M] { event = <EVENT>, <ACTION> [= <PARAM>] }
         filter = <FILTER>
    }
    
Where <ACTION> is one of below;
    
    trace = <EVENT>, <ARG1>[, ...]
    save = <ARG1>[, ...]
    snapshot

And "N" and "M" are digit started strings for multiple histograms
and actions.

For example,

initcall.initcall_finish.actions =
"hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).trace(initcall_latency,func,$lat)"

This can be written as below;

initcall.initcall_finish.hist {
    keys = func
    var.lat = common_timestamp.usecs-$ts0
    onmatch {
        event = initcall.initcall_start
        trace = initcall_latency, func, $lat
    }
}

Also, you can add comments for each options.


Thank you,

---

Masami Hiramatsu (10):
      tracing/boot: Fix a hist trigger dependency for boot time tracing
      tracing/boot: Add per-event histogram action options
      tracing/boot: Support multiple handlers for per-event histogram
      tracing/boot: Support multiple histograms for each event
      tracing/boot: Show correct histogram error command
      Documentation: tracing: Add histogram syntax to boot-time tracing
      tools/bootconfig: Support per-group/all event enabling option
      tools/bootconfig: Add histogram syntax support to bconf2ftrace.sh
      tools/bootconfig: Use per-group/all enable option in ftrace2bconf script
      bootconfig/tracing/ktest: Update ktest example for boot-time tracing


 Documentation/trace/boottime-trace.rst             |   85 +++++-
 kernel/trace/trace_boot.c                          |  301 ++++++++++++++++++++
 tools/bootconfig/scripts/bconf2ftrace.sh           |   97 ++++++
 tools/bootconfig/scripts/ftrace2bconf.sh           |   24 +-
 tools/bootconfig/scripts/xbc.sh                    |    4 
 .../ktest/examples/bootconfigs/boottrace.bconf     |   20 +
 .../ktest/examples/bootconfigs/verify-boottrace.sh |    2 
 7 files changed, 508 insertions(+), 25 deletions(-)

-- 
Masami Hiramatsu (Linaro) <mhiramat@kernel.org>

[PATCH v2 01/10] tracing/boot: Fix a hist trigger dependency for boot time tracing

[Masami Hiramatsu]

Fixes a build error when CONFIG_HIST_TRIGGERS=n with boot-time
tracing. Since the trigger_process_regex() is defined only
when CONFIG_HIST_TRIGGERS=y, if it is disabled, the 'actions'
event option also must be disabled.

Fixes: 81a59555ff15 ("tracing/boot: Add per-event settings")
Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Changes in v3:
  - Use IS_ENABLED() instead of #ifdef and show an error if
    CONFIG_HIST_TRIGGERS is not set but per-event actions
    specified.
---
 kernel/trace/trace_boot.c |   15 +++++++++------
 1 file changed, 9 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 94ef2d099e32..d713714cba67 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -205,12 +205,15 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 			pr_err("Failed to apply filter: %s\n", buf);
 	}
 
-	xbc_node_for_each_array_value(enode, "actions", anode, p) {
-		if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
-			pr_err("action string is too long: %s\n", p);
-		else if (trigger_process_regex(file, buf) < 0)
-			pr_err("Failed to apply an action: %s\n", buf);
-	}
+	if (IS_ENABLED(CONFIG_HIST_TRIGGERS)) {
+		xbc_node_for_each_array_value(enode, "actions", anode, p) {
+			if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
+				pr_err("action string is too long: %s\n", p);
+			else if (trigger_process_regex(file, buf) < 0)
+				pr_err("Failed to apply an action: %s\n", buf);
+		}
+	} else if (xbc_node_find_value(enode, "actions", NULL))
+		pr_err("Failed to apply event actions because CONFIG_HIST_TRIGGERS is not set.\n");
 
 	if (xbc_node_find_value(enode, "enable", NULL)) {
 		if (trace_event_enable_disable(file, 1, 0) < 0)

[PATCH v2 02/10] tracing/boot: Add per-event histogram action options

[Masami Hiramatsu]

Add a hist-trigger action syntax support to boot-time tracing.
Currently, boot-time tracing supports per-event actions as option
strings. However, for the histogram action, it has a special syntax
and usually needs a long action definition.
To make it readable and fit to the bootconfig syntax, this introduces
a new options for histogram.

Here are the histogram action options for boot-time tracing.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
     keys = <KEY>[,...]
     values = <VAL>[,...]
     sort = <SORT-KEY>[,...]
     size = <ENTRIES>
     name = <HISTNAME>
     var { <VAR> = <EXPR> ... }
     pause|continue|clear
     onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
     onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
     filter = <FILTER>
}

Where <ACTION> is one of below;

     trace = <EVENT>, <ARG1>[, ...]
     save = <ARG1>[, ...]
     snapshot

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Changes in v3:
   - Allow var expression includes spaces, since it is natural that
     user write an expression with space in bootconfig.
     (e.g. "var.lat = common_timestamp.usecs - $ts0")
 Changes in v2:
   - Cleanup code to add ':' as a prefix for each element
     instead of fixup the last ':'.
   - Fix syntax typo for handler actions.
   - Make pause|continue|clear mutual exclusive.
   - Add __printf() attribute to the append_printf().
---
 kernel/trace/trace_boot.c |  231 +++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 231 insertions(+)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index d713714cba67..763f8a7b7e1b 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -171,6 +171,231 @@ trace_boot_add_synth_event(struct xbc_node *node, const char *event)
 }
 #endif
 
+#ifdef CONFIG_HIST_TRIGGERS
+static int __init __printf(3, 4)
+append_printf(char **bufp, char *end, const char *fmt, ...)
+{
+	va_list args;
+	int ret;
+
+	if (*bufp == end)
+		return -ENOSPC;
+
+	va_start(args, fmt);
+	ret = vsnprintf(*bufp, end - *bufp, fmt, args);
+	if (ret < end - *bufp) {
+		*bufp += ret;
+	} else {
+		*bufp = end;
+		ret = -ERANGE;
+	}
+	va_end(args);
+
+	return ret;
+}
+
+static int __init
+append_str_nospace(char **bufp, char *end, char *str)
+{
+	char *p = *bufp;
+	int len;
+
+	while (p < end - 1 && *str != '\0') {
+		if (!isspace(*str))
+			*(p++) = *str;
+		str++;
+	}
+	*p = '\0';
+	if (p == end - 1) {
+		*bufp = end;
+		return -ENOSPC;
+	}
+	len = p - *bufp;
+	*bufp = p;
+	return (int)len;
+}
+
+static int __init
+trace_boot_hist_add_array(struct xbc_node *hnode, char **bufp,
+			  char *end, const char *key)
+{
+	struct xbc_node *knode, *anode;
+	const char *p;
+	char sep;
+
+	knode = xbc_node_find_child(hnode, key);
+	if (knode) {
+		anode = xbc_node_get_child(knode);
+		if (!anode) {
+			pr_err("hist.%s requires value(s).\n", key);
+			return -EINVAL;
+		}
+
+		append_printf(bufp, end, ":%s", key);
+		sep = '=';
+		xbc_array_for_each_value(anode, p) {
+			append_printf(bufp, end, "%c%s", sep, p);
+			if (sep == '=')
+				sep = ',';
+		}
+	} else
+		return -ENOENT;
+
+	return 0;
+}
+
+static int __init
+trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
+			    char *end, const char *param)
+{
+	struct xbc_node *knode, *anode;
+	const char *p;
+	char sep;
+
+	/* Compose 'handler' parameter */
+	p = xbc_node_find_value(hnode, param, NULL);
+	if (!p) {
+		pr_err("hist.%s requires '%s' option.\n",
+		       xbc_node_get_data(hnode), param);
+		return -EINVAL;
+	}
+	append_printf(bufp, end, ":%s(%s)", xbc_node_get_data(hnode), p);
+
+	/* Compose 'action' parameter */
+	knode = xbc_node_find_child(hnode, "trace");
+	if (!knode)
+		knode = xbc_node_find_child(hnode, "save");
+
+	if (knode) {
+		anode = xbc_node_get_child(knode);
+		if (!anode || !xbc_node_is_value(anode)) {
+			pr_err("hist.%s.%s requires value(s).\n",
+			       xbc_node_get_data(hnode),
+			       xbc_node_get_data(knode));
+			return -EINVAL;
+		}
+
+		append_printf(bufp, end, ".%s", xbc_node_get_data(knode));
+		sep = '(';
+		xbc_array_for_each_value(anode, p) {
+			append_printf(bufp, end, "%c%s", sep, p);
+			if (sep == '(')
+				sep = ',';
+		}
+		append_printf(bufp, end, ")");
+	} else if (xbc_node_find_child(hnode, "snapshot")) {
+		append_printf(bufp, end, ".snapshot()");
+	} else {
+		pr_err("hist.%s requires an action.\n",
+		       xbc_node_get_data(hnode));
+		return -EINVAL;
+	}
+
+	return 0;
+}
+
+/*
+ * Histogram boottime tracing syntax.
+ *
+ * ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
+ *	keys = <KEY>[,...]
+ *	values = <VAL>[,...]
+ *	sort = <SORT-KEY>[,...]
+ *	size = <ENTRIES>
+ *	name = <HISTNAME>
+ *	var { <VAR> = <EXPR> ... }
+ *	pause|continue|clear
+ *	onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
+ *	onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
+ *	filter = <FILTER>
+ * }
+ *
+ * Where <ACTION> are;
+ *
+ *	trace = <EVENT>, <ARG1>[, ...]
+ *	save = <ARG1>[, ...]
+ *	snapshot
+ */
+static int __init
+trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
+{
+	struct xbc_node *node, *knode;
+	char *end = buf + size;
+	const char *p;
+	int ret = 0;
+
+	append_printf(&buf, end, "hist");
+
+	ret = trace_boot_hist_add_array(hnode, &buf, end, "keys");
+	if (ret < 0) {
+		if (ret == -ENOENT)
+			pr_err("hist requires keys.\n");
+		return -EINVAL;
+	}
+
+	ret = trace_boot_hist_add_array(hnode, &buf, end, "values");
+	if (ret == -EINVAL)
+		return ret;
+	ret = trace_boot_hist_add_array(hnode, &buf, end, "sort");
+	if (ret == -EINVAL)
+		return ret;
+
+	p = xbc_node_find_value(hnode, "size", NULL);
+	if (p)
+		append_printf(&buf, end, ":size=%s", p);
+
+	p = xbc_node_find_value(hnode, "name", NULL);
+	if (p)
+		append_printf(&buf, end, ":name=%s", p);
+
+	node = xbc_node_find_child(hnode, "var");
+	if (node) {
+		xbc_node_for_each_key_value(node, knode, p) {
+			/* Expression must not include spaces. */
+			append_printf(&buf, end, ":%s=",
+				      xbc_node_get_data(knode));
+			append_str_nospace(&buf, end, p);
+		}
+	}
+
+	/* Histogram control attributes (mutual exclusive) */
+	if (xbc_node_find_child(hnode, "pause"))
+		append_printf(&buf, end, ":pause");
+	else if (xbc_node_find_child(hnode, "continue"))
+		append_printf(&buf, end, ":continue");
+	else if (xbc_node_find_child(hnode, "clear"))
+		append_printf(&buf, end, ":clear");
+
+	/* Histogram handler and actions */
+	node = xbc_node_find_child(hnode, "onmax");
+	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
+		return -EINVAL;
+	node = xbc_node_find_child(hnode, "onchange");
+	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
+		return -EINVAL;
+	node = xbc_node_find_child(hnode, "onmatch");
+	if (node && trace_boot_hist_add_handler(node, &buf, end, "event") < 0)
+		return -EINVAL;
+
+	p = xbc_node_find_value(hnode, "filter", NULL);
+	if (p)
+		append_printf(&buf, end, " if %s", p);
+
+	if (buf == end) {
+		pr_err("hist exceeds the max command length.\n");
+		return -E2BIG;
+	}
+
+	return 0;
+}
+#else
+static int __init
+trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
+{
+	return -EOPNOTSUPP;
+}
+#endif
+
 static void __init
 trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 			  struct xbc_node *enode)
@@ -212,6 +437,12 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 			else if (trigger_process_regex(file, buf) < 0)
 				pr_err("Failed to apply an action: %s\n", buf);
 		}
+		anode = xbc_node_find_child(enode, "hist");
+		if (anode &&
+		    trace_boot_compose_hist_cmd(anode, buf, ARRAY_SIZE(buf)) == 0) {
+			if (trigger_process_regex(file, buf) < 0)
+				pr_err("Failed to apply hist trigger: %s\n", buf);
+		}
 	} else if (xbc_node_find_value(enode, "actions", NULL))
 		pr_err("Failed to apply event actions because CONFIG_HIST_TRIGGERS is not set.\n");
 

[PATCH v2 03/10] tracing/boot: Support multiple handlers for per-event histogram

[Masami Hiramatsu]

Support multiple handlers for per-event histogram in boot-time tracing.
Since the histogram can register multiple same handler-actions with
different parameters, this expands the syntax to support such cases.

With this update, the 'onmax', 'onchange' and 'onmatch' handler subkeys
under per-event histogram option will take a number subkeys optionally
as below. (see [.N])

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
     onmax|onchange[.N] { var = <VAR>; <ACTION> [= <PARAM>] }
     onmatch[.N] { event = <EVENT>; <ACTION> [= <PARAM>] }
}

The 'N' must be a digit (or digit started word).

Thus user can add several handler-actions to the histogram,
for example,

ftrace.event.SOMEGROUP.SOMEEVENT.hist {
   keys = SOME_ID; lat = common_timestamp.usecs-$ts0
   onmatch.1 {
	event = GROUP1.STARTEVENT1
	trace = latency_event, SOME_ID, $lat
   }
   onmatch.2 {
	event = GROUP2.STARTEVENT2
	trace = latency_event, SOME_ID, $lat
   }
}

Then, it can trace the elapsed time from GROUP1.STARTEVENT1 to
SOMEGROUP.SOMEEVENT, and from GROUP2.STARTEVENT2 to
SOMEGROUP.SOMEEVENT with SOME_ID key.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/trace/trace_boot.c |   43 +++++++++++++++++++++++++++++++++++--------
 1 file changed, 35 insertions(+), 8 deletions(-)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 763f8a7b7e1b..8ee04ceb12ac 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -245,8 +245,9 @@ trace_boot_hist_add_array(struct xbc_node *hnode, char **bufp,
 }
 
 static int __init
-trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
-			    char *end, const char *param)
+trace_boot_hist_add_one_handler(struct xbc_node *hnode, char **bufp,
+				char *end, const char *handler,
+				const char *param)
 {
 	struct xbc_node *knode, *anode;
 	const char *p;
@@ -259,7 +260,7 @@ trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
 		       xbc_node_get_data(hnode), param);
 		return -EINVAL;
 	}
-	append_printf(bufp, end, ":%s(%s)", xbc_node_get_data(hnode), p);
+	append_printf(bufp, end, ":%s(%s)", handler, p);
 
 	/* Compose 'action' parameter */
 	knode = xbc_node_find_child(hnode, "trace");
@@ -294,6 +295,32 @@ trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
 	return 0;
 }
 
+static int __init
+trace_boot_hist_add_handlers(struct xbc_node *hnode, char **bufp,
+			     char *end, const char *param)
+{
+	struct xbc_node *node;
+	const char *p, *handler;
+	int ret;
+
+	handler = xbc_node_get_data(hnode);
+
+	xbc_node_for_each_subkey(hnode, node) {
+		p = xbc_node_get_data(node);
+		if (!isdigit(p[0]))
+			continue;
+		/* All digit started node should be instances. */
+		ret = trace_boot_hist_add_one_handler(node, bufp, end, handler, param);
+		if (ret < 0)
+			break;
+	}
+
+	if (xbc_node_find_child(hnode, param))
+		ret = trace_boot_hist_add_one_handler(hnode, bufp, end, handler, param);
+
+	return ret;
+}
+
 /*
  * Histogram boottime tracing syntax.
  *
@@ -305,8 +332,8 @@ trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
  *	name = <HISTNAME>
  *	var { <VAR> = <EXPR> ... }
  *	pause|continue|clear
- *	onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
- *	onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
+ *	onmax|onchange[.N] { var = <VAR>; <ACTION> [= <PARAM>] }
+ *	onmatch[.N] { event = <EVENT>; <ACTION> [= <PARAM>] }
  *	filter = <FILTER>
  * }
  *
@@ -368,13 +395,13 @@ trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
 
 	/* Histogram handler and actions */
 	node = xbc_node_find_child(hnode, "onmax");
-	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
+	if (node && trace_boot_hist_add_handlers(node, &buf, end, "var") < 0)
 		return -EINVAL;
 	node = xbc_node_find_child(hnode, "onchange");
-	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
+	if (node && trace_boot_hist_add_handlers(node, &buf, end, "var") < 0)
 		return -EINVAL;
 	node = xbc_node_find_child(hnode, "onmatch");
-	if (node && trace_boot_hist_add_handler(node, &buf, end, "event") < 0)
+	if (node && trace_boot_hist_add_handlers(node, &buf, end, "event") < 0)
 		return -EINVAL;
 
 	p = xbc_node_find_value(hnode, "filter", NULL);

[PATCH v2 04/10] tracing/boot: Support multiple histograms for each event

[Masami Hiramatsu]

Add multiple histograms support for each event. This allows
user to set multiple histograms to an event.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist[.N] {
...
}

The 'N' is a digit started string and it can be omitted
for the default histogram.

For example, multiple hist triggers example in the
Documentation/trace/histogram.rst can be written as below;

ftrace.event.net.netif_receive_skb.hist {
	1 {
		keys = skbaddr.hex
		values = len
		filter = len < 0
	}
	2 {
		keys = skbaddr.hex
		values = len
		filter = len > 4096
	}
	3 {
		keys = skbaddr.hex
		values = len
		filter = len == 256
	}
	4 {
		keys = skbaddr.hex
		values = len
	}
	5 {
		keys = len
		values = common_preempt_count
	}
}

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Changes in v3:
  - Fixes a build error when CONFIG_HIST_TRIGGERS=n.
---
 kernel/trace/trace_boot.c |   41 ++++++++++++++++++++++++++++++++---------
 1 file changed, 32 insertions(+), 9 deletions(-)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 8ee04ceb12ac..69558f149620 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -324,7 +324,7 @@ trace_boot_hist_add_handlers(struct xbc_node *hnode, char **bufp,
 /*
  * Histogram boottime tracing syntax.
  *
- * ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
+ * ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist[.N] {
  *	keys = <KEY>[,...]
  *	values = <VAL>[,...]
  *	sort = <SORT-KEY>[,...]
@@ -415,11 +415,37 @@ trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
 
 	return 0;
 }
+
+static void __init
+trace_boot_init_histograms(struct trace_event_file *file,
+			   struct xbc_node *hnode, char *buf, size_t size)
+{
+	struct xbc_node *node;
+	const char *p;
+
+	xbc_node_for_each_subkey(hnode, node) {
+		p = xbc_node_get_data(node);
+		if (!isdigit(p[0]))
+			continue;
+		/* All digit started node should be instances. */
+		if (trace_boot_compose_hist_cmd(node, buf, size) == 0) {
+			if (trigger_process_regex(file, buf) < 0)
+				pr_err("Failed to apply hist trigger: %s\n", buf);
+		}
+	}
+
+	if (xbc_node_find_child(hnode, "keys")) {
+		if (trace_boot_compose_hist_cmd(hnode, buf, size) == 0)
+			if (trigger_process_regex(file, buf) < 0)
+				pr_err("Failed to apply hist trigger: %s\n", buf);
+	}
+}
 #else
-static int __init
-trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
+static void __init
+trace_boot_init_histograms(struct trace_event_file *file,
+			   struct xbc_node *hnode, char *buf, size_t size)
 {
-	return -EOPNOTSUPP;
+	/* do nothing */
 }
 #endif
 
@@ -465,11 +491,8 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 				pr_err("Failed to apply an action: %s\n", buf);
 		}
 		anode = xbc_node_find_child(enode, "hist");
-		if (anode &&
-		    trace_boot_compose_hist_cmd(anode, buf, ARRAY_SIZE(buf)) == 0) {
-			if (trigger_process_regex(file, buf) < 0)
-				pr_err("Failed to apply hist trigger: %s\n", buf);
-		}
+		if (anode)
+			trace_boot_init_histograms(file, anode, buf, ARRAY_SIZE(buf));
 	} else if (xbc_node_find_value(enode, "actions", NULL))
 		pr_err("Failed to apply event actions because CONFIG_HIST_TRIGGERS is not set.\n");
 

[PATCH v2 05/10] tracing/boot: Show correct histogram error command

[Masami Hiramatsu]

Since trigger_process_regex() modifies given trigger actions
while parsing, the error message couldn't show what command
was passed to the trigger_process_regex() when it returns
an error.

To fix that, show the backed up trigger action command
instead of parsed buffer.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/trace/trace_boot.c |   11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 69558f149620..cfe4a415b468 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -422,6 +422,7 @@ trace_boot_init_histograms(struct trace_event_file *file,
 {
 	struct xbc_node *node;
 	const char *p;
+	char *tmp;
 
 	xbc_node_for_each_subkey(hnode, node) {
 		p = xbc_node_get_data(node);
@@ -429,15 +430,19 @@ trace_boot_init_histograms(struct trace_event_file *file,
 			continue;
 		/* All digit started node should be instances. */
 		if (trace_boot_compose_hist_cmd(node, buf, size) == 0) {
+			tmp = kstrdup(buf, GFP_KERNEL);
 			if (trigger_process_regex(file, buf) < 0)
-				pr_err("Failed to apply hist trigger: %s\n", buf);
+				pr_err("Failed to apply hist trigger: %s\n", tmp);
+			kfree(tmp);
 		}
 	}
 
 	if (xbc_node_find_child(hnode, "keys")) {
 		if (trace_boot_compose_hist_cmd(hnode, buf, size) == 0)
+			tmp = kstrdup(buf, GFP_KERNEL);
 			if (trigger_process_regex(file, buf) < 0)
-				pr_err("Failed to apply hist trigger: %s\n", buf);
+				pr_err("Failed to apply hist trigger: %s\n", tmp);
+			kfree(tmp);
 	}
 }
 #else
@@ -488,7 +493,7 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 			if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
 				pr_err("action string is too long: %s\n", p);
 			else if (trigger_process_regex(file, buf) < 0)
-				pr_err("Failed to apply an action: %s\n", buf);
+				pr_err("Failed to apply an action: %s\n", p);
 		}
 		anode = xbc_node_find_child(enode, "hist");
 		if (anode)

[PATCH v2 06/10] Documentation: tracing: Add histogram syntax to boot-time tracing

[Masami Hiramatsu]

Add the documentation about histogram syntax in boot-time tracing.
This will allow user to write the histogram setting in a structured
parameters.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 Changes in v2:
  - Update for the multiple histogram and the multiple handler.
---
 Documentation/trace/boottime-trace.rst |   85 ++++++++++++++++++++++++++++++--
 1 file changed, 80 insertions(+), 5 deletions(-)

diff --git a/Documentation/trace/boottime-trace.rst b/Documentation/trace/boottime-trace.rst
index 8053898cfeb4..6dcfbc64014d 100644
--- a/Documentation/trace/boottime-trace.rst
+++ b/Documentation/trace/boottime-trace.rst
@@ -125,6 +125,71 @@ Note that kprobe and synthetic event definitions can be written under
 instance node, but those are also visible from other instances. So please
 take care for event name conflict.
 
+Ftrace Histogram Options
+------------------------
+
+Since it is too long to write a histogram action as a string for per-event
+action option, there are tree-style options under per-event 'hist' subkey
+for the histogram actions. For the detail of the each parameter,
+please read the event histogram document [3]_.
+
+.. [3] See :ref:`Documentation/trace/histogram.rst <histogram>`
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]keys = KEY1[, KEY2[...]]
+  Set histogram key parameters. (Mandatory)
+  The 'N' is a digit string for the multiple histogram. You can omit it
+  if there is one histogram on the event.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]values = VAL1[, VAL2[...]]
+  Set histogram value parameters.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]sort = SORT1[, SORT2[...]]
+  Set histogram sort parameter options.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]size = NR_ENTRIES
+  Set histogram size (number of entries).
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]name = NAME
+  Set histogram name.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]var.VARIABLE = EXPR
+  Define a new VARIABLE by EXPR expression.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<pause|continue|clear>
+  Set histogram control parameter. You can set one of them.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmatch.[M.]event = GROUP.EVENT
+  Set histogram 'onmatch' handler matching event parameter.
+  The 'M' is a digit string for the multiple 'onmatch' handler. You can omit it
+  if there is one 'onmatch' handler on this histogram.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmatch.[M.]trace = EVENT[, ARG1[...]]
+  Set histogram 'trace' action for 'onmatch'.
+  EVENT must be a synthetic event name, and ARG1... are parameters
+  for that event. Mandatory if 'onmatch.event' option is set.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmax.[M.]var = VAR
+  Set histogram 'onmax' handler variable parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onchange.[M.]var = VAR
+  Set histogram 'onchange' handler variable parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<onmax|onchange>.[M.]save = ARG1[, ARG2[...]]
+  Set histogram 'save' action parameters for 'onmax' or 'onchange' handler.
+  This option or below 'snapshot' option is mandatory if 'onmax.var' or
+  'onchange.var' option is set.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<onmax|onchange>.[M.]snapshot
+  Set histogram 'snapshot' action for 'onmax' or 'onchange' handler.
+  This option or above 'save' option is mandatory if 'onmax.var' or
+  'onchange.var' option is set.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.filter = FILTER_EXPR
+  Set histogram filter expression. You don't need 'if' in the FILTER_EXPR.
+
+Note that this 'hist' option can conflict with the per-event 'actions'
+option if the 'actions' option has a histogram action.
+
 
 When to Start
 =============
@@ -159,13 +224,23 @@ below::
         }
         synthetic.initcall_latency {
                 fields = "unsigned long func", "u64 lat"
-                actions = "hist:keys=func.sym,lat:vals=lat:sort=lat"
+                hist {
+                        keys = func.sym, lat
+                        values = lat
+                        sort = lat
+                }
         }
-        initcall.initcall_start {
-                actions = "hist:keys=func:ts0=common_timestamp.usecs"
+        initcall.initcall_start.hist {
+                keys = func
+                var.ts0 = common_timestamp.usecs
         }
-        initcall.initcall_finish {
-                actions = "hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).initcall_latency(func,$lat)"
+        initcall.initcall_finish.hist {
+                keys = func
+                var.lat = common_timestamp.usecs - $ts0
+                onmatch {
+                        event = initcall.initcall_start
+                        trace = initcall_latency, func, $lat
+                }
         }
   }
 

[PATCH v2 07/10] tools/bootconfig: Support per-group/all event enabling option

[Masami Hiramatsu]

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 tools/bootconfig/scripts/bconf2ftrace.sh |   13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/tools/bootconfig/scripts/bconf2ftrace.sh b/tools/bootconfig/scripts/bconf2ftrace.sh
index feb30c2c7881..651049c782c0 100755
--- a/tools/bootconfig/scripts/bconf2ftrace.sh
+++ b/tools/bootconfig/scripts/bconf2ftrace.sh
@@ -101,6 +101,12 @@ setup_event() { # prefix group event [instance]
 	else
 		eventdir="$TRACEFS/events/$2/$3"
 	fi
+	# group enable
+	if [ "$3" = "enable" ]; then
+		run_cmd "echo 1 > ${eventdir}"
+		return
+	fi
+
 	case $2 in
 	kprobes)
 		xbc_get_val ${branch}.probes | while read line; do
@@ -127,6 +133,13 @@ setup_events() { # prefix("ftrace" or "ftrace.instance.INSTANCE") [instance]
 			setup_event $prefix ${grpev%.*} ${grpev#*.} $2
 		done
 	fi
+	if xbc_has_branch ${1}.event.enable; then
+		if [ "$2" ]; then
+			run_cmd "echo 1 > $TRACEFS/instances/$2/events/enable"
+		else
+			run_cmd "echo 1 > $TRACEFS/events/enable"
+		fi
+	fi
 }
 
 size2kb() { # size[KB|MB]

[PATCH v2 08/10] tools/bootconfig: Add histogram syntax support to bconf2ftrace.sh

[Masami Hiramatsu]

Add histogram syntax support to bconf2ftrace.sh script.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 tools/bootconfig/scripts/bconf2ftrace.sh |   84 ++++++++++++++++++++++++++++++
 tools/bootconfig/scripts/xbc.sh          |    4 +
 2 files changed, 86 insertions(+), 2 deletions(-)

diff --git a/tools/bootconfig/scripts/bconf2ftrace.sh b/tools/bootconfig/scripts/bconf2ftrace.sh
index 651049c782c0..43b65a199010 100755
--- a/tools/bootconfig/scripts/bconf2ftrace.sh
+++ b/tools/bootconfig/scripts/bconf2ftrace.sh
@@ -94,6 +94,88 @@ compose_synth() { # event_name branch
 	xbc_get_val $2 | while read field; do echo -n "$field; "; done
 }
 
+print_hist_array() { # prefix key
+	__sep="="
+	if xbc_has_key ${1}.${2}; then
+		echo -n ":$2"
+		xbc_get_val ${1}.${2} | while read field; do
+			echo -n "$__sep$field"; __sep=","
+		done
+	fi
+}
+
+print_hist_action_array() { # prefix key
+	__sep="("
+	echo -n ".$2"
+	xbc_get_val ${1}.${2} | while read field; do
+		echo -n "$__sep$field"; __sep=","
+	done
+	echo -n ")"
+}
+
+print_hist_one_action() { # prefix handler param
+	echo -n ":${2}("`xbc_get_val ${1}.${3}`")"
+	if xbc_has_key "${1}.trace"; then
+		print_hist_action_array ${1} "trace"
+	elif xbc_has_key "${1}.save"; then
+		print_hist_action_array ${1} "save"
+	elif xbc_has_key "${1}.snapshot"; then
+		echo -n ".snapshot()"
+	fi
+}
+
+print_hist_actions() { # prefix handler param
+	for __hdr in `xbc_subkeys ${1}.${2} 1 ".[0-9]"`; do
+		print_hist_one_action ${1}.${2}.$__hdr ${2} ${3}
+	done
+	if xbc_has_key ${1}.${2}.${3} ; then
+		print_hist_one_action ${1}.${2} ${2} ${3}
+	fi
+}
+
+print_one_histogram() { # prefix
+	echo -n "hist"
+	print_hist_array $1 "keys"
+	print_hist_array $1 "values"
+	print_hist_array $1 "sort"
+	if xbc_has_key "${1}.size"; then
+		echo -n ":size="`xbc_get_val ${1}.size`
+	fi
+	if xbc_has_key "${1}.name"; then
+		echo -n ":name="`xbc_get_val ${1}.name`
+	fi
+	for __var in `xbc_subkeys "${1}.var" 1`; do
+		echo -n ":$__var="`xbc_get_val ${1}.var.${__var}`
+	done
+	if xbc_has_key "${1}.pause"; then
+		echo -n ":pause"
+	elif xbc_has_key "${1}.continue"; then
+		echo -n ":continue"
+	elif xbc_has_key "${1}.clear"; then
+		echo -n ":clear"
+	fi
+	print_hist_actions ${1} "onmax" "var"
+	print_hist_actions ${1} "onchange" "var"
+	print_hist_actions ${1} "onmatch" "event"
+
+	if xbc_has_key "${1}.filter"; then
+		echo -n " if "`xbc_get_val ${1}.filter`
+	fi
+}
+
+setup_one_histogram() { # prefix trigger-file
+	run_cmd "echo '`print_one_histogram ${1}`' >> ${2}"
+}
+
+setup_histograms() { # prefix trigger-file
+	for __hist in `xbc_subkeys ${1} 1 ".[0-9]"`; do
+		setup_one_histogram ${1}.$__hist ${2}
+	done
+	if xbc_has_key ${1}.keys; then
+		setup_one_histogram ${1} ${2}
+	fi
+}
+
 setup_event() { # prefix group event [instance]
 	branch=$1.$2.$3
 	if [ "$4" ]; then
@@ -121,6 +203,8 @@ setup_event() { # prefix group event [instance]
 	set_value_of ${branch}.filter ${eventdir}/filter
 	set_array_of ${branch}.actions ${eventdir}/trigger
 
+	setup_histograms ${branch}.hist ${eventdir}/trigger
+
 	if xbc_has_key ${branch}.enable; then
 		run_cmd "echo 1 > ${eventdir}/enable"
 	fi
diff --git a/tools/bootconfig/scripts/xbc.sh b/tools/bootconfig/scripts/xbc.sh
index b8c84e654556..1f0ebf50dd2d 100644
--- a/tools/bootconfig/scripts/xbc.sh
+++ b/tools/bootconfig/scripts/xbc.sh
@@ -49,8 +49,8 @@ xbc_has_branch() { # prefix-key
 	grep -q "^$1" $XBC_TMPFILE
 }
 
-xbc_subkeys() { # prefix-key depth
+xbc_subkeys() { # prefix-key depth [subkey-pattern]
 	__keys=`echo $1 | sed "s/\./ /g"`
 	__s=`nr_args $__keys`
-	grep "^$1" $XBC_TMPFILE | cut -d= -f1| cut -d. -f$((__s + 1))-$((__s + $2)) | uniq
+	grep "^$1$3" $XBC_TMPFILE | cut -d= -f1| cut -d. -f$((__s + 1))-$((__s + $2)) | uniq
 }

[PATCH v2 09/10] tools/bootconfig: Use per-group/all enable option in ftrace2bconf script

[Masami Hiramatsu]

Use per-group/all enable option instead of ftrace.events option.
This will make the bootconfig file more readable.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 tools/bootconfig/scripts/ftrace2bconf.sh |   24 ++++++++++++++++++------
 1 file changed, 18 insertions(+), 6 deletions(-)

diff --git a/tools/bootconfig/scripts/ftrace2bconf.sh b/tools/bootconfig/scripts/ftrace2bconf.sh
index a0c3bcc6da4f..fbaf07dc91bf 100755
--- a/tools/bootconfig/scripts/ftrace2bconf.sh
+++ b/tools/bootconfig/scripts/ftrace2bconf.sh
@@ -92,6 +92,10 @@ referred_vars() {
 	grep "^hist" $1/trigger | grep -o '$[a-zA-Z0-9]*'
 }
 
+event_is_enabled() { # enable-file
+	test -f $1 & grep -q "1" $1
+}
+
 per_event_options() { # event-dir
 	evdir=$1
 	# Check the special event which has no filter and no trigger
@@ -113,7 +117,9 @@ per_event_options() { # event-dir
 		emit_kv $PREFIX.event.$group.$event.actions += \'$action\'
 	done
 
-	# enable is not checked; this is done by set_event in the instance.
+	if [ $GROUP_ENABLED -eq 0 ] && event_is_enabled $evdir/enable; then
+		emit_kv $PREFIX.event.$group.$event.enable
+	fi
 	val=`cat $evdir/filter`
 	if [ "$val" != "none" ]; then
 		emit_kv $PREFIX.event.$group.$event.filter = "$val"
@@ -137,8 +143,19 @@ event_options() {
 		kprobe_event_options
 		synth_event_options
 	fi
+	ALL_ENABLED=0
+	if event_is_enabled $INSTANCE/events/enable; then
+		emit_kv $PREFIX.event.enable
+		ALL_ENABLED=1
+	fi
 	for group in `ls $INSTANCE/events/` ; do
 		[ ! -d $INSTANCE/events/$group ] && continue
+		GROUP_ENABLED=$ALL_ENABLED
+		if [ $ALL_ENABLED -eq 0 ] && \
+		   event_is_enabled $INSTANCE/events/$group/enable ;then
+			emit_kv $PREFIX.event.$group.enable
+			GROUP_ENABLED=1
+		fi
 		for event in `ls $INSTANCE/events/$group/` ;do
 			[ ! -d $INSTANCE/events/$group/$event ] && continue
 			per_event_options $INSTANCE/events/$group/$event
@@ -226,11 +243,6 @@ instance_options() { # [instance-name]
 		emit_kv $PREFIX.tracing_on = $val
 	fi
 
-	val=
-	for i in `cat $INSTANCE/set_event`; do
-		val="$val, $i"
-	done
-	[ "$val" ] && emit_kv $PREFIX.events = "${val#,}"
 	val=`cat $INSTANCE/current_tracer`
 	[ $val != nop ] && emit_kv $PREFIX.tracer = $val
 	if grep -qv "^#" $INSTANCE/set_ftrace_filter $INSTANCE/set_ftrace_notrace; then

[PATCH v2 10/10] bootconfig/tracing/ktest: Update ktest example for boot-time tracing

[Masami Hiramatsu]

Update ktest example for the boot-time tracing with histogram
options. Note that since the histogram option uses "trace()" action
instead of "EVENT()", this updates the matching pattern too.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 .../ktest/examples/bootconfigs/boottrace.bconf     |   20 +++++++++++++++-----
 .../ktest/examples/bootconfigs/verify-boottrace.sh |    2 +-
 2 files changed, 16 insertions(+), 6 deletions(-)

diff --git a/tools/testing/ktest/examples/bootconfigs/boottrace.bconf b/tools/testing/ktest/examples/bootconfigs/boottrace.bconf
index 9db64ec589d5..7aa706cccb3b 100644
--- a/tools/testing/ktest/examples/bootconfigs/boottrace.bconf
+++ b/tools/testing/ktest/examples/bootconfigs/boottrace.bconf
@@ -10,13 +10,23 @@ ftrace.event {
 	}
 	synthetic.initcall_latency {
 		fields = "unsigned long func", "u64 lat"
-		actions = "hist:keys=func.sym,lat:vals=lat:sort=lat"
+		hist {
+			keys = func.sym,lat
+			values = lat
+			sort = lat
+		}
 	}
-	initcall.initcall_start {
-		actions = "hist:keys=func:ts0=common_timestamp.usecs"
+	initcall.initcall_start.hist {
+		keys = func;
+		var.ts0 = common_timestamp.usecs
 	}
-	initcall.initcall_finish {
-		actions = "hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).initcall_latency(func,$lat)"
+	initcall.initcall_finish.hist {
+		keys = func
+		var.lat = common_timestamp.usecs - $ts0
+		onmatch {
+			event = initcall.initcall_start
+			trace = initcall_latency, func, $lat
+		}
 	}
 }
 
diff --git a/tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh b/tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh
index f271940ce7fb..233e95cfcf20 100755
--- a/tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh
+++ b/tools/testing/ktest/examples/bootconfigs/verify-boottrace.sh
@@ -58,7 +58,7 @@ compare_file_partial "events/synthetic/initcall_latency/enable" "0"
 compare_file_partial "events/initcall/initcall_start/trigger" "hist:keys=func:vals=hitcount:ts0=common_timestamp.usecs"
 compare_file_partial "events/initcall/initcall_start/enable" "1"
 
-compare_file_partial "events/initcall/initcall_finish/trigger" 'hist:keys=func:vals=hitcount:lat=common_timestamp.usecs-\$ts0:sort=hitcount:size=2048:clock=global:onmatch(initcall.initcall_start).initcall_latency(func,\$lat)'
+compare_file_partial "events/initcall/initcall_finish/trigger" 'hist:keys=func:vals=hitcount:lat=common_timestamp.usecs-\$ts0:sort=hitcount:size=2048:clock=global:onmatch(initcall.initcall_start).trace(initcall_latency,func,\$lat)'
 compare_file_partial "events/initcall/initcall_finish/enable" "1"
 
 compare_file "instances/foo/current_tracer" "function"

Re: [PATCH v2 02/10] tracing/boot: Add per-event histogram action options

[kernel test robot]

[-- Attachment #1: Type: text/plain, Size: 5580 bytes --]

Hi Masami,

I love your patch! Perhaps something to improve:

[auto build test WARNING on trace/for-next]
[also build test WARNING on linux/master linus/master v5.14-rc5 next-20210809]
[cannot apply to tip/perf/core]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch]

url:    https://github.com/0day-ci/linux/commits/Masami-Hiramatsu/tracing-boot-Add-histogram-syntax-support-in-boot-time-tracing/20210809-235246
base:   https://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git for-next
config: i386-randconfig-r014-20210809 (attached as .config)
compiler: gcc-9 (Debian 9.3.0-22) 9.3.0
reproduce (this is a W=1 build):
        # https://github.com/0day-ci/linux/commit/f9498294f1e13e2ee4a0a6bec385e74f6603d633
        git remote add linux-review https://github.com/0day-ci/linux
        git fetch --no-tags linux-review Masami-Hiramatsu/tracing-boot-Add-histogram-syntax-support-in-boot-time-tracing/20210809-235246
        git checkout f9498294f1e13e2ee4a0a6bec385e74f6603d633
        # save the attached .config to linux build tree
        make W=1 ARCH=i386 

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@intel.com>

All warnings (new ones prefixed by >>):

   kernel/trace/trace_boot.c: In function 'trace_boot_compose_hist_cmd':
>> kernel/trace/trace_boot.c:357:34: warning: passing argument 3 of 'append_str_nospace' discards 'const' qualifier from pointer target type [-Wdiscarded-qualifiers]
     357 |    append_str_nospace(&buf, end, p);
         |                                  ^
   kernel/trace/trace_boot.c:198:50: note: expected 'char *' but argument is of type 'const char *'
     198 | append_str_nospace(char **bufp, char *end, char *str)
         |                                            ~~~~~~^~~


vim +357 kernel/trace/trace_boot.c

   296	
   297	/*
   298	 * Histogram boottime tracing syntax.
   299	 *
   300	 * ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
   301	 *	keys = <KEY>[,...]
   302	 *	values = <VAL>[,...]
   303	 *	sort = <SORT-KEY>[,...]
   304	 *	size = <ENTRIES>
   305	 *	name = <HISTNAME>
   306	 *	var { <VAR> = <EXPR> ... }
   307	 *	pause|continue|clear
   308	 *	onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
   309	 *	onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
   310	 *	filter = <FILTER>
   311	 * }
   312	 *
   313	 * Where <ACTION> are;
   314	 *
   315	 *	trace = <EVENT>, <ARG1>[, ...]
   316	 *	save = <ARG1>[, ...]
   317	 *	snapshot
   318	 */
   319	static int __init
   320	trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
   321	{
   322		struct xbc_node *node, *knode;
   323		char *end = buf + size;
   324		const char *p;
   325		int ret = 0;
   326	
   327		append_printf(&buf, end, "hist");
   328	
   329		ret = trace_boot_hist_add_array(hnode, &buf, end, "keys");
   330		if (ret < 0) {
   331			if (ret == -ENOENT)
   332				pr_err("hist requires keys.\n");
   333			return -EINVAL;
   334		}
   335	
   336		ret = trace_boot_hist_add_array(hnode, &buf, end, "values");
   337		if (ret == -EINVAL)
   338			return ret;
   339		ret = trace_boot_hist_add_array(hnode, &buf, end, "sort");
   340		if (ret == -EINVAL)
   341			return ret;
   342	
   343		p = xbc_node_find_value(hnode, "size", NULL);
   344		if (p)
   345			append_printf(&buf, end, ":size=%s", p);
   346	
   347		p = xbc_node_find_value(hnode, "name", NULL);
   348		if (p)
   349			append_printf(&buf, end, ":name=%s", p);
   350	
   351		node = xbc_node_find_child(hnode, "var");
   352		if (node) {
   353			xbc_node_for_each_key_value(node, knode, p) {
   354				/* Expression must not include spaces. */
   355				append_printf(&buf, end, ":%s=",
   356					      xbc_node_get_data(knode));
 > 357				append_str_nospace(&buf, end, p);
   358			}
   359		}
   360	
   361		/* Histogram control attributes (mutual exclusive) */
   362		if (xbc_node_find_child(hnode, "pause"))
   363			append_printf(&buf, end, ":pause");
   364		else if (xbc_node_find_child(hnode, "continue"))
   365			append_printf(&buf, end, ":continue");
   366		else if (xbc_node_find_child(hnode, "clear"))
   367			append_printf(&buf, end, ":clear");
   368	
   369		/* Histogram handler and actions */
   370		node = xbc_node_find_child(hnode, "onmax");
   371		if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
   372			return -EINVAL;
   373		node = xbc_node_find_child(hnode, "onchange");
   374		if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
   375			return -EINVAL;
   376		node = xbc_node_find_child(hnode, "onmatch");
   377		if (node && trace_boot_hist_add_handler(node, &buf, end, "event") < 0)
   378			return -EINVAL;
   379	
   380		p = xbc_node_find_value(hnode, "filter", NULL);
   381		if (p)
   382			append_printf(&buf, end, " if %s", p);
   383	
   384		if (buf == end) {
   385			pr_err("hist exceeds the max command length.\n");
   386			return -E2BIG;
   387		}
   388	
   389		return 0;
   390	}
   391	#else
   392	static int __init
   393	trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
   394	{
   395		return -EOPNOTSUPP;
   396	}
   397	#endif
   398	

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@lists.01.org

[-- Attachment #2: config.gz --]
[-- Type: application/gzip, Size: 35744 bytes --]

Re: [PATCH v2 00/10] tracing/boot: Add histogram syntax support in boot-time tracing

[Masami Hiramatsu]

Oops, I forgot to update the title. This is v3.

On Tue, 10 Aug 2021 00:47:49 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hi,
> 
> Here is the 3rd version of boot-time tracing to add histogram
> syntax extension with a bugfix related hist-trigger.
> 
> In this version, I updated the first bugfix to use IS_ENABLED()
> and show error if CONFIG_HIST_TRIGGERS=n ([1/10]), allow the spaces
> in the variable expressions ([2/10]), and update ktest bootconfig
> testcase ([10/10]).
> 
> 
> 'Histogram' options
> -------------------
> Currently, the boot-time tracing only supports per-event actions
> for setting trigger actions. This is enough for short actions
> like 'traceon', 'traceoff', 'snapshot' etc. However, it is not good
> for the 'hist' trigger action because it is usually too long to write
> it in a single string especially if it has an 'onmatch' action.
> 
> Here is the new syntax.
> 
>     ftrace[.instance.INSTANCE].event.GROUP.EVENT.hist[.N] {
>          keys = <KEY>[,...]
>          values = <VAL>[,...]
>          sort = <SORT-KEY>[,...]
>          size = <ENTRIES>
>          name = <HISTNAME>
>          var { <VAR> = <EXPR> ... }
>          pause|continue|clear
>          onmax|onchange[.M] { var = <VAR>, <ACTION> [= <PARAM>] }
>          onmatch[.M] { event = <EVENT>, <ACTION> [= <PARAM>] }
>          filter = <FILTER>
>     }
>     
> Where <ACTION> is one of below;
>     
>     trace = <EVENT>, <ARG1>[, ...]
>     save = <ARG1>[, ...]
>     snapshot
> 
> And "N" and "M" are digit started strings for multiple histograms
> and actions.
> 
> For example,
> 
> initcall.initcall_finish.actions =
> "hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(initcall.initcall_start).trace(initcall_latency,func,$lat)"
> 
> This can be written as below;
> 
> initcall.initcall_finish.hist {
>     keys = func
>     var.lat = common_timestamp.usecs-$ts0
>     onmatch {
>         event = initcall.initcall_start
>         trace = initcall_latency, func, $lat
>     }
> }
> 
> Also, you can add comments for each options.
> 
> 
> Thank you,
> 
> ---
> 
> Masami Hiramatsu (10):
>       tracing/boot: Fix a hist trigger dependency for boot time tracing
>       tracing/boot: Add per-event histogram action options
>       tracing/boot: Support multiple handlers for per-event histogram
>       tracing/boot: Support multiple histograms for each event
>       tracing/boot: Show correct histogram error command
>       Documentation: tracing: Add histogram syntax to boot-time tracing
>       tools/bootconfig: Support per-group/all event enabling option
>       tools/bootconfig: Add histogram syntax support to bconf2ftrace.sh
>       tools/bootconfig: Use per-group/all enable option in ftrace2bconf script
>       bootconfig/tracing/ktest: Update ktest example for boot-time tracing
> 
> 
>  Documentation/trace/boottime-trace.rst             |   85 +++++-
>  kernel/trace/trace_boot.c                          |  301 ++++++++++++++++++++
>  tools/bootconfig/scripts/bconf2ftrace.sh           |   97 ++++++
>  tools/bootconfig/scripts/ftrace2bconf.sh           |   24 +-
>  tools/bootconfig/scripts/xbc.sh                    |    4 
>  .../ktest/examples/bootconfigs/boottrace.bconf     |   20 +
>  .../ktest/examples/bootconfigs/verify-boottrace.sh |    2 
>  7 files changed, 508 insertions(+), 25 deletions(-)
> 
> -- 
> Masami Hiramatsu (Linaro) <mhiramat@kernel.org>


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v2 02/10] tracing/boot: Add per-event histogram action options

[Masami Hiramatsu]

On Tue, 10 Aug 2021 00:48:04 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Add a hist-trigger action syntax support to boot-time tracing.
> Currently, boot-time tracing supports per-event actions as option
> strings. However, for the histogram action, it has a special syntax
> and usually needs a long action definition.
> To make it readable and fit to the bootconfig syntax, this introduces
> a new options for histogram.
> 
> Here are the histogram action options for boot-time tracing.
> 
> ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
>      keys = <KEY>[,...]
>      values = <VAL>[,...]
>      sort = <SORT-KEY>[,...]
>      size = <ENTRIES>
>      name = <HISTNAME>
>      var { <VAR> = <EXPR> ... }
>      pause|continue|clear
>      onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
>      onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
>      filter = <FILTER>
> }
> 
> Where <ACTION> is one of below;
> 
>      trace = <EVENT>, <ARG1>[, ...]
>      save = <ARG1>[, ...]
>      snapshot
> 
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  Changes in v3:
>    - Allow var expression includes spaces, since it is natural that
>      user write an expression with space in bootconfig.
>      (e.g. "var.lat = common_timestamp.usecs - $ts0")
>  Changes in v2:
>    - Cleanup code to add ':' as a prefix for each element
>      instead of fixup the last ':'.
>    - Fix syntax typo for handler actions.
>    - Make pause|continue|clear mutual exclusive.
>    - Add __printf() attribute to the append_printf().
> ---
>  kernel/trace/trace_boot.c |  231 +++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 231 insertions(+)
> 
> diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
> index d713714cba67..763f8a7b7e1b 100644
> --- a/kernel/trace/trace_boot.c
> +++ b/kernel/trace/trace_boot.c
> @@ -171,6 +171,231 @@ trace_boot_add_synth_event(struct xbc_node *node, const char *event)
>  }
>  #endif
>  
> +#ifdef CONFIG_HIST_TRIGGERS
> +static int __init __printf(3, 4)
> +append_printf(char **bufp, char *end, const char *fmt, ...)
> +{
> +	va_list args;
> +	int ret;
> +
> +	if (*bufp == end)
> +		return -ENOSPC;
> +
> +	va_start(args, fmt);
> +	ret = vsnprintf(*bufp, end - *bufp, fmt, args);
> +	if (ret < end - *bufp) {
> +		*bufp += ret;
> +	} else {
> +		*bufp = end;
> +		ret = -ERANGE;
> +	}
> +	va_end(args);
> +
> +	return ret;
> +}
> +
> +static int __init
> +append_str_nospace(char **bufp, char *end, char *str)

Kbuild bot reported that I missed 'const' for the @str. Indeed, it's correct.

Let me update the series.

Thank you,

> +{
> +	char *p = *bufp;
> +	int len;
> +
> +	while (p < end - 1 && *str != '\0') {
> +		if (!isspace(*str))
> +			*(p++) = *str;
> +		str++;
> +	}
> +	*p = '\0';
> +	if (p == end - 1) {
> +		*bufp = end;
> +		return -ENOSPC;
> +	}
> +	len = p - *bufp;
> +	*bufp = p;
> +	return (int)len;
> +}
> +
> +static int __init
> +trace_boot_hist_add_array(struct xbc_node *hnode, char **bufp,
> +			  char *end, const char *key)
> +{
> +	struct xbc_node *knode, *anode;
> +	const char *p;
> +	char sep;
> +
> +	knode = xbc_node_find_child(hnode, key);
> +	if (knode) {
> +		anode = xbc_node_get_child(knode);
> +		if (!anode) {
> +			pr_err("hist.%s requires value(s).\n", key);
> +			return -EINVAL;
> +		}
> +
> +		append_printf(bufp, end, ":%s", key);
> +		sep = '=';
> +		xbc_array_for_each_value(anode, p) {
> +			append_printf(bufp, end, "%c%s", sep, p);
> +			if (sep == '=')
> +				sep = ',';
> +		}
> +	} else
> +		return -ENOENT;
> +
> +	return 0;
> +}
> +
> +static int __init
> +trace_boot_hist_add_handler(struct xbc_node *hnode, char **bufp,
> +			    char *end, const char *param)
> +{
> +	struct xbc_node *knode, *anode;
> +	const char *p;
> +	char sep;
> +
> +	/* Compose 'handler' parameter */
> +	p = xbc_node_find_value(hnode, param, NULL);
> +	if (!p) {
> +		pr_err("hist.%s requires '%s' option.\n",
> +		       xbc_node_get_data(hnode), param);
> +		return -EINVAL;
> +	}
> +	append_printf(bufp, end, ":%s(%s)", xbc_node_get_data(hnode), p);
> +
> +	/* Compose 'action' parameter */
> +	knode = xbc_node_find_child(hnode, "trace");
> +	if (!knode)
> +		knode = xbc_node_find_child(hnode, "save");
> +
> +	if (knode) {
> +		anode = xbc_node_get_child(knode);
> +		if (!anode || !xbc_node_is_value(anode)) {
> +			pr_err("hist.%s.%s requires value(s).\n",
> +			       xbc_node_get_data(hnode),
> +			       xbc_node_get_data(knode));
> +			return -EINVAL;
> +		}
> +
> +		append_printf(bufp, end, ".%s", xbc_node_get_data(knode));
> +		sep = '(';
> +		xbc_array_for_each_value(anode, p) {
> +			append_printf(bufp, end, "%c%s", sep, p);
> +			if (sep == '(')
> +				sep = ',';
> +		}
> +		append_printf(bufp, end, ")");
> +	} else if (xbc_node_find_child(hnode, "snapshot")) {
> +		append_printf(bufp, end, ".snapshot()");
> +	} else {
> +		pr_err("hist.%s requires an action.\n",
> +		       xbc_node_get_data(hnode));
> +		return -EINVAL;
> +	}
> +
> +	return 0;
> +}
> +
> +/*
> + * Histogram boottime tracing syntax.
> + *
> + * ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist {
> + *	keys = <KEY>[,...]
> + *	values = <VAL>[,...]
> + *	sort = <SORT-KEY>[,...]
> + *	size = <ENTRIES>
> + *	name = <HISTNAME>
> + *	var { <VAR> = <EXPR> ... }
> + *	pause|continue|clear
> + *	onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
> + *	onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }
> + *	filter = <FILTER>
> + * }
> + *
> + * Where <ACTION> are;
> + *
> + *	trace = <EVENT>, <ARG1>[, ...]
> + *	save = <ARG1>[, ...]
> + *	snapshot
> + */
> +static int __init
> +trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
> +{
> +	struct xbc_node *node, *knode;
> +	char *end = buf + size;
> +	const char *p;
> +	int ret = 0;
> +
> +	append_printf(&buf, end, "hist");
> +
> +	ret = trace_boot_hist_add_array(hnode, &buf, end, "keys");
> +	if (ret < 0) {
> +		if (ret == -ENOENT)
> +			pr_err("hist requires keys.\n");
> +		return -EINVAL;
> +	}
> +
> +	ret = trace_boot_hist_add_array(hnode, &buf, end, "values");
> +	if (ret == -EINVAL)
> +		return ret;
> +	ret = trace_boot_hist_add_array(hnode, &buf, end, "sort");
> +	if (ret == -EINVAL)
> +		return ret;
> +
> +	p = xbc_node_find_value(hnode, "size", NULL);
> +	if (p)
> +		append_printf(&buf, end, ":size=%s", p);
> +
> +	p = xbc_node_find_value(hnode, "name", NULL);
> +	if (p)
> +		append_printf(&buf, end, ":name=%s", p);
> +
> +	node = xbc_node_find_child(hnode, "var");
> +	if (node) {
> +		xbc_node_for_each_key_value(node, knode, p) {
> +			/* Expression must not include spaces. */
> +			append_printf(&buf, end, ":%s=",
> +				      xbc_node_get_data(knode));
> +			append_str_nospace(&buf, end, p);
> +		}
> +	}
> +
> +	/* Histogram control attributes (mutual exclusive) */
> +	if (xbc_node_find_child(hnode, "pause"))
> +		append_printf(&buf, end, ":pause");
> +	else if (xbc_node_find_child(hnode, "continue"))
> +		append_printf(&buf, end, ":continue");
> +	else if (xbc_node_find_child(hnode, "clear"))
> +		append_printf(&buf, end, ":clear");
> +
> +	/* Histogram handler and actions */
> +	node = xbc_node_find_child(hnode, "onmax");
> +	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
> +		return -EINVAL;
> +	node = xbc_node_find_child(hnode, "onchange");
> +	if (node && trace_boot_hist_add_handler(node, &buf, end, "var") < 0)
> +		return -EINVAL;
> +	node = xbc_node_find_child(hnode, "onmatch");
> +	if (node && trace_boot_hist_add_handler(node, &buf, end, "event") < 0)
> +		return -EINVAL;
> +
> +	p = xbc_node_find_value(hnode, "filter", NULL);
> +	if (p)
> +		append_printf(&buf, end, " if %s", p);
> +
> +	if (buf == end) {
> +		pr_err("hist exceeds the max command length.\n");
> +		return -E2BIG;
> +	}
> +
> +	return 0;
> +}
> +#else
> +static int __init
> +trace_boot_compose_hist_cmd(struct xbc_node *hnode, char *buf, size_t size)
> +{
> +	return -EOPNOTSUPP;
> +}
> +#endif
> +
>  static void __init
>  trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
>  			  struct xbc_node *enode)
> @@ -212,6 +437,12 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
>  			else if (trigger_process_regex(file, buf) < 0)
>  				pr_err("Failed to apply an action: %s\n", buf);
>  		}
> +		anode = xbc_node_find_child(enode, "hist");
> +		if (anode &&
> +		    trace_boot_compose_hist_cmd(anode, buf, ARRAY_SIZE(buf)) == 0) {
> +			if (trigger_process_regex(file, buf) < 0)
> +				pr_err("Failed to apply hist trigger: %s\n", buf);
> +		}
>  	} else if (xbc_node_find_value(enode, "actions", NULL))
>  		pr_err("Failed to apply event actions because CONFIG_HIST_TRIGGERS is not set.\n");
>  
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

Re: [PATCH v2 05/10] tracing/boot: Show correct histogram error command

[Masami Hiramatsu]

On Tue, 10 Aug 2021 00:48:26 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Since trigger_process_regex() modifies given trigger actions
> while parsing, the error message couldn't show what command
> was passed to the trigger_process_regex() when it returns
> an error.
> 
> To fix that, show the backed up trigger action command
> instead of parsed buffer.
> 
> Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
> ---
>  kernel/trace/trace_boot.c |   11 ++++++++---
>  1 file changed, 8 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
> index 69558f149620..cfe4a415b468 100644
> --- a/kernel/trace/trace_boot.c
> +++ b/kernel/trace/trace_boot.c
> @@ -422,6 +422,7 @@ trace_boot_init_histograms(struct trace_event_file *file,
>  {
>  	struct xbc_node *node;
>  	const char *p;
> +	char *tmp;
>  
>  	xbc_node_for_each_subkey(hnode, node) {
>  		p = xbc_node_get_data(node);
> @@ -429,15 +430,19 @@ trace_boot_init_histograms(struct trace_event_file *file,
>  			continue;
>  		/* All digit started node should be instances. */
>  		if (trace_boot_compose_hist_cmd(node, buf, size) == 0) {
> +			tmp = kstrdup(buf, GFP_KERNEL);
>  			if (trigger_process_regex(file, buf) < 0)
> -				pr_err("Failed to apply hist trigger: %s\n", buf);
> +				pr_err("Failed to apply hist trigger: %s\n", tmp);
> +			kfree(tmp);
>  		}
>  	}
>  
>  	if (xbc_node_find_child(hnode, "keys")) {
>  		if (trace_boot_compose_hist_cmd(hnode, buf, size) == 0)
> +			tmp = kstrdup(buf, GFP_KERNEL);
>  			if (trigger_process_regex(file, buf) < 0)
> -				pr_err("Failed to apply hist trigger: %s\n", buf);
> +				pr_err("Failed to apply hist trigger: %s\n", tmp);
> +			kfree(tmp);

And this lacks '{}' for the 2nd if...

>  	}
>  }
>  #else
> @@ -488,7 +493,7 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
>  			if (strlcpy(buf, p, ARRAY_SIZE(buf)) >= ARRAY_SIZE(buf))
>  				pr_err("action string is too long: %s\n", p);
>  			else if (trigger_process_regex(file, buf) < 0)
> -				pr_err("Failed to apply an action: %s\n", buf);
> +				pr_err("Failed to apply an action: %s\n", p);
>  		}
>  		anode = xbc_node_find_child(enode, "hist");
>  		if (anode)
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>