[PATCH v3 0/2] trace-cmd report: support function retval in function_graph

[PATCH v3 0/2] trace-cmd report: support function retval in function_graph

[Jianfeng Wang]

The upstream Linux kernel has introduced a funcgraph retval feature
for the function_graph tracer. (Commit ID:
a1be9ccc57f07d54278be34eed6bd679bc941c97). This patchset is to utilize
this feature to support printing each function's return value in
'trace-cmd report'. Add three fgraph options so that users can skip
the printing, and force the return values to be printed in decimal
or in hex format.

Change history:
===============
v3:
- Fix code format.
- Add fgraph:retval-dec option.

v2:
- Check if a retval is an error code: if not, print it in hex.
- Make this retval feature on by default.
- Add fgraph:retval-skip and fgraph:retval-hex options.

v1: https://lore.kernel.org/linux-trace-devel/20240415154921.4998-1-jianfeng.w.wang@oracle.com

Jianfeng Wang (2):
  trace-cmd report: Print function retval in function_graph
  trace-cmd report: Add options for the fgraph retval feature

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

-- 
2.42.1

[PATCH v3 1/2] trace-cmd report: 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. Error codes are
printed in decimal, while others are printed in hex.

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..d2d1321a 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;
 }
 
-- 
2.42.1

[PATCH v3 2/2] trace-cmd report: Add options for the fgraph retval feature

[Jianfeng Wang]

Add three internal options for fgraph: fgraph:retval-skip,
fgraph:retval-dec, and fgraph:retval-hex.

trace-cmd will print each function's return value at the
function_graph exit point if the kernel supports the fgraph-retval
feature. If users want to skip the output of return values, then
set fgraph:retval-skip. By default, return values are printed in
hex, while they are printed in decimal if they are error codes.
Users can set fgraph:retval-dec to force return values to be
printed in decimal, or set fgraph:retval-hex to force them to be
printed in hex. fgraph:retval-dec overwrites fgraph:retval-hex.

Here are example commands:
> trace-cmd report -O fgraph:retval-skip
> trace-cmd report -O fgraph:retval-dec
> trace-cmd report -O fgraph:retval-hex

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

diff --git a/lib/trace-cmd/trace-ftrace.c b/lib/trace-cmd/trace-ftrace.c
index d2d1321a..d0e6a8e7 100644
--- a/lib/trace-cmd/trace-ftrace.c
+++ b/lib/trace-cmd/trace-ftrace.c
@@ -26,6 +26,24 @@ struct tep_plugin_option trace_ftrace_options[] = {
 		.description =
 		"Show the depth of each entry",
 	},
+	{
+		.name = "retval-skip",
+		.plugin_alias = "fgraph",
+		.description =
+		"Skip printing function retval in function graph",
+	},
+	{
+		.name = "retval-dec",
+		.plugin_alias = "fgraph",
+		.description =
+		"Print function retval in decimal at function exit in function graph",
+	},
+	{
+		.name = "retval-hex",
+		.plugin_alias = "fgraph",
+		.description =
+		"Print function retval in hex at function exit in function graph",
+	},
 	{
 		.name = NULL,
 	}
@@ -33,6 +51,9 @@ 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_skip = &trace_ftrace_options[2];
+static struct tep_plugin_option *fgraph_retval_dec = &trace_ftrace_options[3];
+static struct tep_plugin_option *fgraph_retval_hex = &trace_ftrace_options[4];
 
 static int find_ret_event(struct tracecmd_ftrace *finfo, struct tep_handle *pevent)
 {
@@ -235,11 +256,18 @@ print_graph_entry_leaf(struct trace_seq *s,
 		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
+	if (ret && fgraph_retval_supported && !fgraph_retval_skip->set) {
+		if (fgraph_retval_dec->set) {
 			ret = trace_seq_printf(s, " (ret=%lld)", retval);
+		} else if (fgraph_retval_hex->set) {
+			ret = trace_seq_printf(s, " (ret=0x%llx)", retval);
+		} else {
+			/* Error codes are in decimal; others are in hex */
+			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;
@@ -385,11 +413,18 @@ fgraph_ret_handler(struct trace_seq *s, struct tep_record *record,
 		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
+	if (fgraph_retval_supported && !fgraph_retval_skip->set) {
+		if (fgraph_retval_dec->set) {
 			trace_seq_printf(s, " (ret=%lld)", retval);
+		} else if (fgraph_retval_hex->set) {
+			trace_seq_printf(s, " (ret=0x%llx)", retval);
+		} else {
+			/* Error codes are in decimal; others are in hex */
+			if (!IS_LINUX_ERR_VALUE(retval))
+				trace_seq_printf(s, " (ret=0x%llx)", retval);
+			else
+				trace_seq_printf(s, " (ret=%lld)", retval);
+		}
 	}
 
 	return 0;
-- 
2.42.1