Re: [PATCH v2 1/4] ftrace: Add print_function_args()

Alan Maguire
2025-01-08T11:20:16Z

On 08/01/2025 04:52, Masami Hiramatsu (Google) wrote:
> On Wed, 8 Jan 2025 10:30:08 +0800
> Donglin Peng <dolinux.peng@gmail.com> wrote:
>
>> Steven Rostedt <rostedt@goodmis.org>于2024年12月24日 周二04:14写道：
>>
>>> From: Sven Schnelle <svens@linux.ibm.com>
>>>
>>> Add a function to decode argument types with the help of BTF. Will
>>> be used to display arguments in the function and function graph
>>> tracer.
>>>
>>> It can only handle simply arguments and up to FTRACE_REGS_MAX_ARGS number
>>> of arguments. When it hits a max, it will print ", ...":
>>>
>>> page_to_skb(vi=0xffff8d53842dc980, rq=0xffff8d53843a0800,
>>> page=0xfffffc2e04337c00, offset=6160, len=64, truesize=1536, ...)
>>>
>>> And if it hits an argument that is not recognized, it will print the raw
>>> value and the type of argument it is:
>>>
>>> make_vfsuid(idmap=0xffffffff87f99db8, fs_userns=0xffffffff87e543c0,
>>> kuid=0x0 (STRUCT))
>>> __pti_set_user_pgtbl(pgdp=0xffff8d5384ab47f8, pgd=0x110e74067 (STRUCT))
>>>
>>> Co-developed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>>> Signed-off-by: Sven Schnelle <svens@linux.ibm.com>
>>> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>>> ---
>>> Changes since v1:
>>> https://lore.kernel.org/20240904065908.1009086-5-svens@linux.ibm.com
>>>
>>> - Added Config option FUNCTION_TRACE_ARGS to this patch
>>> (unconditional if dependencies are met)
>>>
>>> - Changed the print_function_args() function to take an array of
>>> unsigned long args and not the ftrace_regs pointer. The ftrace_regs
>>> should be opaque from generic code.
>>>
>>> - Have the function print the name of an BTF type that is not supported.
>>>
>>> - Added FTRACE_REGS_MAX_ARGS as the number of arguments saved in
>>> the event and printed out.
>>>
>>> - Print "...," if the number of arguments goes past FTRACE_REGS_MAX_ARGS.
>>>
>>> include/linux/ftrace_regs.h | 5 +++
>>> kernel/trace/Kconfig | 6 +++
>>> kernel/trace/trace_output.c | 78 +++++++++++++++++++++++++++++++++++++
>>> kernel/trace/trace_output.h | 9 +++++
>>> 4 files changed, 98 insertions(+)
>>>
>>> diff --git a/include/linux/ftrace_regs.h b/include/linux/ftrace_regs.h
>>> index bbc1873ca6b8..15627ceea9bc 100644
>>> --- a/include/linux/ftrace_regs.h
>>> +++ b/include/linux/ftrace_regs.h
>>> @@ -35,4 +35,9 @@ struct ftrace_regs;
>>>
>>> #endif /* HAVE_ARCH_FTRACE_REGS */
>>>
>>> +/* This can be overridden by the architectures */
>>> +#ifndef FTRACE_REGS_MAX_ARGS
>>> +# define FTRACE_REGS_MAX_ARGS 6
>>> +#endif
>>> +
>>> #endif /* _LINUX_FTRACE_REGS_H */
>>> diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
>>> index d570b8b9c0a9..60412c1012ef 100644
>>> --- a/kernel/trace/Kconfig
>>> +++ b/kernel/trace/Kconfig
>>> @@ -263,6 +263,12 @@ config FUNCTION_GRAPH_RETADDR
>>> the function is called. This feature is off by default, and you
>>> can
>>> enable it via the trace option funcgraph-retaddr.
>>>
>>> +config FUNCTION_TRACE_ARGS
>>> + bool
>>> + depends on HAVE_FUNCTION_ARG_ACCESS_API
>>> + depends on DEBUG_INFO_BTF
>>> + default y
>>> +
>>> config DYNAMIC_FTRACE
>>> bool "enable/disable function tracing dynamically"
>>> depends on FUNCTION_TRACER
>>> diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
>>> index da748b7cbc4d..40d6c7a9e0c4 100644
>>> --- a/kernel/trace/trace_output.c
>>> +++ b/kernel/trace/trace_output.c
>>> @@ -12,8 +12,11 @@
>>> #include <linux/sched/clock.h>
>>> #include <linux/sched/mm.h>
>>> #include <linux/idr.h>
>>> +#include <linux/btf.h>
>>> +#include <linux/bpf.h>
>>>
>>> #include "trace_output.h"
>>> +#include "trace_btf.h"
>>>
>>> /* must be a power of 2 */
>>> #define EVENT_HASHSIZE 128
>>> @@ -680,6 +683,81 @@ int trace_print_lat_context(struct trace_iterator
>>> *iter)
>>> return !trace_seq_has_overflowed(s);
>>> }
>>>
>>> +#ifdef CONFIG_FUNCTION_TRACE_ARGS
>>> +void print_function_args(struct trace_seq *s, unsigned long *args,
>>> + unsigned long func)
>>> +{
>>> + const struct btf_param *param;
>>> + const struct btf_type *t;
>>> + const char *param_name;
>>> + char name[KSYM_NAME_LEN];
>>> + unsigned long arg;
>>> + struct btf *btf;
>>> + s32 tid, nr = 0;
>>> + int i;
>>> +
>>> + trace_seq_printf(s, "(");
>>> +
>>> + if (!args)
>>> + goto out;
>>> + if (lookup_symbol_name(func, name))
>>> + goto out;
>>> +
>>> + btf = bpf_get_btf_vmlinux();
>>> + if (IS_ERR_OR_NULL(btf))
>>> + goto out;
>>
>>
>> There is no need to the retrieve the BTF of vmlinux, as btf_find_func_proto
>> will return the correct BTF via its second parameter.
>
> Good catch! The second parameter of btf_find_func_proto() is output.
>

One thought here - with btf_find_func_proto(), we will try kernel BTF
and then proceed to module BTF, iterating over all modules to find the
function prototype. So where we are tracing module functions this could
get expensive if such a function is frequently encountered, and it also
opens up the risk that we end up using the wrong function prototype from
the wrong module that just happens to match on function name.

So I wonder if we could use the function address to do a more guided
lookup. Perhaps we could use kallsyms_lookup(), retrieving the
(potential) module name. Then maybe modify the signature of
btf_find_func_proto() to take an optional module name parameter to avoid
iteration? None of this is strictly needed, but it may speed things up a
bit and give us more accurate parameter info for those few cases with
name clashes, so could be done as a follow-up if needed. Thanks!

Alan

> Thank you,
>
>>
>> — donglin
>>
>>
>>> +
>>> + t = btf_find_func_proto(name, &btf);
>>> + if (IS_ERR_OR_NULL(t))
>>> + goto out;
>>> +
>>> + param = btf_get_func_param(t, &nr);
>>> + if (!param)
>>> + goto out_put;
>>> +
>>> + for (i = 0; i < nr; i++) {
>>> + /* This only prints what the arch allows (6 args by
>>> default) */
>>> + if (i == FTRACE_REGS_MAX_ARGS) {
>>> + trace_seq_puts(s, "...");
>>> + break;
>>> + }
>>> +
>>> + arg = args[i];
>>> +
>>> + param_name = btf_name_by_offset(btf, param[i].name_off);
>>> + if (param_name)
>>> + trace_seq_printf(s, "%s=", param_name);
>>> + t = btf_type_skip_modifiers(btf, param[i].type, &tid);
>>> +
>>> + switch (t ? BTF_INFO_KIND(t->info) : BTF_KIND_UNKN) {
>>> + case BTF_KIND_UNKN:
>>> + trace_seq_putc(s, '?');
>>> + /* Still print unknown type values */
>>> + fallthrough;
>>> + case BTF_KIND_PTR:
>>> + trace_seq_printf(s, "0x%lx", arg);
>>> + break;
>>> + case BTF_KIND_INT:
>>> + trace_seq_printf(s, "%ld", arg);
>>> + break;
>>> + case BTF_KIND_ENUM:
>>> + trace_seq_printf(s, "%ld", arg);
>>> + break;
>>> + default:
>>> + /* This does not handle complex arguments */
>>> + trace_seq_printf(s, "0x%lx (%s)", arg,
>>> btf_type_str(t));
>>> + break;
>>> + }
>>> + if (i < nr - 1)
>>> + trace_seq_printf(s, ", ");
>>> + }
>>> +out_put:
>>> + btf_put(btf);
>>> +out:
>>> + trace_seq_printf(s, ")");
>>> +}
>>> +#endif
>>> +
>>> /**
>>> * ftrace_find_event - find a registered event
>>> * @type: the type of event to look for
>>> diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h
>>> index dca40f1f1da4..2e305364f2a9 100644
>>> --- a/kernel/trace/trace_output.h
>>> +++ b/kernel/trace/trace_output.h
>>> @@ -41,5 +41,14 @@ extern struct rw_semaphore trace_event_sem;
>>> #define SEQ_PUT_HEX_FIELD(s, x) \
>>> trace_seq_putmem_hex(s, &(x), sizeof(x))
>>>
>>> +#ifdef CONFIG_FUNCTION_TRACE_ARGS
>>> +void print_function_args(struct trace_seq *s, unsigned long *args,
>>> + unsigned long func);
>>> +#else
>>> +static inline void print_function_args(struct trace_seq *s, unsigned long
>>> *args,
>>> + unsigned long func) {
>>> + trace_seq_puts(s, "()");
>>> +}
>>> +#endif
>>> #endif
>>>
>>> --
>>> 2.45.2
>>>
>>>
>>>
>
>