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

[Steven Rostedt <rostedt@goodmis.org>]

Sorry for the late reply, I'm finally able to look at userspace tooling.

First little nit, please start the subject with a capital letter:

  trace-cmd report: Print function retval in function_graph

Also note that it's for the report command.

On Tue, 21 May 2024 14:37:29 -0700
Jianfeng Wang <jianfeng.w.wang@oracle.com> wrote:

> 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.
> 
> Example usage:
> *  Record
> > trace-cmd record -p function_graph -P <pid>  
> 
> The recording process is not changed: trace-cmd can communicate
> with the kernel to get the actual funcgraph_exit event format.
> If the kernel supports ftrace-retval, trace-cmd will use the
> updated event format that has "retval" field.
> 
> * Report
> > trace-cmd report -O fgraph:depth -O fgraph:tailprint  
> 
> If the kernel supports this feature, the output looks like this:
> 
>  <...>-1136215 [006] ..... 1724848.377495: funcgraph_entry:                   |        __cond_resched() { (3)
>  <...>-1136215 [006] ..... 1724848.377495: funcgraph_entry:        0.200 us   |          rcu_all_qs(); (4) (ret=0x0)
>  <...>-1136215 [006] ..... 1724848.377496: funcgraph_exit:         0.601 us   |        } /* __cond_resched */ (3) (ret=0x0)
>  <...>-1136215 [006] ..... 1724848.377496: funcgraph_entry:        0.581 us   |        proc_reg_write(); (3) (ret=-5)
>  <...>-1136215 [006] ..... 1724848.377497: funcgraph_exit:         5.059 us   |      } /* vfs_write */ (2) (ret=-5)
>  <...>-1136215 [006] ..... 1724848.377497: funcgraph_exit:         6.332 us   |    } /* ksys_write */ (1) (ret=-5)
>  <...>-1136215 [006] ..... 1724848.377497: funcgraph_exit:       + 18.414 us  |  } /* __x64_sys_write */ (0) (ret=-5)
> 
> Signed-off-by: Jianfeng Wang <jianfeng.w.wang@oracle.com>
> ---
>  lib/trace-cmd/trace-ftrace.c | 37 ++++++++++++++++++++++++++++++++++++
>  1 file changed, 37 insertions(+)
> 
> diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c
> index 89e46c3d..2b4e49a5 100644
> --- a/lib/trace-cmd/trace-ftrace.c
> +++ b/lib/trace-cmd/trace-ftrace.c
> @@ -10,6 +10,9 @@
>  
>  #include "trace-cmd-private.h"
>  
> +#define MAX_LINUX_ERRNO   4095
> +#define IS_LINUX_ERR_VALUE(x) ((unsigned long long)(void *)(x) >= (unsigned long long)-MAX_LINUX_ERRNO)
> +
>  struct tep_plugin_option trace_ftrace_options[] = {
>  	{
>  		.name = "tailprint",
> @@ -185,6 +188,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 +200,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 {

This should follow Linux kernel syntax rules. That is, if one block of
a if statement has brackets, then the other should too.

Thanks,

-- Steve

> +		if (tep_get_field_val(s, finfo->fgraph_ret_event, "retval", ret_rec, &retval, 1))
> +			return trace_seq_putc(s, '!');
> +	}
> +
>  	duration = rettime - calltime;