[PATCH 0/2] trace-cmd ftrace: support function retval feature in function_graph

[PATCH 0/2] trace-cmd ftrace: support function retval feature in function_graph

[Jianfeng Wang]

The upstream Linux kernel has introduced a funcgraph retval
feature for the function_graph tracer. (Commit ID:
a1be9ccc57f07d54278be34eed6bd679bc941c97). This feature can be
useful for debugging kernel problems, such as root cause
analysis for syscall errors.

This patch series is to utilize this feature to support
printing each function's return value in 'trace-cmd report'.
The default is off. Add a ftrace internal option so that
users can turn this feature on if they'd like to request for
the retval information in the function_graph tracer.

Jianfeng Wang (2):
  trace-cmd ftrace: print function retval in function_graph
  trace-cmd: Add ftrace options with fgraph retval option

 lib/trace-cmd/trace-ftrace.c | 33 +++++++++++++++++++++++++++++++++
 1 file changed, 33 insertions(+)

-- 
2.42.1

[PATCH 1/2] trace-cmd ftrace: print function retval in function_graph

[Jianfeng Wang]

The upstream Linux kernel has introduced a new feature, i.e.
funcgraph-retval for the function_graph tracer. (Commit ID:
a1be9ccc57f07d54278be34eed6bd679bc941c97). With this feature, the
function_graph tracer can record each function's return value along
with its execution time at the function_graph exit handler. This is
useful for debugging kernel issues, such as syscall errors.

This commit enhances 'trace-cmd report' by supporting the
function_graph retval feature if the underlying kernel supports it.
Once the feature is supported, 'trace-cmd report' will print each
function's return value in this format: '(ret=retval)" at the end
of every funcgraph leaf entry and exit event.

Signed-off-by: Jianfeng Wang <jianfeng.w.wang@oracle.com>
---
 lib/trace-cmd/trace-ftrace.c | 26 ++++++++++++++++++++++++++
 1 file changed, 26 insertions(+)

diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c
index 89e46c3d..cb05d88c 100644
--- a/lib/trace-cmd/trace-ftrace.c
+++ b/lib/trace-cmd/trace-ftrace.c
@@ -185,6 +185,8 @@ print_graph_entry_leaf(struct trace_seq *s,
 	unsigned long long rettime, calltime;
 	unsigned long long duration, depth;
 	unsigned long long val;
+	unsigned long long retval;
+	bool fgraph_retval_supported = true;
 	const char *func;
 	int ret;
 	int i;
@@ -195,6 +197,13 @@ print_graph_entry_leaf(struct trace_seq *s,
 	if (tep_get_field_val(s, finfo->fgraph_ret_event, "calltime", ret_rec, &calltime, 1))
 		return trace_seq_putc(s, '!');
 
+	if (!tep_find_field(finfo->fgraph_ret_event, "retval"))
+		fgraph_retval_supported = false;
+	else {
+		if (tep_get_field_val(s, finfo->fgraph_ret_event, "retval", ret_rec, &retval, 1))
+			return trace_seq_putc(s, '!');
+	}
+
 	duration = rettime - calltime;
 
 	/* Overhead */
@@ -222,6 +231,10 @@ print_graph_entry_leaf(struct trace_seq *s,
 	if (ret && fgraph_depth->set)
 		ret = trace_seq_printf(s, " (%lld)", depth);
 
+	/* Return Value */
+	if (ret && fgraph_retval_supported)
+		ret = trace_seq_printf(s, " (ret=%lld)", retval);
+
 	return ret;
 }
 
@@ -316,6 +329,8 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
 	unsigned long long duration, depth;
 	unsigned long long val;
 	const char *func;
+	unsigned long long retval;
+	bool fgraph_retval_supported = true;
 	int i;
 
 	ret_event_check(finfo, event->tep);
@@ -326,6 +341,13 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
 	if (tep_get_field_val(s, event, "calltime", record, &calltime, 1))
 		return trace_seq_putc(s, '!');
 
+	if (!tep_find_field(event, "retval"))
+		fgraph_retval_supported = false;
+	else {
+		if (tep_get_field_val(s, event, "retval", record, &retval, 1))
+			return trace_seq_putc(s, '!');
+	}
+
 	duration = rettime - calltime;
 
 	/* Overhead */
@@ -355,6 +377,10 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
 	if (fgraph_depth->set)
 		trace_seq_printf(s, " (%lld)", depth);
 
+	/* Return Value */
+	if (fgraph_retval_supported)
+		trace_seq_printf(s, " (ret=%lld)", retval);
+
 	return 0;
 }
 
-- 
2.42.1

[PATCH 2/2] trace-cmd: Add ftrace options with fgraph retval option

[Jianfeng Wang]

Added internal options for ftrace, and included a fgraph:retval
option that will print the function names at the function exit.
When the option is set and the function_graph retval feature is
supported by the kernel, each function's return value will be
printed as '(ret=retval)'.

Signed-off-by: Jianfeng Wang <jianfeng.w.wang@oracle.com>
---
 lib/trace-cmd/trace-ftrace.c | 11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c
index cb05d88c..fecc3d69 100644
--- a/lib/trace-cmd/trace-ftrace.c
+++ b/lib/trace-cmd/trace-ftrace.c
@@ -23,6 +23,12 @@ struct tep_plugin_option trace_ftrace_options[] = {
 		.description =
 		"Show the depth of each entry",
 	},
+	{
+		.name = "retval",
+		.plugin_alias = "fgraph",
+		.description =
+		"Print function retval at function exit in function graph",
+	},
 	{
 		.name = NULL,
 	}
@@ -30,6 +36,7 @@ struct tep_plugin_option trace_ftrace_options[] = {
 
 static struct tep_plugin_option *fgraph_tail = &trace_ftrace_options[0];
 static struct tep_plugin_option *fgraph_depth = &trace_ftrace_options[1];
+static struct tep_plugin_option *fgraph_retval = &trace_ftrace_options[2];
 
 static int find_ret_event(struct tracecmd_ftrace *finfo, struct tep_handle *pevent)
 {
@@ -232,7 +239,7 @@ print_graph_entry_leaf(struct trace_seq *s,
 		ret = trace_seq_printf(s, " (%lld)", depth);
 
 	/* Return Value */
-	if (ret && fgraph_retval_supported)
+	if (ret && fgraph_retval->set && fgraph_retval_supported)
 		ret = trace_seq_printf(s, " (ret=%lld)", retval);
 
 	return ret;
@@ -378,7 +385,7 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
 		trace_seq_printf(s, " (%lld)", depth);
 
 	/* Return Value */
-	if (fgraph_retval_supported)
+	if (fgraph_retval->set && fgraph_retval_supported)
 		trace_seq_printf(s, " (ret=%lld)", retval);
 
 	return 0;
-- 
2.42.1

Re: [PATCH 2/2] trace-cmd: Add ftrace options with fgraph retval option

[Jianfeng Wang]

On 4/15/24 8:49 AM, Jianfeng Wang wrote:
> Added internal options for ftrace, and included a fgraph:retval
> option that will print the function names at the function exit.
> When the option is set and the function_graph retval feature is
> supported by the kernel, each function's return value will be
> printed as '(ret=retval)'.
> 
> Signed-off-by: Jianfeng Wang <jianfeng.w.wang@oracle.com>
> ---
>  lib/trace-cmd/trace-ftrace.c | 11 +++++++++--
>  1 file changed, 9 insertions(+), 2 deletions(-)
> 
> diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c
> index cb05d88c..fecc3d69 100644
> --- a/lib/trace-cmd/trace-ftrace.c
> +++ b/lib/trace-cmd/trace-ftrace.c
> @@ -23,6 +23,12 @@ struct tep_plugin_option trace_ftrace_options[] = {
>  		.description =
>  		"Show the depth of each entry",
>  	},
> +	{
> +		.name = "retval",
> +		.plugin_alias = "fgraph",
> +		.description =
> +		"Print function retval at function exit in function graph",
> +	},
>  	{
>  		.name = NULL,
>  	}
> @@ -30,6 +36,7 @@ struct tep_plugin_option trace_ftrace_options[] = {
>  
>  static struct tep_plugin_option *fgraph_tail = &trace_ftrace_options[0];
>  static struct tep_plugin_option *fgraph_depth = &trace_ftrace_options[1];
> +static struct tep_plugin_option *fgraph_retval = &trace_ftrace_options[2];
>  
>  static int find_ret_event(struct tracecmd_ftrace *finfo, struct tep_handle *pevent)
>  {
> @@ -232,7 +239,7 @@ print_graph_entry_leaf(struct trace_seq *s,
>  		ret = trace_seq_printf(s, " (%lld)", depth);
>  
>  	/* Return Value */
> -	if (ret && fgraph_retval_supported)
> +	if (ret && fgraph_retval->set && fgraph_retval_supported)
>  		ret = trace_seq_printf(s, " (ret=%lld)", retval);
>  
>  	return ret;
> @@ -378,7 +385,7 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
>  		trace_seq_printf(s, " (%lld)", depth);
>  
>  	/* Return Value */
> -	if (fgraph_retval_supported)
> +	if (fgraph_retval->set && fgraph_retval_supported)
>  		trace_seq_printf(s, " (ret=%lld)", retval);
>  
>  	return 0;

Kindly ask for reviews on this patchset :)

Here, I include a more detailed effect of this patchset.

* Record process
The trace-cmd record process is not changed.

# trace-cmd record -p function_graph -P 4331

trace-cmd can communicate with the kernel to get the actual funcgraph_exit
event format. If the kernel supports ftrace-retval, then trace-cmd will
use the updated event format that has "retval" field.

* Report process
By default, trace-cmd won't print each function's retval.

# trace-cmd report

However, if one wants to turn it on and the kernel supports the feature,
do the following (through fgraph plugin options):

# trace-cmd report -O fgraph:depth -O fgraph:tailprint -O fgraph:retval

The output looks like this:

  <idle>-0     [012] d....   361.071503: funcgraph_entry:                   |  switch_mm_irqs_off() { (0)
  <idle>-0     [012] d....   361.071507: funcgraph_entry:        0.491 us   |    load_new_mm_cr3(); (1) (ret=0)
  <idle>-0     [012] d....   361.071508: funcgraph_entry:        0.251 us   |    switch_ldt(); (1) (ret=0)
  <idle>-0     [012] d....   361.071508: funcgraph_exit:         5.901 us   |  } /* switch_mm_irqs_off */ (0) (ret=0)

Each function's return value will be printed at the function's return point.

Re: [PATCH 2/2] trace-cmd: Add ftrace options with fgraph retval option

[Steven Rostedt]

On Tue, 30 Apr 2024 15:45:43 -0700
Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:

> Kindly ask for reviews on this patchset :)

I haven't forgotten these patches ;-)

I was hoping to get to the userspace side this month, but things came up on
the kernel side I had to take care of.

I'm hoping to get to them in then next week or so.

Thanks,

-- Steve