Kprobe 기반 Event Tracing

개요와 활성화

Kprobe event는 tracepoint event와 비슷하지만 tracepoint 대신 kprobe와 kretprobe를 기반으로 한다. 따라서 `__kprobes`·`nokprobe_inline` annotation이 있거나 `NOKPROBE_SYMBOL`로 표시된 function을 제외하면 Kprobes가 허용하는 모든 위치를 probe할 수 있다. 정적 tracepoint event와 달리 실행 중 동적으로 추가·제거할 수 있다.

기능을 사용하려면 `CONFIG_KPROBE_EVENTS=y`로 kernel을 build한다. Event tracer처럼 `current_tracer`로 활성화할 필요는 없다. `/sys/kernel/tracing/kprobe_events`에 probe point를 추가하고 `/sys/kernel/tracing/events/kprobes/<EVENT>/enable`로 event를 켠다.

`kprobe_events` 대신 `/sys/kernel/tracing/dynamic_events`를 사용해도 된다. 이 interface는 다른 dynamic event까지 통합해 접근하게 한다.

==========================
Kprobe-based Event Tracing
==========================

:Author: Masami Hiramatsu

Overview
--------
These events are similar to tracepoint-based events. Instead of tracepoints,
this is based on kprobes (kprobe and kretprobe). So it can probe wherever
kprobes can probe (this means, all functions except those with
__kprobes/nokprobe_inline annotation and those marked NOKPROBE_SYMBOL).
Unlike the tracepoint-based event, this can be added and removed
dynamically, on the fly.

To enable this feature, build your kernel with CONFIG_KPROBE_EVENTS=y.

Similar to the event tracer, this doesn't need to be activated via
current_tracer. Instead of that, add probe points via
/sys/kernel/tracing/kprobe_events, and enable it via
/sys/kernel/tracing/events/kprobes/<EVENT>/enable.

You can also use /sys/kernel/tracing/dynamic_events instead of
kprobe_events. That interface will provide unified access to other
dynamic events too.

`kprobe_events` 문법과 fetcharg

::

  p[:[GRP/][EVENT]] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS]	: Set a probe
  r[MAXACTIVE][:[GRP/][EVENT]] [MOD:]SYM[+0] [FETCHARGS]	: Set a return probe
  p[:[GRP/][EVENT]] [MOD:]SYM[+0]%return [FETCHARGS]	: Set a return probe
  -:[GRP/][EVENT]						: Clear a probe

 GRP		: Group name. If omitted, use "kprobes" for it.
 EVENT		: Event name. If omitted, the event name is generated
		  based on SYM+offs or MEMADDR.
 MOD		: Module name which has given SYM.
 SYM[+offs]	: Symbol+offset where the probe is inserted.
 SYM%return	: Return address of the symbol
 MEMADDR	: Address where the probe is inserted.
 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/kprobes.rst section 1.3.1.

 FETCHARGS	: Arguments. Each probe can have up to 128 args.
  %REG		: Fetch register REG
  @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) (\*1)
  $retval	: Fetch return value.(\*2)
  $comm		: Fetch current task comm.
  +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*3)(\*4)
  \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), VFS layer common type(%pd/%pD), "char",
                  "string", "ustring", "symbol", "symstr" and bitfield are
                  supported.

`p`는 일반 probe, `r[MAXACTIVE]` 또는 `%return`은 return probe를 만들고 `-:`는 지정 event를 지운다. Group을 생략하면 `kprobes`를 사용하며 event 이름을 생략하면 symbol·offset 또는 memory address에서 자동 생성한다. `MOD:`는 symbol이 속한 module을 지정한다.

`MAXACTIVE`는 동시에 추적할 function instance 최대 수이며 0은 `Documentation/trace/kprobes.rst`에 정의된 기본값을 사용한다. Probe마다 fetch argument를 최대 128개 지정할 수 있다.

`$argN`은 function entry와 offset 0에서만, `$retval`은 return probe에서만 쓸 수 있다. 두 접근 모두 ABI와 value type에 따라 register 하나로는 완전하지 않을 수 있다. Dereference의 `u`는 user-space address를 뜻한다.

Synopsis of kprobe_events
-------------------------
::

  p[:[GRP/][EVENT]] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS]	: Set a probe
  r[MAXACTIVE][:[GRP/][EVENT]] [MOD:]SYM[+0] [FETCHARGS]	: Set a return probe
  p[:[GRP/][EVENT]] [MOD:]SYM[+0]%return [FETCHARGS]	: Set a return probe
  -:[GRP/][EVENT]						: Clear a probe

 GRP		: Group name. If omitted, use "kprobes" for it.
 EVENT		: Event name. If omitted, the event name is generated
		  based on SYM+offs or MEMADDR.
 MOD		: Module name which has given SYM.
 SYM[+offs]	: Symbol+offset where the probe is inserted.
 SYM%return	: Return address of the symbol
 MEMADDR	: Address where the probe is inserted.
 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/kprobes.rst section 1.3.1.

 FETCHARGS	: Arguments. Each probe can have up to 128 args.
  %REG		: Fetch register REG
  @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) (\*1)
  $retval	: Fetch return value.(\*2)
  $comm		: Fetch current task comm.
  +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*3)(\*4)
  \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), VFS layer common type(%pd/%pD), "char",
                  "string", "ustring", "symbol", "symstr" and bitfield are
                  supported.

  (\*1) 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.
  (\*2) 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.
  (\*3) this is useful for fetching a field of data structures.
  (\*4) "u" means user-space dereference. See :ref:`user_mem_access`.

Function argument와 fetcharg type

Kretprobe에서도 `$argN`으로 function argument를 가져올 수 있다. Parameter와 return value를 한 event에서 기록하거나 function이 data structure field를 올바르게 갱신했는지 전후 차이를 추적할 때 유용하다. 동작 예는 fprobe exit-argument sample을 참조한다.

Fetcharg type의 `s`와 `u` prefix는 signed·unsigned decimal, `x`는 unsigned hexadecimal 출력을 뜻한다. Cast가 없으면 architecture에 따라 `x32` 또는 `x64`를 사용한다.

Base type 뒤에 `[N]`을 붙이면 64개 미만의 고정 길이 array를 기록한다. 예를 들어 `x16[4]`는 2-byte hexadecimal element 4개다. Array는 memory fetcharg에만 적용할 수 있어 `$stack1:x8[8]`은 틀리고 `+8($stack):x8[8]`은 유효하다.

`char`는 character value를 표시한다. `string`은 kernel space의 null-terminated string을 가져오며 page-out된 container에서는 실패해 `NULL`을 저장한다. User space에는 `ustring`을 사용한다.

`string[1]`은 일반 base type array와 달리 `string`과 같지 않다. `string`은 char array를, string array는 `char *` array를 나타낸다. 따라서 `+0(%di):string[1]`은 `+0(+0(%di)):string`과 같다.

Bitfield is another special type, which takes 3 parameters, bit-width, bit-
offset, and container-size (usually 32). The syntax is::

 b<bit-width>@<bit-offset>/<container-size>

Bitfield type은 bit width, bit offset, 보통 32인 container size를 받는다. `symbol`은 `BITS_PER_LONG`에 따른 u32/u64 alias이며 pointer를 `symbol+offset`으로 표시한다. `symstr`은 address를 `symbol+offset/symbolsize` 문자열로 변환해 wildcard symbol filter를 가능하게 한다.

`$comm`의 기본 type은 `string`이고 다른 type은 사용할 수 없다. `%pd`와 `%pD`는 각각 `struct dentry`와 `struct file` address에서 VFS layer name을 가져온다.

Function arguments at kretprobe
-------------------------------
Function arguments can be accessed at kretprobe 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>` in fprobe event for how
it works.

.. _kprobetrace_types:

Types
-----
Several types are supported for fetchargs. Kprobe tracer will access memory
by given type. Prefix 's' and 'u' means those types are signed and unsigned
respectively. 'x' prefix implies it is unsigned. Traced arguments are shown
in decimal ('s' and 'u') or hexadecimal ('x'). Without type casting, 'x32'
or 'x64' is used depends on the architecture (e.g. x86-32 uses x32, and
x86-64 uses x64).

These value types can be an array. To record array data, you can add '[N]'
(where N is a fixed number, less than 64) to the base type.
E.g. 'x16[4]' means an array of x16 (2-byte hex) with 4 elements.
Note that the array can be applied to memory type fetchargs, you can not
apply it to registers/stack-entries etc. (for example, '$stack1:x8[8]' is
wrong, but '+8($stack):x8[8]' is OK.)

Char type can be used to show the character value of traced arguments.

String type is a special type, which fetches a "null-terminated" string from
kernel space. This means it will fail and store NULL if the string container
has been paged out. "ustring" type is an alternative of string for user-space.
See :ref:`user_mem_access` for more info.

The string array type is a bit different from other types. For other base
types, <base-type>[1] is equal to <base-type> (e.g. +0(%di):x32[1] is same
as +0(%di):x32.) But string[1] is not equal to string. The string type itself
represents "char array", but string array type represents "char * array".
So, for example, +0(%di):string[1] is equal to +0(+0(%di)):string.
Bitfield is another special type, which takes 3 parameters, bit-width, bit-
offset, and container-size (usually 32). The syntax is::

 b<bit-width>@<bit-offset>/<container-size>

Symbol type('symbol') is an alias of u32 or u64 type (depends on BITS_PER_LONG)
which shows given pointer in "symbol+offset" style.
On the other hand, symbol-string type ('symstr') converts the given address to
"symbol+offset/symbolsize" style and stores it as a null-terminated string.
With 'symstr' type, you can filter the event with wildcard pattern of the
symbols, and you don't need to solve symbol name by yourself.
For $comm, the default type is "string"; any other type is invalid.

VFS layer common type(%pd/%pD) is a special type, which fetches dentry's or
file's name from struct dentry's address or struct file's address.

User memory 접근

Kprobe event는 user-space dereference 문법과 `ustring` type으로 user memory를 읽는다. Dereference 앞에 `u`를 붙이면 user-space data structure field를 뜻한다.

예를 들어 `+u4(%si)`는 `%si + 4`의 user memory를 읽는다. `+u0(%si):string`은 `%si`가 가리키는 user string을 읽고, `+0(%si):ustring`도 같은 의미다.

Interface가 user-memory 문법을 제공한다고 해서 일반 dereference를 자동 변환하지는 않는다. User address에 일반 dereference나 `string`을 사용하면 실패할 수 있고 일부 architecture에서는 항상 실패한다. 대상 data가 kernel space인지 user space인지 사용자가 확인해야 한다.

.. _user_mem_access:

User Memory Access
------------------
Kprobe events supports user-space memory access. For that purpose, you can use
either user-space dereference syntax or 'ustring' type.

The user-space dereference syntax allows you to access a field of a data
structure in user-space. This is done by adding the "u" prefix to the
dereference syntax. For example, +u4(%si) means it will read memory from the
address in the register %si offset by 4, and the memory is expected to be in
user-space. You can use this for strings too, e.g. +u0(%si):string will read
a string from the address in the register %si that is expected to be in user-
space. 'ustring' is a shortcut way of performing the same task. That is,
+0(%si):ustring is equivalent to +u0(%si):string.

Note that kprobe-event provides the user-memory access syntax but it doesn't
use it transparently. This means if you use normal dereference or string type
for user memory, it might fail, and may always fail on some architectures. The
user has to carefully check if the target data is in kernel or user space.

Probe별 filter와 profiling

`p:`나 `r:` 바로 뒤에 event 이름을 지정하면 `tracing/events/kprobes/<EVENT>` directory가 생기고 각 probe에 서로 다른 filter를 적용할 수 있다. Directory에는 `id`, `enable`, `format`, `filter`, `trigger`가 있다.

`/sys/kernel/tracing/kprobe_profile`은 event별 총 probe hit와 miss-hit를 보여 준다. 첫 column은 event 이름, 둘째는 hit 수, 셋째는 miss-hit 수다.

Per-Probe Event Filtering
-------------------------
Per-probe event filtering feature allows you to set different filter on each
probe and gives you what arguments will be shown in trace buffer. If an event
name is specified right after 'p:' or 'r:' in kprobe_events, it adds an event
under tracing/events/kprobes/<EVENT>, at the directory you can see 'id',
'enable', 'format', 'filter' and 'trigger'.

enable:
  You can enable/disable the probe by writing 1 or 0 on it.

format:
  This shows the format of this probe event.

filter:
  You can write filtering rules of this event.

id:
  This shows the id of this probe event.

trigger:
  This allows to install trigger commands which are executed when the event is
  hit (for details, see Documentation/trace/events.rst, section 6).

Event Profiling
---------------
You can check the total number of probe hits and probe miss-hits via
/sys/kernel/tracing/kprobe_profile.
The first column is event name, the second is the number of probe hits,
the third is the number of probe miss-hits.

Kernel boot parameter

Boot 때 `kprobe_event=` parameter로 새 kprobe event를 추가하고 활성화할 수 있다. 여러 event는 semicolon으로 구분하며 형식은 `kprobe_events`와 비슷하지만 정의 parameter 사이를 space 대신 comma로 구분한다.

instead of space. For example, adding myprobe event on do_sys_open like below::

  p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)

should be below for kernel boot parameter (just replace spaces with comma)::

  p:myprobe,do_sys_open,dfd=%ax,filename=%dx,flags=%cx,mode=+4($stack)

Kernel Boot Parameter
---------------------
You can add and enable new kprobe events when booting up the kernel by
"kprobe_event=" parameter. The parameter accepts a semicolon-delimited
kprobe events, which format is similar to the kprobe_events.
The difference is that the probe definition parameters are comma-delimited
instead of space. For example, adding myprobe event on do_sys_open like below::

  p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)

should be below for kernel boot parameter (just replace spaces with comma)::

  p:myprobe,do_sys_open,dfd=%ax,filename=%dx,flags=%cx,mode=+4($stack)

사용 예제

새 event를 만들려면 definition을 `kprobe_events`에 쓴다. 다음 예는 `do_sys_open()` entry에 `myprobe`를 설치하고 1~4번째 argument를 기록한다.

  echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/tracing/kprobe_events

Function argument가 어느 register나 stack entry에 배치되는지는 architecture ABI에 달려 있다. 확실하지 않으면 `tools/perf/`의 probe subcommand를 사용한다. Fetcharg에 익숙한 field 이름을 붙일 수 있다.

  echo 'r:myretprobe do_sys_open $retval' >> /sys/kernel/tracing/kprobe_events

두 번째 정의는 `do_sys_open()` return point에 `myretprobe`를 설치하고 `$retval`을 기록한다. 생성 event의 schema는 `events/kprobes/<EVENT>/format`에서 확인한다.

  cat /sys/kernel/tracing/events/kprobes/myprobe/format
  name: myprobe
  ID: 780
  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:12;      size:4; signed:0;
          field:int __probe_nargs;        offset:16;      size:4; signed:1;
          field:unsigned long dfd;        offset:20;      size:4; signed:0;
          field:unsigned long filename;   offset:24;      size:4; signed:0;
          field:unsigned long flags;      offset:28;      size:4; signed:0;
          field:unsigned long mode;       offset:32;      size:4; signed:0;


  print fmt: "(%lx) dfd=%lx filename=%lx flags=%lx mode=%lx", REC->__probe_ip,
  REC->dfd, REC->filename, REC->flags, REC->mode

Format 출력에는 정의한 네 argument가 event field와 print format으로 나타난다. `kprobe_events` 파일을 비우면 모든 probe point를 지우고, `-:myprobe`를 append하면 해당 probe만 선택적으로 지운다.

::

  echo > /sys/kernel/tracing/kprobe_events

This clears all probe points.

Or,
::

  echo -:myprobe >> kprobe_events

정의 직후 event는 기본적으로 disabled이므로 각 event의 `enable`에 1을 써야 한다.

::

  echo 1 > /sys/kernel/tracing/events/kprobes/myprobe/enable
  echo 1 > /sys/kernel/tracing/events/kprobes/myretprobe/enable

`tracing_on`을 1과 0으로 바꿔 관심 interval만 기록하고 `trace` 파일에서 결과를 읽는다.

Use the following command to start tracing in an interval.
::

    # echo 1 > tracing_on
    Open something...
    # echo 0 > tracing_on

And you can see the traced information via /sys/kernel/tracing/trace.
::

  cat /sys/kernel/tracing/trace
  # tracer: nop
  #
  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
  #              | |       |          |         |
             <...>-1447  [001] 1038282.286875: myprobe: (do_sys_open+0x0/0xd6) dfd=3 filename=7fffd1ec4440 flags=8000 mode=0
             <...>-1447  [001] 1038282.286878: myretprobe: (sys_openat+0xc/0xe <- do_sys_open) $retval=fffffffffffffffe
             <...>-1447  [001] 1038282.286885: myprobe: (do_sys_open+0x0/0xd6) dfd=ffffff9c filename=40413c flags=8000 mode=1b6
             <...>-1447  [001] 1038282.286915: myretprobe: (sys_open+0x1b/0x1d <- do_sys_open) $retval=3
             <...>-1447  [001] 1038282.286969: myprobe: (do_sys_open+0x0/0xd6) dfd=ffffff9c filename=4041c6 flags=98800 mode=10
             <...>-1447  [001] 1038282.286976: myretprobe: (sys_open+0x1b/0x1d <- do_sys_open) $retval=3

각 trace line은 kernel이 event를 hit한 시점을 보여 준다. `<- SYMBOL`은 kernel이 그 symbol에서 return했음을 뜻한다. 예를 들어 `sys_open+0x1b/0x1d <- do_sys_open`은 `do_sys_open`에서 `sys_open+0x1b`로 return했다는 의미다.

Usage examples
--------------
To add a probe as a new event, write a new definition to kprobe_events
as below::

  echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/tracing/kprobe_events

This sets a kprobe on the top of do_sys_open() function with recording
1st to 4th arguments as "myprobe" event. Note, which register/stack entry is
assigned to each function argument depends on arch-specific ABI. If you unsure
the ABI, please try to use probe subcommand of perf-tools (you can find it
under tools/perf/).
As this example shows, users can choose more familiar names for each arguments.
::

  echo 'r:myretprobe do_sys_open $retval' >> /sys/kernel/tracing/kprobe_events

This sets a kretprobe on the return point of do_sys_open() function with
recording return value as "myretprobe" event.
You can see the format of these events via
/sys/kernel/tracing/events/kprobes/<EVENT>/format.
::

  cat /sys/kernel/tracing/events/kprobes/myprobe/format
  name: myprobe
  ID: 780
  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:12;      size:4; signed:0;
          field:int __probe_nargs;        offset:16;      size:4; signed:1;
          field:unsigned long dfd;        offset:20;      size:4; signed:0;
          field:unsigned long filename;   offset:24;      size:4; signed:0;
          field:unsigned long flags;      offset:28;      size:4; signed:0;
          field:unsigned long mode;       offset:32;      size:4; signed:0;


  print fmt: "(%lx) dfd=%lx filename=%lx flags=%lx mode=%lx", REC->__probe_ip,
  REC->dfd, REC->filename, REC->flags, REC->mode

You can see that the event has 4 arguments as in the expressions you specified.
::

  echo > /sys/kernel/tracing/kprobe_events

This clears all probe points.

Or,
::

  echo -:myprobe >> kprobe_events

This clears probe points selectively.

Right after definition, each event is disabled by default. For tracing these
events, you need to enable it.
::

  echo 1 > /sys/kernel/tracing/events/kprobes/myprobe/enable
  echo 1 > /sys/kernel/tracing/events/kprobes/myretprobe/enable

Use the following command to start tracing in an interval.
::

    # echo 1 > tracing_on
    Open something...
    # echo 0 > tracing_on

And you can see the traced information via /sys/kernel/tracing/trace.
::

  cat /sys/kernel/tracing/trace
  # tracer: nop
  #
  #           TASK-PID    CPU#    TIMESTAMP  FUNCTION
  #              | |       |          |         |
             <...>-1447  [001] 1038282.286875: myprobe: (do_sys_open+0x0/0xd6) dfd=3 filename=7fffd1ec4440 flags=8000 mode=0
             <...>-1447  [001] 1038282.286878: myretprobe: (sys_openat+0xc/0xe <- do_sys_open) $retval=fffffffffffffffe
             <...>-1447  [001] 1038282.286885: myprobe: (do_sys_open+0x0/0xd6) dfd=ffffff9c filename=40413c flags=8000 mode=1b6
             <...>-1447  [001] 1038282.286915: myretprobe: (sys_open+0x1b/0x1d <- do_sys_open) $retval=3
             <...>-1447  [001] 1038282.286969: myprobe: (do_sys_open+0x0/0xd6) dfd=ffffff9c filename=4041c6 flags=98800 mode=10
             <...>-1447  [001] 1038282.286976: myretprobe: (sys_open+0x1b/0x1d <- do_sys_open) $retval=3


Each line shows when the kernel hits an event, and <- SYMBOL means kernel
returns from SYMBOL(e.g. "sys_open+0x1b/0x1d <- do_sys_open" means kernel
returns from do_sys_open to sys_open+0x1b).