[PATCH -next V7 0/7] riscv: Optimize function trace

Mon Jan 16 07:02:13 PST 2023

Hi,

On 12.01.2023 12:05, guoren at kernel.org wrote:
> From: Guo Ren <guoren at linux.alibaba.com>
> 
> The previous ftrace detour implementation fc76b8b8011 ("riscv: Using
> PATCHABLE_FUNCTION_ENTRY instead of MCOUNT") contain three problems.
> 
>   - The most horrible bug is preemption panic which found by Andy [1].
>     Let's disable preemption for ftrace first, and Andy could continue
>     the ftrace preemption work.

It seems, the patches #2-#7 of this series do not require "riscv: 
ftrace: Fixup panic by disabling preemption" and can be used without it.

How about moving that patch out of the series and processing it separately?

As it was pointed out in the discussion of that patch, some other 
solution to non-atomic changes of the prologue might be needed anyway.

>   - The "-fpatchable-function-entry= CFLAG" wasted code size
>     !RISCV_ISA_C.
>   - The ftrace detour implementation wasted code size.
>   - When livepatching, the trampoline (ftrace_regs_caller) would not
>     return to <func_prolog+12> but would rather jump to the new function.
>     So, "REG_L ra, -SZREG(sp)" would not run and the original return
>     address would not be restored. The kernel is likely to hang or crash
>     as a result. (Found by Evgenii Shatokhin [4])
> 
> Patches 1,2,3 fixup above problems.
> 
> Patches 4,5,6,7 are the features based on reduced detour code
> patch, we include them in the series for test and maintenance.
> 
> You can directly try it with:
> https://github.com/guoren83/linux/tree/ftrace_fixup_v7
> 
> Make function graph use ftrace directly [2] (patch 4, 5)
> ========================================================
> 
> In RISC-V architecture, when we enable the ftrace_graph tracer on some
> functions, the function tracings on other functions will suffer extra
> graph tracing work. In essence, graph_ops isn't limited by its func_hash
> due to the global ftrace_graph_[regs]_call label. That should be
> corrected.
> 
> What inspires me is the commit 0c0593b45c9b ("x86/ftrace: Make function
> graph use ftrace directly") that uses graph_ops::func function to
> install return_hooker and makes the function called against its
> func_hash.
> 
> This series of patches makes function graph use ftrace directly for
> riscv.
> 
> If FTRACE_WITH_REGS isn't defined, ftrace_caller keeps ftrace_graph_call
> so that it can be replaced with the calling of prepare_ftrace_return by
> the enable/disable helper.
> 
> As for defining FTRACE_WITH_REGS, ftrace_caller is adjusted to save the
> necessary regs against the pt_regs layout, so it can reasonably call the
> graph_ops::func function - ftrace_graph_func. And
> ftrace_graph_[regs]_call
> and its enable/disable helper aren't needed.
> 
> Test log:
> 
> The tests generated by CONFIG_FTRACE_STARTUP_TEST have passed in the
> local
> qemu-system-riscv64 virt machine. The following is the log during
> startup.
> 
> ```
> Nov 15 03:07:13 stage4 kernel: Testing tracer function: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing dynamic ftrace: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing dynamic ftrace ops #1:
> Nov 15 03:07:13 stage4 kernel: (1 0 1 0 0)
> Nov 15 03:07:13 stage4 kernel: (1 1 2 0 0)
> Nov 15 03:07:13 stage4 kernel: (2 1 3 0 365)
> Nov 15 03:07:13 stage4 kernel: (2 2 4 0 399)
> Nov 15 03:07:13 stage4 kernel: (3 2 4 0 146071)
> Nov 15 03:07:13 stage4 kernel: (3 3 5 0 146105) PASSED
> Nov 15 03:07:13 stage4 kernel: Testing dynamic ftrace ops #2:
> Nov 15 03:07:13 stage4 kernel: (1 0 1 589 0)
> Nov 15 03:07:13 stage4 kernel: (1 1 2 635 0)
> Nov 15 03:07:13 stage4 kernel: (2 1 3 1 2)
> Nov 15 03:07:13 stage4 kernel: (2 2 4 125 126)
> Nov 15 03:07:13 stage4 kernel: (3 2 4 146001 146078)
> Nov 15 03:07:13 stage4 kernel: (3 3 5 146035 146112) PASSED
> Nov 15 03:07:13 stage4 kernel: Testing ftrace recursion: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing ftrace recursion safe: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing ftrace regs: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer nop: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer irqsoff: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer wakeup:
> Nov 15 03:07:13 stage4 kernel: sched: DL replenish lagged too much
> Nov 15 03:07:13 stage4 kernel: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer wakeup_rt: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer wakeup_dl: PASSED
> Nov 15 03:07:13 stage4 kernel: Testing tracer function_graph: PASSED
> ```
> 
> Add WITH_DIRECT_CALLS support [3] (patch 6, 7)
> ==============================================
> 
> This series adds DYNAMIC_FTRACE_WITH_DIRECT_CALLS support for RISC-V.
> SAMPLE_FTRACE_DIRECT and SAMPLE_FTRACE_DIRECT_MULTI are also included
> here as the samples for testing DIRECT_CALLS related interface.
> 
> First, select the DYNAMIC_FTRACE_WITH_DIRECT_CALLS to provide
> register_ftrace_direct[_multi] interfaces allowing user to register
> the customed trampoline (direct_caller) as the mcount for one or
> more target functions. And modify_ftrace_direct[_multi] are also
> provided for modify direct_caller.
> 
> At the same time, the samples in ./samples/ftrace/ can be built
> as kerenl module for testing these interfaces with SAMPLE_FTRACE_DIRECT
> and SAMPLE_FTRACE_DIRECT_MULTI selected.
> 
> Second, to make the direct_caller and the other ftrace hooks
> (eg. function/fgraph tracer, k[ret]probes) co-exist, a temporary
> register
> are nominated to store the address of direct_caller in
> ftrace_regs_caller.
> After the setting of the address direct_caller by direct_ops->func and
> the RESTORE_REGS in ftrace_regs_caller, direct_caller will be jumped to
> by the `jr` inst.
> 
> The following tests have been passed in my local qemu-riscv64 virt
> machine.
> 
> 1. tests with CONFIG_FTRACE_STARTUP_TEST
> 2. tests of samples/ftrace/ftrace*.ko
> 3. manual tests with any combination of the following hooks
>    - function/function_graph tracer
>    - ftrace*.ko
>    - kprobe/kretprobe
> 
> For your reference, here is the log when function tracer, kretprobe and
> ftrace-direct-too.ko co-hooks the handle_mm_fault function.
> 
> ```
> [root at stage4 tracing]# echo handle_mm_fault > set_ftrace_filter
> [root at stage4 tracing]# echo 'r:myr handle_mm_fault' > kprobe_events
> [root at stage4 tracing]# echo function > current_tracer
> [root at stage4 tracing]# echo 1 > events/kprobes/myr/enable
> [root at stage4 tracing]# insmod /root/ftrace-direct-too.ko
> [root at stage4 tracing]#
> [root at stage4 tracing]# cat trace | tail
>               cat-388     [000] ...1.   583.051438: myr:
> (do_page_fault+0x16c/0x5f2 <- handle_mm_fault)
>               cat-388     [000] ...2.   583.057930: handle_mm_fault
> <-do_page_fault
>               cat-388     [000] .....   583.057990: my_direct_func:
> handle mm fault vma=000000002d9fe19c address=ffffffae9b7000 flags=215
>               cat-388     [000] ...1.   583.058284: myr:
> (do_page_fault+0x16c/0x5f2 <- handle_mm_fault)
>              tail-389     [001] ...2.   583.059062: handle_mm_fault
> <-do_page_fault
>              tail-389     [001] .....   583.059104: my_direct_func:
> handle mm fault vma=0000000017f3c48e address=aaaaaabebf3000 flags=215
>              tail-389     [001] ...1.   583.059325: myr:
> (do_page_fault+0x16c/0x5f2 <- handle_mm_fault)
>              tail-389     [001] ...2.   583.060371: handle_mm_fault
> <-do_page_fault
>              tail-389     [001] .....   583.060410: my_direct_func:
> handle mm fault vma=0000000017f3c48e address=aaaaaabebf1000 flags=255
>              tail-389     [001] ...1.   583.060996: myr:
> (do_page_fault+0x16c/0x5f2 <- handle_mm_fault)
> ```
> Note1:
> 
> The checkpatch.pl will output some warnings on this series, like this
> 
> ```
> WARNING: Prefer using '"%s...", __func__' to using 'my_direct_func2',
> this function's name, in a string
> 111: FILE: samples/ftrace/ftrace-direct-multi-modify.c:48:
> +"       call my_direct_func2\n"
> ```
> 
> The reason is that checkpatch depends on patch context providing the
> function name. In the above warning, my_direct_func2 has some codeline
> distance with the changed trunk, so its declaration doesn't come into
> the patch, and then the warning jumps out.
> 
> You may notice the location of `my_ip` variable changes in the 2nd
> patch. I did that for reducing the warnings to some extent. But killing
> all the warnings will makes the patch less readable, so I stopped here.
> 
> [1] https://lpc.events/event/16/contributions/1171/
> [2] https://lore.kernel.org/lkml/20221120084230.910152-1-suagrfillet@gmail.com/
> [3] https://lore.kernel.org/linux-riscv/20221123142025.1504030-1-suagrfillet@gmail.com/
> [4] https://lore.kernel.org/linux-riscv/d7d5730b-ebef-68e5-5046-e763e1ee6164@yadro.com/
> 
> Changes in v7:
>   - Fixup RESTORE_ABI_REGS by remove PT_T0(sp) overwrite.
>   - Add FTRACE_MCOUNT_USE_PATCHABLE_FUNCTION_ENTRY
>   - Fixup kconfig with HAVE_SAMPLE_FTRACE_DIRECT &
>     HAVE_SAMPLE_FTRACE_DIRECT_MULTI
> 
> Changes in v6:
> https://lore.kernel.org/linux-riscv/20230107133549.4192639-1-guoren@kernel.org/
>   - Replace 8 with MCOUNT_INSN_SIZE
>   - Replace "REG_L a1, PT_RA(sp)" with "mv a1, ra"
>   - Add Evgenii Shatokhin comment
> 
> Changes in v5:
> https://lore.kernel.org/linux-riscv/20221208091244.203407-1-guoren@kernel.org/
>   - Sort Kconfig entries in alphabetical order.
> 
> Changes in v4:
> https://lore.kernel.org/linux-riscv/20221129033230.255947-1-guoren@kernel.org/
>   - Include [3] for maintenance. [Song Shuai]
> 
> Changes in V3:
> https://lore.kernel.org/linux-riscv/20221123153950.2911981-1-guoren@kernel.org/
>   - Include [2] for maintenance. [Song Shuai]
> 
> Changes in V2:
> https://lore.kernel.org/linux-riscv/20220921034910.3142465-1-guoren@kernel.org/
>   - Add Signed-off for preemption fixup.
> 
> Changes in V1:
> https://lore.kernel.org/linux-riscv/20220916103817.9490-1-guoren@kernel.org/
> 
> Andy Chiu (1):
>    riscv: ftrace: Fixup panic by disabling preemption
> 
> Guo Ren (2):
>    riscv: ftrace: Remove wasted nops for !RISCV_ISA_C
>    riscv: ftrace: Reduce the detour code size to half
> 
> Song Shuai (4):
>    riscv: ftrace: Add ftrace_graph_func
>    riscv: ftrace: Add DYNAMIC_FTRACE_WITH_DIRECT_CALLS support
>    samples: ftrace: Add riscv support for SAMPLE_FTRACE_DIRECT[_MULTI]
>    riscv : select FTRACE_MCOUNT_USE_PATCHABLE_FUNCTION_ENTRY
> 
>   arch/riscv/Kconfig                          |   6 +-
>   arch/riscv/Makefile                         |   6 +-
>   arch/riscv/include/asm/ftrace.h             |  71 ++++++--
>   arch/riscv/kernel/ftrace.c                  |  91 ++++------
>   arch/riscv/kernel/mcount-dyn.S              | 179 +++++++++++++-------
>   samples/ftrace/ftrace-direct-modify.c       |  33 ++++
>   samples/ftrace/ftrace-direct-multi-modify.c |  37 ++++
>   samples/ftrace/ftrace-direct-multi.c        |  22 +++
>   samples/ftrace/ftrace-direct-too.c          |  26 +++
>   samples/ftrace/ftrace-direct.c              |  22 +++
>   10 files changed, 356 insertions(+), 137 deletions(-)
> 
> --
> 2.36.1
> 
> 

I tested this series a bit on top of 6.2-rc4, with 
https://github.com/sugarfillet/linux/commit/9539a80dc6e7d1137ec7a96ebef2ab912a694bd7.patch 
added.

The kernel was built with CONFIG_DYNAMIC_FTRACE_WITH_REGS=y and 
CONFIG_RISCV_ISA_C=y.

Here are some results:

* The kernel was built without visible issues.

* Most of the Ftrace startup tests ran and passed. Certain 
event-specific tests caused soft lockups in one of the test runs but 
they are likely unrelated to this patchset and could happen without it too.

* "function" and "function_graph" tracers worked in my simple use cases.

* "ipmodify" functionality worked.

* kprobe sample modules worked OK, which is good, because they actually 
use Ftrace: they plant the probes at the beginning of the resp. functions.

* ftrace-direct-multi and ftrace-direct-multi-modify sample modules 
reported possibly invalid data. More info - in my reply to
"[PATCH -next V7 6/7] samples: ftrace: Add riscv support for 
SAMPLE_FTRACE_DIRECT[_MULTI]"

Regards,
Evgenii