[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

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

[Steven Rostedt]

Finally got the time to look at these patches ;-)

On Mon, 15 Apr 2024 08:49:21 -0700
Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:

> +++ 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",
> +	},

Honestly, I don't think this should be an option. Or if it is, it
should be default on. If the retval exists in the trace, it should just
be printed. Why ask the user to show it when they spent the time to
enable it in the recording?

Thanks!

-- Steve

>  	{
>  		.name = NULL,
>  	}

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

[Jianfeng Wang]

On 5/16/24 5:53 PM, Steven Rostedt wrote:
> 
> Finally got the time to look at these patches ;-)
> 
> On Mon, 15 Apr 2024 08:49:21 -0700
> Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:
> 
>> +++ 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",
>> +	},
> 
> Honestly, I don't think this should be an option. Or if it is, it
> should be default on. If the retval exists in the trace, it should just
> be printed. Why ask the user to show it when they spent the time to
> enable it in the recording?
> 
> Thanks!
> 
> -- Steve
> 

Thanks for your response!

I make it a default-off option because the feature changes the output format of
the 'trace-cmd report'. So to be on the safe side, keep the original format by
default. Also, the kernel has options (i.e., options/funcgraph-retval and
options/funcgraph-retval-hex) to enable printing functions' retval in trace.log

From my point of view, I'd like to see the retval on by default. If you are
okay, I'd like to make it default on and add an option to display retval in hex.

>>  	{
>>  		.name = NULL,
>>  	}

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

[Steven Rostedt]

On Fri, 17 May 2024 11:50:29 -0700
Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:

> > Honestly, I don't think this should be an option. Or if it is, it
> > should be default on. If the retval exists in the trace, it should just
> > be printed. Why ask the user to show it when they spent the time to
> > enable it in the recording?
> > 

> 
> I make it a default-off option because the feature changes the output format of
> the 'trace-cmd report'. So to be on the safe side, keep the original format by
> default. Also, the kernel has options (i.e., options/funcgraph-retval and
> options/funcgraph-retval-hex) to enable printing functions' retval in trace.log
> 
> >From my point of view, I'd like to see the retval on by default. If you are  
> okay, I'd like to make it default on and add an option to display retval in hex.

Yeah, we can keep both as an option, but make the retval default on.

It will not change default behavior, as it should only be shown if retval
was recorded in the first place. If it wasn't recorded, the behavior should
be the same regardless of if the retval option is enabled or not in the
trace-cmd output.

-- Steve

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

[Jianfeng Wang]

On 5/17/24 12:00 PM, Steven Rostedt wrote:
> On Fri, 17 May 2024 11:50:29 -0700
> Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:
> 
>>> Honestly, I don't think this should be an option. Or if it is, it
>>> should be default on. If the retval exists in the trace, it should just
>>> be printed. Why ask the user to show it when they spent the time to
>>> enable it in the recording?
>>>
> 
>>
>> I make it a default-off option because the feature changes the output format of
>> the 'trace-cmd report'. So to be on the safe side, keep the original format by
>> default. Also, the kernel has options (i.e., options/funcgraph-retval and
>> options/funcgraph-retval-hex) to enable printing functions' retval in trace.log
>>
>> >From my point of view, I'd like to see the retval on by default. If you are  
>> okay, I'd like to make it default on and add an option to display retval in hex.
> 
> Yeah, we can keep both as an option, but make the retval default on.
> 
> It will not change default behavior, as it should only be shown if retval
> was recorded in the first place. If it wasn't recorded, the behavior should
> be the same regardless of if the retval option is enabled or not in the
> trace-cmd output.
> 
> -- Steve

SGTM. I will send a v2.

Thanks,
Jianfeng