[PATCH v2 0/4] ftrace: Add function arguments to function tracers

Steven Rostedt posted 4 patches 1 year, 1 month ago
There is a newer version of this series
include/linux/ftrace_regs.h          |   5 +
kernel/trace/Kconfig                 |  12 +++
kernel/trace/trace.c                 |  12 ++-
kernel/trace/trace.h                 |   4 +-
kernel/trace/trace_entries.h         |  12 ++-
kernel/trace/trace_functions.c       |  46 ++++++++-
kernel/trace/trace_functions_graph.c | 174 ++++++++++++++++++++++++++++-------
kernel/trace/trace_irqsoff.c         |   4 +-
kernel/trace/trace_output.c          |  96 ++++++++++++++++++-
kernel/trace/trace_output.h          |   9 ++
kernel/trace/trace_sched_wakeup.c    |   4 +-
11 files changed, 324 insertions(+), 54 deletions(-)
[PATCH v2 0/4] ftrace: Add function arguments to function tracers
Posted by Steven Rostedt 1 year, 1 month ago
These patches add support for printing function arguments in ftrace.

Example usage:

function tracer:

 ~# cd /sys/kernel/tracing/
 ~# echo icmp_rcv >set_ftrace_filter
 ~# echo function >current_tracer
 ~# echo 1 >options/func-args
 ~# ping -c 10 127.0.0.1
[..]
 ~# cat trace
[..]
            ping-1277    [030] ..s1.    39.120939: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    39.120946: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    40.179724: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    40.179730: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    41.219700: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    41.219706: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    42.259717: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    42.259725: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    43.299735: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    43.299742: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu

function graph:

 ~# cd /sys/kernel/tracing
 ~# echo icmp_rcv >set_graph_function
 ~# echo function_graph >current_tracer
 ~# echo 1 >options/funcgraph-args

 ~# ping -c 1 127.0.0.1

 ~# cat trace

 30)               |  icmp_rcv(skb=0xa0ecab00) {
 30)               |    __skb_checksum_complete(skb=0xa0ecab00) {
 30)               |      skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0) {
 30)               |        __skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0, ops=0x232e0327a88) {
 30)   0.418 us    |          csum_partial(buff=0xa0d20924, len=64, sum=0)
 30)   0.985 us    |        }
 30)   1.463 us    |      }
 30)   2.039 us    |    }
[..]

This was last posted by Sven Schnelle here:

  https://lore.kernel.org/all/20240904065908.1009086-1-svens@linux.ibm.com/

As Sven hasn't worked on it since, I decided to continue to push it
through. I'm keeping Sven as original author and added myself as
"Co-developed-by".

The main changes are:

- Made the kconfig option unconditional if all the dependencies are set.

- Not save ftrace_regs in the ring buffer, as that is an abstract
  descriptor defined by the architectures and should remain opaque from
  generic code. Instead, the args are read at the time they are recorded
  (with the ftrace_regs passed to the callback function), and saved into
  the ring buffer. Then the print function only takes an array of elements.

  This could allow archs to retrieve arguments that are on the stack where
  as, post processing ftrace_regs could cause undesirable results.

- Made the function and function graph entry events dynamically sized
  to allow the arguments to be appended to the event in the ring buffer.
  The print function only looks to see if the event saved in the ring
  buffer is big enough to hold all the arguments defined by the new
  FTRACE_REGS_MAX_ARGS macro and if so, it will assume there are arguments
  there and print them. This also means user space will not break on
  reading these events as arguments will simply be ignored.

- The printing of the arguments has some more data when things are not
  processed by BPF. Any unsupported argument will have the type printed
  out in the ring buffer. 

- Also removed the spaces around the '=' as that's more in line to how
  trace events show their fields.

- One new patch I added to convert function graph tracing over to using
  args as soon as the user sets the option even if function graph tracing
  is enabled. Function tracer did this already by default.

Steven Rostedt (1):
      ftrace: Have funcgraph-args take affect during tracing

Sven Schnelle (3):
      ftrace: Add print_function_args()
      ftrace: Add support for function argument to graph tracer
      ftrace: Add arguments to function tracer

----
 include/linux/ftrace_regs.h          |   5 +
 kernel/trace/Kconfig                 |  12 +++
 kernel/trace/trace.c                 |  12 ++-
 kernel/trace/trace.h                 |   4 +-
 kernel/trace/trace_entries.h         |  12 ++-
 kernel/trace/trace_functions.c       |  46 ++++++++-
 kernel/trace/trace_functions_graph.c | 174 ++++++++++++++++++++++++++++-------
 kernel/trace/trace_irqsoff.c         |   4 +-
 kernel/trace/trace_output.c          |  96 ++++++++++++++++++-
 kernel/trace/trace_output.h          |   9 ++
 kernel/trace/trace_sched_wakeup.c    |   4 +-
 11 files changed, 324 insertions(+), 54 deletions(-)
Re: [PATCH v2 0/4] ftrace: Add function arguments to function tracers
Posted by Jiri Olsa 1 year, 1 month ago
On Mon, Dec 23, 2024 at 03:13:47PM -0500, Steven Rostedt wrote:
> 
> These patches add support for printing function arguments in ftrace.
> 
> Example usage:
> 
> function tracer:
> 
>  ~# cd /sys/kernel/tracing/
>  ~# echo icmp_rcv >set_ftrace_filter
>  ~# echo function >current_tracer
>  ~# echo 1 >options/func-args
>  ~# ping -c 10 127.0.0.1
> [..]
>  ~# cat trace
> [..]
>             ping-1277    [030] ..s1.    39.120939: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    39.120946: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    40.179724: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    40.179730: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    41.219700: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    41.219706: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    42.259717: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    42.259725: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    43.299735: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
>             ping-1277    [030] ..s1.    43.299742: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
> 
> function graph:
> 
>  ~# cd /sys/kernel/tracing
>  ~# echo icmp_rcv >set_graph_function
>  ~# echo function_graph >current_tracer
>  ~# echo 1 >options/funcgraph-args
> 
>  ~# ping -c 1 127.0.0.1
> 
>  ~# cat trace
> 
>  30)               |  icmp_rcv(skb=0xa0ecab00) {
>  30)               |    __skb_checksum_complete(skb=0xa0ecab00) {
>  30)               |      skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0) {
>  30)               |        __skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0, ops=0x232e0327a88) {
>  30)   0.418 us    |          csum_partial(buff=0xa0d20924, len=64, sum=0)
>  30)   0.985 us    |        }
>  30)   1.463 us    |      }
>  30)   2.039 us    |    }
> [..]
> 
> This was last posted by Sven Schnelle here:
> 
>   https://lore.kernel.org/all/20240904065908.1009086-1-svens@linux.ibm.com/
> 
> As Sven hasn't worked on it since, I decided to continue to push it
> through. I'm keeping Sven as original author and added myself as
> "Co-developed-by".
> 
> The main changes are:
> 
> - Made the kconfig option unconditional if all the dependencies are set.
> 
> - Not save ftrace_regs in the ring buffer, as that is an abstract
>   descriptor defined by the architectures and should remain opaque from
>   generic code. Instead, the args are read at the time they are recorded
>   (with the ftrace_regs passed to the callback function), and saved into
>   the ring buffer. Then the print function only takes an array of elements.
> 
>   This could allow archs to retrieve arguments that are on the stack where
>   as, post processing ftrace_regs could cause undesirable results.
> 
> - Made the function and function graph entry events dynamically sized
>   to allow the arguments to be appended to the event in the ring buffer.
>   The print function only looks to see if the event saved in the ring
>   buffer is big enough to hold all the arguments defined by the new
>   FTRACE_REGS_MAX_ARGS macro and if so, it will assume there are arguments
>   there and print them. This also means user space will not break on
>   reading these events as arguments will simply be ignored.
> 
> - The printing of the arguments has some more data when things are not
>   processed by BPF. Any unsupported argument will have the type printed
>   out in the ring buffer. 
> 
> - Also removed the spaces around the '=' as that's more in line to how
>   trace events show their fields.
> 
> - One new patch I added to convert function graph tracing over to using
>   args as soon as the user sets the option even if function graph tracing
>   is enabled. Function tracer did this already by default.
> 
> Steven Rostedt (1):
>       ftrace: Have funcgraph-args take affect during tracing
> 
> Sven Schnelle (3):
>       ftrace: Add print_function_args()
>       ftrace: Add support for function argument to graph tracer
>       ftrace: Add arguments to function tracer

hi,
what branch is this based on? can't find any that would apply patch#2
without conflict.

thanks,
jirka

> 
> ----
>  include/linux/ftrace_regs.h          |   5 +
>  kernel/trace/Kconfig                 |  12 +++
>  kernel/trace/trace.c                 |  12 ++-
>  kernel/trace/trace.h                 |   4 +-
>  kernel/trace/trace_entries.h         |  12 ++-
>  kernel/trace/trace_functions.c       |  46 ++++++++-
>  kernel/trace/trace_functions_graph.c | 174 ++++++++++++++++++++++++++++-------
>  kernel/trace/trace_irqsoff.c         |   4 +-
>  kernel/trace/trace_output.c          |  96 ++++++++++++++++++-
>  kernel/trace/trace_output.h          |   9 ++
>  kernel/trace/trace_sched_wakeup.c    |   4 +-
>  11 files changed, 324 insertions(+), 54 deletions(-)
>
Re: [PATCH v2 0/4] ftrace: Add function arguments to function tracers
Posted by Steven Rostedt 1 year, 1 month ago
On Wed, 25 Dec 2024 22:40:53 +0100
Jiri Olsa <olsajiri@gmail.com> wrote:

> hi,
> what branch is this based on? can't find any that would apply patch#2
> without conflict.

Sorry, I should have mentioned in the cover letter, that this is based
on v6.13-rc4 with Masami's fprobe patchset applied:

  https://lore.kernel.org/linux-trace-kernel/173379652547.973433.2311391879173461183.stgit@devnote2/

-- Steve