Re: [PATCH v5 1/2] function_graph: Support recording and printing the return value of function
From: Donglin Peng
Date: Wed Mar 22 2023 - 04:47:43 EST
On 2023/3/21 22:24, Mark Rutland wrote:
On Mon, Mar 20, 2023 at 06:16:49AM -0700, Donglin Peng wrote:
When using the function_graph tracer to analyze system call failures,
it can be time-consuming to analyze the trace logs and locate the kernel
function that first returns an error. This change aims to simplify the
process by recording the function return value to the 'retval' member of
'ftrace_graph_ent' and printing it when outputing the trace log.
New trace options are introduced: funcgraph-retval and graph_retval_hex.
The former is used to control whether to display the return value, while
the latter is used to control the display format of the reutrn value.
Note that even if a function's return type is void, a return value will
still be printed, so just ignore it.
Currently, this modification supports the following commonly used
processor architectures: x86_64, x86, arm64, arm, riscv.
Here is an example:
I want to attach the demo process to a cpu cgroup, but it failed:
echo `pidof demo` > /sys/fs/cgroup/cpu/test/tasks
-bash: echo: write error: Invalid argument
The strace logs tells that the write system call returned -EINVAL(-22):
...
write(1, "273\n", 4) = -1 EINVAL (Invalid argument)
...
Use the following commands to capture trace logs when calling the write
system call:
cd /sys/kernel/debug/tracing/
echo 0 > tracing_on
echo > trace
echo *sys_write > set_graph_function
echo *spin* > set_graph_notrace
echo *rcu* >> set_graph_notrace
echo *alloc* >> set_graph_notrace
echo preempt* >> set_graph_notrace
echo kfree* >> set_graph_notrace
echo $$ > set_ftrace_pid
echo function_graph > current_tracer
echo 1 > tracing_on
echo `pidof demo` > /sys/fs/cgroup/cpu/test/tasks
echo 0 > tracing_on
echo 1 > options/funcgraph-retval
cat trace > ~/trace.log
Search the error code -22 directly in the file trace.log and find the
first function that return -22, then read the function code to get the
root cause.
...
1) | cgroup_migrate() {
1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */
1) | cgroup_migrate_execute() {
1) | cpu_cgroup_can_attach() {
1) | cgroup_taskset_first() {
1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */
1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */
1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */
1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */
1) 4.369 us | } /* cgroup_migrate_execute = -22 */
1) 7.143 us | } /* cgroup_migrate = -22 */
...
Signed-off-by: Donglin Peng <pengdonglin@xxxxxxxxxxxxxx>
diff --git a/arch/arm64/kernel/entry-ftrace.S b/arch/arm64/kernel/entry-ftrace.S
index 350ed81324ac..d1a5d76e6d72 100644
--- a/arch/arm64/kernel/entry-ftrace.S
+++ b/arch/arm64/kernel/entry-ftrace.S
@@ -276,7 +276,15 @@ SYM_CODE_START(return_to_handler)
stp x4, x5, [sp, #32]
stp x6, x7, [sp, #48]
+#ifdef CONFIG_FUNCTION_GRAPH_RETVAL
+ /*
+ * Pass both the function return values in the register x0 and x1
+ * to ftrace_return_to_handler.
+ */
+ mov x2, x29 // parent's fp
+#else
mov x0, x29 // parent's fp
+#endif
bl ftrace_return_to_handler// addr = ftrace_return_to_hander(fp);
mov x30, x0 // restore the original return address
Please don't make the calling convention of the asm change depending on a
selectable config option.
We already store the regs here; I'd be happy to make that a struct ftrace_regs
and pass a pointer to that to C code. Then it's be easy to acquire the value
you want in the exact same way as upon entry, and it'll work even if we decide
to return a structure by value somewhere (as that can use registers x2-x7 too).
Agree, I think we only need to store return registers, but ftrace_regs
has too many members. So we can introduce a new structure called
pt_ret_regs which only contains return registers and frame pointer
register, for ARM64, they are x0~x7 and x29. Then pass the pointer to
pt_ret_regs to ftrace_return_to_handler.
Thanks,
Mark.