[v2] tracing: Improbe BTF support on probe events

[PATCH v2 9/9] Documentation: tracing: Update fprobe event example with BTF field

Posted by Masami Hiramatsu (Google) 2 years, 6 months ago

From: Masami Hiramatsu (Google) <mhiramat@kernel.org>

Update fprobe event example with BTF data structure field specification.

Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 Changes in v2:
  - Remove 'retval' and use '$retval'.
---
 Documentation/trace/fprobetrace.rst |   50 ++++++++++++++++++++++-------------
 1 file changed, 32 insertions(+), 18 deletions(-)

diff --git a/Documentation/trace/fprobetrace.rst b/Documentation/trace/fprobetrace.rst
index 7297f9478459..e9e764fadf14 100644
--- a/Documentation/trace/fprobetrace.rst
+++ b/Documentation/trace/fprobetrace.rst
@@ -79,9 +79,9 @@ automatically set by the given name. ::
  f:fprobes/myprobe vfs_read count=count pos=pos
 
 It also chooses the fetch type from BTF information. For example, in the above
-example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus, both
-are converted to 64bit unsigned long, but only ``pos`` has "%Lx" print-format as
-below ::
+example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus,
+both are converted to 64bit unsigned long, but only ``pos`` has "%Lx"
+print-format as below ::
 
  # cat events/fprobes/myprobe/format
  name: myprobe
@@ -105,9 +105,33 @@ is expanded to all function arguments of the function or the tracepoint. ::
  # cat dynamic_events
  f:fprobes/myprobe vfs_read file=file buf=buf count=count pos=pos
 
-BTF also affects the ``$retval``. If user doesn't set any type, the retval type is
-automatically picked from the BTF. If the function returns ``void``, ``$retval``
-is rejected.
+BTF also affects the ``$retval``. If user doesn't set any type, the retval
+type is automatically picked from the BTF. If the function returns ``void``,
+``$retval`` is rejected.
+
+You can access the data fields of a data structure using allow operator ``->``
+(for pointer type) and dot operator ``.`` (for data structure type.)::
+
+# echo 't sched_switch preempt prev_pid=prev->pid next_pid=next->pid' >> dynamic_events
+
+This data field access is available for the return value via ``$retval``,
+e.g. ``$retval->name``.
+
+For these BTF arguments and fields, ``:string`` and ``:ustring`` change the
+behavior. If these are used for BTF argument or field, it checks whether
+the BTF type of the argument or the data field is ``char *`` or ``char []``,
+or not.  If not, it rejects applying the string types. Also, with the BTF
+support, you don't need a memory dereference operator (``+0(PTR)``) for
+accessing the string pointed by a ``PTR``. It automatically adds the memory
+dereference operator according to the BTF type. e.g. ::
+
+# echo 't sched_switch prev->comm:string' >> dynamic_events
+# echo 'f getname_flags%return $retval->name:string' >> dynamic_events
+
+The ``prev->comm`` is an embedded char array in the data structure, and
+``$retval->name`` is a char pointer in the data structure. But in both
+cases, you can use ``:string`` type to get the string.
+
 
 Usage examples
 --------------
@@ -161,10 +185,10 @@ parameters. This means you can access any field values in the task
 structure pointed by the ``prev`` and ``next`` arguments.
 
 For example, usually ``task_struct::start_time`` is not traced, but with this
-traceprobe event, you can trace it as below.
+traceprobe event, you can trace that field as below.
 ::
 
-  # echo 't sched_switch comm=+1896(next):string start_time=+1728(next):u64' > dynamic_events
+  # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events
   # head -n 20 trace | tail
  #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
  #              | |         |   |||||     |         |
@@ -176,13 +200,3 @@ traceprobe event, you can trace it as below.
            <idle>-0       [000] d..3.  5606.690317: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
       kworker/0:1-14      [000] d..3.  5606.690339: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
            <idle>-0       [000] d..3.  5606.692368: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
-
-Currently, to find the offset of a specific field in the data structure,
-you need to build kernel with debuginfo and run `perf probe` command with
-`-D` option. e.g.
-::
-
- # perf probe -D "__probestub_sched_switch next->comm:string next->start_time"
- p:probe/__probestub_sched_switch __probestub_sched_switch+0 comm=+1896(%cx):string start_time=+1728(%cx):u64
-
-And replace the ``%cx`` with the ``next``.

Re: [PATCH v2 9/9] Documentation: tracing: Update fprobe event example with BTF field

Posted by Alan Maguire 2 years, 6 months ago

On 17/07/2023 16:24, Masami Hiramatsu (Google) wrote:
> From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 
> Update fprobe event example with BTF data structure field specification.
> 
> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>

One suggestion below, but

Reviewed-by: Alan Maguire <alan.maguire@oracle.com>

> ---
>  Changes in v2:
>   - Remove 'retval' and use '$retval'.
> ---
>  Documentation/trace/fprobetrace.rst |   50 ++++++++++++++++++++++-------------
>  1 file changed, 32 insertions(+), 18 deletions(-)
> 
> diff --git a/Documentation/trace/fprobetrace.rst b/Documentation/trace/fprobetrace.rst
> index 7297f9478459..e9e764fadf14 100644
> --- a/Documentation/trace/fprobetrace.rst
> +++ b/Documentation/trace/fprobetrace.rst
> @@ -79,9 +79,9 @@ automatically set by the given name. ::
>   f:fprobes/myprobe vfs_read count=count pos=pos
>  
>  It also chooses the fetch type from BTF information. For example, in the above
> -example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus, both
> -are converted to 64bit unsigned long, but only ``pos`` has "%Lx" print-format as
> -below ::
> +example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus,
> +both are converted to 64bit unsigned long, but only ``pos`` has "%Lx"
> +print-format as below ::
>  
>   # cat events/fprobes/myprobe/format
>   name: myprobe
> @@ -105,9 +105,33 @@ is expanded to all function arguments of the function or the tracepoint. ::
>   # cat dynamic_events
>   f:fprobes/myprobe vfs_read file=file buf=buf count=count pos=pos
>  
> -BTF also affects the ``$retval``. If user doesn't set any type, the retval type is
> -automatically picked from the BTF. If the function returns ``void``, ``$retval``
> -is rejected.
> +BTF also affects the ``$retval``. If user doesn't set any type, the retval
> +type is automatically picked from the BTF. If the function returns ``void``,
> +``$retval`` is rejected.
> +
> +You can access the data fields of a data structure using allow operator ``->``
> +(for pointer type) and dot operator ``.`` (for data structure type.)::
> +
> +# echo 't sched_switch preempt prev_pid=prev->pid next_pid=next->pid' >> dynamic_events
> +

Could you describe what field access combinations are supported here;
i.e. foo->bar[.baz]?

> +This data field access is available for the return value via ``$retval``,
> +e.g. ``$retval->name``.
> +
> +For these BTF arguments and fields, ``:string`` and ``:ustring`` change the
> +behavior. If these are used for BTF argument or field, it checks whether
> +the BTF type of the argument or the data field is ``char *`` or ``char []``,
> +or not.  If not, it rejects applying the string types. Also, with the BTF
> +support, you don't need a memory dereference operator (``+0(PTR)``) for
> +accessing the string pointed by a ``PTR``. It automatically adds the memory
> +dereference operator according to the BTF type. e.g. ::
> +
> +# echo 't sched_switch prev->comm:string' >> dynamic_events
> +# echo 'f getname_flags%return $retval->name:string' >> dynamic_events
> +
> +The ``prev->comm`` is an embedded char array in the data structure, and
> +``$retval->name`` is a char pointer in the data structure. But in both
> +cases, you can use ``:string`` type to get the string.
> +
>  
>  Usage examples
>  --------------
> @@ -161,10 +185,10 @@ parameters. This means you can access any field values in the task
>  structure pointed by the ``prev`` and ``next`` arguments.
>  
>  For example, usually ``task_struct::start_time`` is not traced, but with this
> -traceprobe event, you can trace it as below.
> +traceprobe event, you can trace that field as below.
>  ::
>  
> -  # echo 't sched_switch comm=+1896(next):string start_time=+1728(next):u64' > dynamic_events
> +  # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events
>    # head -n 20 trace | tail
>   #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
>   #              | |         |   |||||     |         |
> @@ -176,13 +200,3 @@ traceprobe event, you can trace it as below.
>             <idle>-0       [000] d..3.  5606.690317: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
>        kworker/0:1-14      [000] d..3.  5606.690339: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
>             <idle>-0       [000] d..3.  5606.692368: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
> -
> -Currently, to find the offset of a specific field in the data structure,
> -you need to build kernel with debuginfo and run `perf probe` command with
> -`-D` option. e.g.
> -::
> -
> - # perf probe -D "__probestub_sched_switch next->comm:string next->start_time"
> - p:probe/__probestub_sched_switch __probestub_sched_switch+0 comm=+1896(%cx):string start_time=+1728(%cx):u64
> -
> -And replace the ``%cx`` with the ``next``.
> 
>

Re: [PATCH v2 9/9] Documentation: tracing: Update fprobe event example with BTF field

Posted by Masami Hiramatsu (Google) 2 years, 6 months ago

On Thu, 20 Jul 2023 23:53:43 +0100
Alan Maguire <alan.maguire@oracle.com> wrote:

> On 17/07/2023 16:24, Masami Hiramatsu (Google) wrote:
> > From: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > 
> > Update fprobe event example with BTF data structure field specification.
> > 
> > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> 
> One suggestion below, but
> 
> Reviewed-by: Alan Maguire <alan.maguire@oracle.com>

Thanks,

> 
> > ---
> >  Changes in v2:
> >   - Remove 'retval' and use '$retval'.
> > ---
> >  Documentation/trace/fprobetrace.rst |   50 ++++++++++++++++++++++-------------
> >  1 file changed, 32 insertions(+), 18 deletions(-)
> > 
> > diff --git a/Documentation/trace/fprobetrace.rst b/Documentation/trace/fprobetrace.rst
> > index 7297f9478459..e9e764fadf14 100644
> > --- a/Documentation/trace/fprobetrace.rst
> > +++ b/Documentation/trace/fprobetrace.rst
> > @@ -79,9 +79,9 @@ automatically set by the given name. ::
> >   f:fprobes/myprobe vfs_read count=count pos=pos
> >  
> >  It also chooses the fetch type from BTF information. For example, in the above
> > -example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus, both
> > -are converted to 64bit unsigned long, but only ``pos`` has "%Lx" print-format as
> > -below ::
> > +example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus,
> > +both are converted to 64bit unsigned long, but only ``pos`` has "%Lx"
> > +print-format as below ::
> >  
> >   # cat events/fprobes/myprobe/format
> >   name: myprobe
> > @@ -105,9 +105,33 @@ is expanded to all function arguments of the function or the tracepoint. ::
> >   # cat dynamic_events
> >   f:fprobes/myprobe vfs_read file=file buf=buf count=count pos=pos
> >  
> > -BTF also affects the ``$retval``. If user doesn't set any type, the retval type is
> > -automatically picked from the BTF. If the function returns ``void``, ``$retval``
> > -is rejected.
> > +BTF also affects the ``$retval``. If user doesn't set any type, the retval
> > +type is automatically picked from the BTF. If the function returns ``void``,
> > +``$retval`` is rejected.
> > +
> > +You can access the data fields of a data structure using allow operator ``->``
> > +(for pointer type) and dot operator ``.`` (for data structure type.)::
> > +
> > +# echo 't sched_switch preempt prev_pid=prev->pid next_pid=next->pid' >> dynamic_events
> > +
> 
> Could you describe what field access combinations are supported here;
> i.e. foo->bar[.baz]?

OK, I'll add below.

The field access operators, ``->`` and ``.`` can be combined for accessing deeper
members and other stucture members pointed by the member. e.g. ``foo->bar.baz->qux``
If there is non-name union member, you can directly access it as C does. For example::

 struct {
 	union {
 	int a;
 	int b;
 	};
 } *foo;

To access ``a`` and ``b``, use ``foo->a`` and ``foo->b`` in this case.

Thank you,


> 
> > +This data field access is available for the return value via ``$retval``,
> > +e.g. ``$retval->name``.
> > +
> > +For these BTF arguments and fields, ``:string`` and ``:ustring`` change the
> > +behavior. If these are used for BTF argument or field, it checks whether
> > +the BTF type of the argument or the data field is ``char *`` or ``char []``,
> > +or not.  If not, it rejects applying the string types. Also, with the BTF
> > +support, you don't need a memory dereference operator (``+0(PTR)``) for
> > +accessing the string pointed by a ``PTR``. It automatically adds the memory
> > +dereference operator according to the BTF type. e.g. ::
> > +
> > +# echo 't sched_switch prev->comm:string' >> dynamic_events
> > +# echo 'f getname_flags%return $retval->name:string' >> dynamic_events
> > +
> > +The ``prev->comm`` is an embedded char array in the data structure, and
> > +``$retval->name`` is a char pointer in the data structure. But in both
> > +cases, you can use ``:string`` type to get the string.
> > +
> >  
> >  Usage examples
> >  --------------
> > @@ -161,10 +185,10 @@ parameters. This means you can access any field values in the task
> >  structure pointed by the ``prev`` and ``next`` arguments.
> >  
> >  For example, usually ``task_struct::start_time`` is not traced, but with this
> > -traceprobe event, you can trace it as below.
> > +traceprobe event, you can trace that field as below.
> >  ::
> >  
> > -  # echo 't sched_switch comm=+1896(next):string start_time=+1728(next):u64' > dynamic_events
> > +  # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events
> >    # head -n 20 trace | tail
> >   #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
> >   #              | |         |   |||||     |         |
> > @@ -176,13 +200,3 @@ traceprobe event, you can trace it as below.
> >             <idle>-0       [000] d..3.  5606.690317: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
> >        kworker/0:1-14      [000] d..3.  5606.690339: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
> >             <idle>-0       [000] d..3.  5606.692368: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
> > -
> > -Currently, to find the offset of a specific field in the data structure,
> > -you need to build kernel with debuginfo and run `perf probe` command with
> > -`-D` option. e.g.
> > -::
> > -
> > - # perf probe -D "__probestub_sched_switch next->comm:string next->start_time"
> > - p:probe/__probestub_sched_switch __probestub_sched_switch+0 comm=+1896(%cx):string start_time=+1728(%cx):u64
> > -
> > -And replace the ``%cx`` with the ``next``.
> > 
> > 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>