| Message ID | 20240521213730.67993-2-jianfeng.w.wang@oracle.com (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | trace-cmd ftrace: support function retval feature in function_graph | expand |
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;
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 { + 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 +234,14 @@ 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) { + if (!IS_LINUX_ERR_VALUE(retval)) + ret = trace_seq_printf(s, " (ret=0x%llx)", retval); + else + ret = trace_seq_printf(s, " (ret=%lld)", retval); + } + return ret; } @@ -316,6 +336,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 +348,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 +384,14 @@ 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) { + if (!IS_LINUX_ERR_VALUE(retval)) + trace_seq_printf(s, " (ret=0x%llx)", retval); + else + trace_seq_printf(s, " (ret=%lld)", retval); + } + return 0; }