[RFC PATCH 0/3] tracing/boot: Add histogram syntax support in boot-time tracing

[RFC PATCH 0/3] tracing/boot: Add histogram syntax support in boot-time tracing

[Masami Hiramatsu]

Hi,

Here is a series of patches for boot-time tracing to add histogram
syntax extension and fixes a build issue.

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

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.


TODO
====
- This version doesn't support multiple histograms on an event. For
  that purpose, you still need to use per-event 'actions' option.
  Maybe it can be extended to support multiple instance by adding
  '_#NUM' subkey, e.g. "hist._1.keys = ...; hist._2.keys = ...".
- This also doesn't support multiple 'onmatch'/'onmax'/'onchange'
  handler actions.
- Need to expand ktest testcase for checking this syntax.

Tom, this version doesn't make pause/continue/clear mutually exclusive.
And onmatch/onmax/onchange, too. As far as I can see the code, those
can be set on one histogram. But maybe I'm wrong. Please tell me if
there is some limitations or exclusiveness among those options.

Thank you,

---

Masami Hiramatsu (3):
      tracing/boot: Fix a hist trigger dependency for boot time tracing
      tracing/boot: Add per-event histogram action options
      Documentation: tracing: Add histogram syntax to boot-time tracing


 Documentation/trace/boottime-trace.rst |   81 ++++++++++++-
 kernel/trace/trace_boot.c              |  203 ++++++++++++++++++++++++++++++++
 2 files changed, 278 insertions(+), 6 deletions(-)

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

[RFC PATCH 1/3] 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>
---
 kernel/trace/trace_boot.c |    3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index 94ef2d099e32..e6dc9269ad75 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -204,13 +204,14 @@ trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 		else if (apply_event_filter(file, buf) < 0)
 			pr_err("Failed to apply filter: %s\n", buf);
 	}
-
+#ifdef 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);
 	}
+#endif
 
 	if (xbc_node_find_value(enode, "enable", NULL)) {
 		if (trace_event_enable_disable(file, 1, 0) < 0)

[RFC PATCH 2/3] 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>
---
 kernel/trace/trace_boot.c |  200 +++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 200 insertions(+)

diff --git a/kernel/trace/trace_boot.c b/kernel/trace/trace_boot.c
index e6dc9269ad75..56e92d34a88c 100644
--- a/kernel/trace/trace_boot.c
+++ b/kernel/trace/trace_boot.c
@@ -171,6 +171,200 @@ trace_boot_add_synth_event(struct xbc_node *node, const char *event)
 }
 #endif
 
+#ifdef CONFIG_HIST_TRIGGERS
+static int __init
+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
+trace_boot_hist_add_array(struct xbc_node *hnode, char **bufp,
+			  char *end, const char *key)
+{
+	struct xbc_node *knode, *anode;
+	const char *p;
+
+	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);
+		xbc_array_for_each_value(anode, p) {
+			append_printf(bufp, end, "%s,", p);
+		}
+		(*bufp)[-1] = ':';
+	} 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;
+
+	/* 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));
+		xbc_array_for_each_value(anode, p) {
+			append_printf(bufp, end, "%s,", p);
+		}
+		(*bufp)[-1] = ')';
+	} 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;
+	}
+	append_printf(bufp, end, ":");
+
+	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) {
+			append_printf(&buf, end, "%s=%s:",
+				      xbc_node_get_data(knode), p);
+		}
+	}
+
+	/* Histogram control attributes */
+	if (xbc_node_find_child(hnode, "pause"))
+		append_printf(&buf, end, "pause:");
+	if (xbc_node_find_child(hnode, "continue"))
+		append_printf(&buf, end, "continue:");
+	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;
+
+	/* Remove the last ':' */
+	if (buf + size > end)
+		*(--buf) = '\0';
+
+	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;
+}
+#endif
+
 static void __init
 trace_boot_init_one_event(struct trace_array *tr, struct xbc_node *gnode,
 			  struct xbc_node *enode)
@@ -211,6 +405,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);
+	}
 #endif
 
 	if (xbc_node_find_value(enode, "enable", NULL)) {

[RFC PATCH 3/3] 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>
---
 Documentation/trace/boottime-trace.rst |   81 ++++++++++++++++++++++++++++++--
 1 file changed, 76 insertions(+), 5 deletions(-)

diff --git a/Documentation/trace/boottime-trace.rst b/Documentation/trace/boottime-trace.rst
index 8053898cfeb4..8c36785b57e9 100644
--- a/Documentation/trace/boottime-trace.rst
+++ b/Documentation/trace/boottime-trace.rst
@@ -125,6 +125,67 @@ 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.keys = KEY1[, KEY2[...]]
+  Set histogram key parameters. (Mandatory)
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.values = VAL1[, VAL2[...]]
+  Set histogram value parameters.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.sort = SORT1[, SORT2[...]]
+  Set histogram sort parameter options.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.size = NR_ENTRIES
+  Set histogram size (number of entries).
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.name = NAME
+  Set histogram name.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.var.VARIABLE = EXPR
+  Define a new VARIABLE by EXPR expression.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.<pause|continue|clear>
+  Set histogram control parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.onmatch.event = GROUP.EVENT
+  Set histogram 'onmatch' handler matching event parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.onmatch.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.onmax.var = VAR
+  Set histogram 'onmax' handler variable parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.onchange.var = VAR
+  Set histogram 'onchange' handler variable parameter.
+
+ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.<onmax|onchange>.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.<onmax|onchange>.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.
+
+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 +220,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
+                }
         }
   }
 

Re: [RFC PATCH 0/3] tracing/boot: Add histogram syntax support in boot-time tracing

[Steven Rostedt]

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

> Hi,
> 
> Here is a series of patches for boot-time tracing to add histogram
> syntax extension and fixes a build issue.

Cool, I'll try to look at this, this week.

Thanks Masami!

-- Steve


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

Re: [RFC PATCH 0/3] tracing/boot: Add histogram syntax support in boot-time tracing

[Masami Hiramatsu]

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

> Hi,
> 
> Here is a series of patches for boot-time tracing to add histogram
> syntax extension and fixes a build issue.
> 
> 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 {
>          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>] }

Oops, these must use ';' as below.

  onmax|onchange { var = <VAR>; <ACTION> [= <PARAM>] }
  onmatch { event = <EVENT>; <ACTION> [= <PARAM>] }

>          filter = <FILTER>
>     }

Hmm, I found that one histogram can have several actions.

"hist:keys=func:lat=common_timestamp.usecs-$ts0:onmatch(A).trace(initcall_latency,func,$lat):onmatch(B).trace(initcall_latency,func,$lat)"

This syntax can be used for the case that measures the elapsed time
from A to C, and from B to C, 

event A -> event C
event B -> event C

So,

onmatch.GROUP.EVENT.<ACTION> = <PARAMS>

allows us to define multiple "onmatch" on one histogram.

onmatch.groupA.eventA.trace = synthevent, arg1, arg2
onmatch.groupB.eventB.trace = synthevent, arg1, arg2

However, there is another problem on "onmax" and "onchange".
Those will take a variable name that starts from "$", but we can not
use "$" in the subkey in bootconfig.

onmax.$lat.trace = synthevent, arg1, arg2 # this will cause error because of "$lat"

Thus, maybe we can expand the original one as

  onmax|onchange[.#NUM] { var = <VAR>; <ACTION> [= <PARAM>] }
  onmatch[.#NUM] { event = <EVENT>; <ACTION> [= <PARAM>] }

Then, we can add multiple handler-actions in one histogram.

onmatch.1 {
  event = ...
  trace = ...
}
onmatch.2 {
  event = ...
  trace = ...
}

Thank you,

>     
> Where <ACTION> is one of below;
>     
>     trace = <EVENT>, <ARG1>[, ...]
>     save = <ARG1>[, ...]
>     snapshot
> 
> 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.
> 
> 
> TODO
> ====
> - This version doesn't support multiple histograms on an event. For
>   that purpose, you still need to use per-event 'actions' option.
>   Maybe it can be extended to support multiple instance by adding
>   '_#NUM' subkey, e.g. "hist._1.keys = ...; hist._2.keys = ...".
> - This also doesn't support multiple 'onmatch'/'onmax'/'onchange'
>   handler actions.
> - Need to expand ktest testcase for checking this syntax.
> 
> Tom, this version doesn't make pause/continue/clear mutually exclusive.
> And onmatch/onmax/onchange, too. As far as I can see the code, those
> can be set on one histogram. But maybe I'm wrong. Please tell me if
> there is some limitations or exclusiveness among those options.
> 
> Thank you,
> 
> ---
> 
> Masami Hiramatsu (3):
>       tracing/boot: Fix a hist trigger dependency for boot time tracing
>       tracing/boot: Add per-event histogram action options
>       Documentation: tracing: Add histogram syntax to boot-time tracing
> 
> 
>  Documentation/trace/boottime-trace.rst |   81 ++++++++++++-
>  kernel/trace/trace_boot.c              |  203 ++++++++++++++++++++++++++++++++
>  2 files changed, 278 insertions(+), 6 deletions(-)
> 
> -- 
> Masami Hiramatsu (Linaro) <mhiramat@kernel.org>


-- 
Masami Hiramatsu <mhiramat@kernel.org>