Fprobe-based Event Tracing

개요

이 문서는 GPL-2.0 조건을 따르며 Masami Hiramatsu가 작성했다.

fprobe event는 kprobe event와 비슷하지만 function entry와 exit만 탐사한다. 일부 특정 function만 trace하는 많은 use case에는 이 제한으로도 충분하다.

tracepoint probe event인 tprobe도 tracepoint entry에서만 동작하므로 이 문서에서 함께 다룬다. 사용자는 tracepoint argument 일부를 추적하거나, trace-event로 노출되지 않아 tracefs에서 보이지 않는 tracepoint 자체를 추적할 수 있다.

다른 dynamic event와 마찬가지로 fprobe event와 tracepoint probe event는 tracefs의 `dynamic_events` interface 파일을 통해 정의한다.

.. SPDX-License-Identifier: GPL-2.0

==========================
Fprobe-based Event Tracing
==========================

.. Author: Masami Hiramatsu <mhiramat@kernel.org>

Overview
--------

Fprobe event is similar to the kprobe event, but limited to probe on
the function entry and exit only. It is good enough for many use cases
which only traces some specific functions.

This document also covers tracepoint probe events (tprobe) since this
is also works only on the tracepoint entry. User can trace a part of
tracepoint argument, or the tracepoint without trace-event, which is
not exposed on tracefs.

As same as other dynamic events, fprobe events and tracepoint probe
events are defined via `dynamic_events` interface file on tracefs.

Fprobe event 문법

function entry probe는 `f[:[GRP1/][EVENT1]] SYM [FETCHARGS]`, function exit probe는 `f[MAXACTIVE][:[GRP1/][EVENT1]] SYM%return [FETCHARGS]`, tracepoint probe는 `t[:[GRP2/][EVENT2]] TRACEPOINT [FETCHARGS]` 형식으로 정의한다.

`GRP1`을 생략하면 fprobe group은 `fprobes`다. `GRP2`를 생략하면 tprobe group은 `tracepoints`다.

fprobe `EVENT1`을 생략하면 event 이름은 `SYM__entry` 또는 `SYM__exit`가 된다. tprobe `EVENT2`를 생략하면 `TRACEPOINT` 이름을 그대로 쓰지만 tracepoint 이름이 숫자로 시작하면 앞에 `_`를 붙인다.

`MAXACTIVE`는 동시에 탐사할 수 있는 해당 function instance의 최대 수다. `0`은 `Documentation/trace/fprobe.rst`에 정의된 기본값을 사용한다.

각 probe에는 `FETCHARGS`를 최대 128개까지 둘 수 있다. BTF가 활성화된 function entry 또는 tracepoint에서는 argument 이름 `ARG`로 가져올 수 있다. `@ADDR`는 kernel address의 memory를, `@SYM[+|-offs]`는 data symbol 기준 offset의 memory를 읽는다.

`$stackN`은 0부터 세는 N번째 stack entry를, `$stack`은 stack address를 가져온다. `$argN`은 1부터 세는 N번째 function argument를 가져오며 offset 0의 function entry probe에서만 사용할 수 있다. register로 전달된 argument만 지원하므로 best-effort다.

`$retval`은 return probe에서 return value를 best-effort로 가져온다. 반환 type에 따라 register 쌍으로 전달될 수 있지만 이 기능은 register 하나만 읽는다. `$comm`은 current task의 command name을 가져온다.

`+|-[u]OFFS(FETCHARG)`는 `FETCHARG`가 가리키는 address에 offset을 더하거나 빼 memory를 읽으며 structure field를 가져올 때 유용하다. `u`는 user-space dereference를 뜻한다. `\IMM`은 immediate value를 저장한다.

`NAME=FETCHARG`는 argument 이름을 지정한다. `FETCHARG:TYPE`은 type을 지정하며 기본 integer type, hexadecimal type, `char`, `string`, `ustring`, `symbol`, `symstr`, bitfield를 지원한다. TYPE 상세는 kprobetrace 문서의 type 절을 참조한다.

Synopsis of fprobe-events
-------------------------
::

  f[:[GRP1/][EVENT1]] SYM [FETCHARGS]                       : Probe on function entry
  f[MAXACTIVE][:[GRP1/][EVENT1]] SYM%return [FETCHARGS]     : Probe on function exit
  t[:[GRP2/][EVENT2]] TRACEPOINT [FETCHARGS]                : Probe on tracepoint

 GRP1           : Group name for fprobe. If omitted, use "fprobes" for it.
 GRP2           : Group name for tprobe. If omitted, use "tracepoints" for it.
 EVENT1         : Event name for fprobe. If omitted, the event name is
                  "SYM__entry" or "SYM__exit".
 EVENT2         : Event name for tprobe. If omitted, the event name is
                  the same as "TRACEPOINT", but if the "TRACEPOINT" starts
                  with a digit character, "_TRACEPOINT" is used.
 MAXACTIVE      : Maximum number of instances of the specified function that
                  can be probed simultaneously, or 0 for the default value
                  as defined in Documentation/trace/fprobe.rst

 FETCHARGS      : Arguments. Each probe can have up to 128 args.
  ARG           : Fetch "ARG" function argument using BTF (only for function
                  entry or tracepoint.) (\*1)
  @ADDR         : Fetch memory at ADDR (ADDR should be in kernel)
  @SYM[+|-offs] : Fetch memory at SYM +|- offs (SYM should be a data symbol)
  $stackN       : Fetch Nth entry of stack (N >= 0)
  $stack        : Fetch stack address.
  $argN         : Fetch the Nth function argument. (N >= 1) (\*2)
  $retval       : Fetch return value.(\*3)
  $comm         : Fetch current task comm.
  +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*4)(\*5)
  \IMM          : Store an immediate value to the argument.
  NAME=FETCHARG : Set NAME as the argument name of FETCHARG.
  FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types
                  (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types
                  (x8/x16/x32/x64), "char", "string", "ustring", "symbol", "symstr"
                  and bitfield are supported.

  (\*1) This is available only when BTF is enabled.
  (\*2) only for the probe on function entry (offs == 0). Note, this argument access
        is best effort, because depending on the argument type, it may be passed on
        the stack. But this only support the arguments via registers.
  (\*3) only for return probe. Note that this is also best effort. Depending on the
        return value type, it might be passed via a pair of registers. But this only
        accesses one register.
  (\*4) this is useful for fetching a field of data structures.
  (\*5) "u" means user-space dereference.

For the details of TYPE, see :ref:`kprobetrace documentation <kprobetrace_types>`.

Exit에서 function argument 접근

exit probe에서도 `$arg<N>` fetcharg로 function argument에 접근할 수 있다. 이를 이용하면 function parameter와 return value를 한 event에서 함께 기록할 수 있다.

structure 초기화 함수가 전달받은 structure를 올바르게 갱신했는지 debug할 때처럼, entry와 exit 사이의 structure field 차이를 추적하는 데 유용하다. 동작 예제는 아래 return-probe sample을 참조한다.

Function arguments at exit
--------------------------
Function arguments can be accessed at exit probe using $arg<N> fetcharg. This
is useful to record the function parameter and return value at once, and
trace the difference of structure fields (for debugging a function whether it
correctly updates the given data structure or not)
See the :ref:`sample<fprobetrace_exit_args_sample>` below for how it works.

BTF argument

BTF(BPF Type Format) argument를 사용하면 `$argN` 대신 이름으로 function과 tracepoint parameter를 추적할 수 있다. kernel에 `CONFIG_BPF_SYSCALL`과 `CONFIG_DEBUG_INFO_BTF`가 설정돼 있어야 한다.

BTF argument 이름만 지정하면 event argument 이름도 자동으로 같은 이름으로 설정된다. 예시의 `vfs_read count pos`는 `count=count pos=pos`로 확장된다.

fetch type도 BTF 정보에서 고른다. 예시에서 `count`는 unsigned long이고 `pos`는 pointer라 둘 다 64-bit unsigned long field가 되지만, pointer인 `pos`에만 hexadecimal `%Lx` print format이 적용된다.

argument 이름을 모르면 `$arg*`를 사용한다. 이 표기는 function 또는 tracepoint의 모든 argument로 확장된다. `vfs_read $arg*`는 `file`, `buf`, `count`, `pos`를 각각 이름이 붙은 fetch argument로 만든다.

BTF는 `$retval`에도 적용된다. 사용자가 type을 지정하지 않으면 BTF에서 return type을 자동 선택한다. function이 `void`를 반환하면 `$retval`은 거부된다.

pointer type의 structure field는 `->`, structure value의 field는 `.`로 접근한다. 두 operator를 `foo->bar.baz->qux`처럼 결합해 더 깊은 member와 member가 가리키는 다른 structure에 접근할 수 있다.

anonymous union member는 C code와 마찬가지로 union 이름 없이 직접 접근한다. 예시 structure의 `a`, `b`는 `foo->a`, `foo->b`로 읽는다. return value도 `$retval->name`처럼 field에 접근할 수 있다.

BTF argument나 field에 `:string` 또는 `:ustring`을 적용하면 BTF type이 `char *` 또는 `char []`인지 검사하고, 아니면 string type 적용을 거부한다.

BTF를 사용하면 pointer가 가리키는 string을 읽기 위해 `+0(PTR)` memory dereference를 직접 적을 필요가 없다. BTF type에 맞춰 자동으로 dereference를 추가한다. embedded char array인 `prev->comm`과 structure 안의 char pointer인 `$retval->name` 모두 `:string`으로 가져올 수 있다.

BTF arguments
-------------
BTF (BPF Type Format) argument allows user to trace function and tracepoint
parameters by its name instead of ``$argN``. This feature is available if the
kernel is configured with CONFIG_BPF_SYSCALL and CONFIG_DEBUG_INFO_BTF.
If user only specify the BTF argument, the event's argument name is also
automatically set by the given name. ::

 # echo 'f:myprobe vfs_read count pos' >> dynamic_events
 # cat dynamic_events
 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 ::

 # cat events/fprobes/myprobe/format
 name: myprobe
 ID: 1313
 format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:unsigned long __probe_ip;	offset:8;	size:8;	signed:0;
	field:u64 count;	offset:16;	size:8;	signed:0;
	field:u64 pos;	offset:24;	size:8;	signed:0;

 print fmt: "(%lx) count=%Lu pos=0x%Lx", REC->__probe_ip, REC->count, REC->pos

If user unsures the name of arguments, ``$arg*`` will be helpful. The ``$arg*``
is expanded to all function arguments of the function or the tracepoint. ::

 # echo 'f:myprobe vfs_read $arg*' >> dynamic_events
 # 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.

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

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

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

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

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.

사용 예제

첫 예제는 BTF argument를 사용해 `vfs_read()` entry와 exit에 fprobe event를 추가한다. entry에서는 `$arg*`로 모든 argument를 기록하고 exit에서는 `$retval`을 기록한다. 기본 이름은 `vfs_read__entry`, `vfs_read__exit`가 된다.

`events/fprobes/enable`을 켠 뒤 trace를 읽으면 각 call의 `file`, `buf`, `count`, `pos`와 return value가 entry·exit record로 짝을 이뤄 나타난다. 예제에서는 function argument와 return value가 모두 signed integer 형태로 기록된 것을 볼 수 있다.

두 번째 예제는 `sched_switch` tracepoint에 `$arg*` tprobe를 추가하고 비교를 위해 기존 `sched/sched_switch` trace event도 함께 활성화한다.

기존 `sched_switch` trace event는 가공된 cooked parameter를 보여 주지만 tracepoint probe event는 raw parameter를 보여 준다. 따라서 raw `prev`, `next` argument가 가리키는 `task_struct`의 임의 field에 접근할 수 있다.

보통 trace되지 않는 `task_struct::start_time`도 `comm=next->comm:string next->start_time`처럼 지정해 기록할 수 있다. 출력에는 다음 task의 command name과 `start_time`이 함께 나타난다.

return probe는 error code를 반환하면서 실제 결과를 function parameter로 전달하는 structure 초기화 함수의 결과를 조사할 때 유용하다.

`vfs_open()`은 file structure를 inode에 연결하고 mode를 갱신한다. entry와 `%return` 양쪽에서 `file->f_mode`와 `file->f_inode`를 읽으면 entry에서는 inode가 비어 있고, exit에서는 mode와 inode pointer가 갱신된 것을 확인할 수 있다.

Usage examples
--------------
Here is an example to add fprobe events on ``vfs_read()`` function entry
and exit, with BTF arguments.
::

  # echo 'f vfs_read $arg*' >> dynamic_events
  # echo 'f vfs_read%return $retval' >> dynamic_events
  # cat dynamic_events
 f:fprobes/vfs_read__entry vfs_read file=file buf=buf count=count pos=pos
 f:fprobes/vfs_read__exit vfs_read%return arg1=$retval
  # echo 1 > events/fprobes/enable
  # head -n 20 trace | tail
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
               sh-70      [000] ...1.   335.883195: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
               sh-70      [000] .....   335.883208: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
               sh-70      [000] ...1.   335.883220: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
               sh-70      [000] .....   335.883224: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
               sh-70      [000] ...1.   335.883232: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c687a count=1 pos=0xffffc900005aff08
               sh-70      [000] .....   335.883237: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
               sh-70      [000] ...1.   336.050329: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
               sh-70      [000] .....   336.050343: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1

You can see all function arguments and return values are recorded as signed int.

Also, here is an example of tracepoint events on ``sched_switch`` tracepoint.
To compare the result, this also enables the ``sched_switch`` traceevent too.
::

  # echo 't sched_switch $arg*' >> dynamic_events
  # echo 1 > events/sched/sched_switch/enable
  # echo 1 > events/tracepoints/sched_switch/enable
  # echo > trace
  # head -n 20 trace | tail
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
               sh-70      [000] d..2.  3912.083993: sched_switch: prev_comm=sh prev_pid=70 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
               sh-70      [000] d..3.  3912.083995: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff88800664e100 next=0xffffffff828229c0 prev_state=1
           <idle>-0       [000] d..2.  3912.084183: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=16 next_prio=120
           <idle>-0       [000] d..3.  3912.084184: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0
      rcu_preempt-16      [000] d..2.  3912.084196: sched_switch: prev_comm=rcu_preempt prev_pid=16 prev_prio=120 prev_state=I ==> next_comm=swapper/0 next_pid=0 next_prio=120
      rcu_preempt-16      [000] d..3.  3912.084196: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff888004208000 next=0xffffffff828229c0 prev_state=1026
           <idle>-0       [000] d..2.  3912.085191: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=16 next_prio=120
           <idle>-0       [000] d..3.  3912.085191: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0

As you can see, the ``sched_switch`` trace-event shows *cooked* parameters, on
the other hand, the ``sched_switch`` tracepoint probe event shows *raw*
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 that field as below.
::

  # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events
  # head -n 20 trace | tail
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
               sh-70      [000] d..3.  5606.686577: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000
      rcu_preempt-16      [000] d..3.  5606.686602: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="sh" usage=1 start_time=1596095526
               sh-70      [000] d..3.  5606.686637: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
           <idle>-0       [000] d..3.  5606.687190: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000
      rcu_preempt-16      [000] d..3.  5606.687202: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
           <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

.. _fprobetrace_exit_args_sample:

The return probe allows us to access the results of some functions, which returns
the error code and its results are passed via function parameter, such as an
structure-initialization function.

For example, vfs_open() will link the file structure to the inode and update
mode. You can trace that changes with return probe.
::

 # echo 'f vfs_open mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events
 # echo 'f vfs_open%%return mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events
 # echo 1 > events/fprobes/enable
 # cat trace
              sh-131     [006] ...1.  1945.714346: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x2 inode=0x0
              sh-131     [006] ...1.  1945.714358: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4d801e inode=0xffff888008470168
             cat-143     [007] ...1.  1945.717949: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0
             cat-143     [007] ...1.  1945.717956: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4a801d inode=0xffff888005f78d28
             cat-143     [007] ...1.  1945.720616: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0
             cat-143     [007] ...1.  1945.728263: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0xa800d inode=0xffff888004ada8d8

You can see the `file::f_mode` and `file::f_inode` are updated in `vfs_open()`.