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@xxxxxxxxxx> 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@xxxxxxxxxx>
> ---
> 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;
|