Eprobe - Event 기반 probe tracing

Eprobe 개요와 활성화

Eprobe는 기존 event 위에 배치하는 dynamic event다. pointer인 field를 역참조하거나 trace event에 기록할 field를 제한하는 데 사용한다.

Eprobe는 kprobe event에 의존하므로 kernel을 `CONFIG_EPROBE_EVENTS=y`로 build해야 한다. `/sys/kernel/tracing/dynamic_events` file을 통해 생성한다.

.. SPDX-License-Identifier: GPL-2.0

==================================
Eprobe - Event-based Probe Tracing
==================================

:Author: Steven Rostedt <rostedt@goodmis.org>

- Written for v6.17

Overview
========

Eprobes are dynamic events that are placed on existing events to either
dereference a field that is a pointer, or simply to limit what fields are
recorded in the trace event.

Eprobes depend on kprobe events so to enable this feature, build your kernel
with CONFIG_EPROBE_EVENTS=y.

Eprobes are created via the /sys/kernel/tracing/dynamic_events file.

eprobe_events 문법, FETCHARGS와 연결 대상

probe 설정 형식은 `e[:[EGRP/][EEVENT]] GRP.EVENT [FETCHARGS]`이고 삭제 형식은 `-:[EGRP/][EEVENT]`다. `EGRP`를 생략하면 새 event group은 `eprobes`가 된다. `EEVENT`를 생략하면 연결 대상 event와 같은 이름을 자동 생성한다.

`GRP.EVENT`는 연결할 기존 event의 group과 event name이다. probe 하나는 최대 128개 argument를 가질 수 있다.

`$FIELD`는 연결된 event field 값을 가져오고, `@ADDR`는 kernel address의 memory를, `@SYM[+|-offs]`는 data symbol 기준 memory를 가져온다. `$comm`은 current task의 comm을 가져온다.

`+|-[u]OFFS(FETCHARG)`는 FETCHARG 기준 offset address의 memory를 읽는다. `IMM`은 immediate value를 저장한다. `NAME=FETCHARG`는 argument 이름을 지정하고 `FETCHARG:TYPE`은 type을 지정한다.

지원 type에는 기본 정수 `u8`부터 `s64`, 16진수 `x8`부터 `x64`, VFS 공통 type `%pd`와 `%pD`, `char`, `string`, `ustring`, `symbol`, `symstr`, `bitfield`가 있다.

FETCHARGS는 `Documentation/trace/kprobetrace.rst`의 kprobe event 문법과 매우 비슷하다. 차이는 Eprobe의 `$FIELD`가 연결된 event field 내용을 반환한다는 점이다. Eprobe는 kprobe가 접근하는 register, stack, function argument에는 접근할 수 없다.

field argument가 pointer라면 FETCHARGS memory-address 문법으로 역참조할 수 있다. Eprobe는 normal event뿐 아니라 kprobe event, synthetic event, fprobe event에도 연결할 수 있어 field type을 바꿀 때 유용하다.

Synopsis of eprobe_events
-------------------------
::

  e[:[EGRP/][EEVENT]] GRP.EVENT [FETCHARGS]	: Set a probe
  -:[EGRP/][EEVENT]				: Clear a probe

 EGRP		: Group name of the new event. If omitted, use "eprobes" for it.
 EEVENT		: Event name. If omitted, the event name is generated and will
		  be the same event name as the event it attached to.
 GRP		: Group name of the event to attach to.
 EVENT		: Event name of the event to attach to.

 FETCHARGS	: Arguments. Each probe can have up to 128 args.
  $FIELD	: Fetch the value of the event field called FIELD.
  @ADDR		: Fetch memory at ADDR (ADDR should be in kernel)
  @SYM[+|-offs]	: Fetch memory at SYM +|- offs (SYM should be a data symbol)
  $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.

Types
-----
The FETCHARGS above is very similar to the kprobe events as described in
Documentation/trace/kprobetrace.rst.

The difference between eprobes and kprobes FETCHARGS is that eprobes has a
$FIELD command that returns the content of the event field of the event
that is attached. Eprobes do not have access to registers, stacks and function
arguments that kprobes has.

If a field argument is a pointer, it may be dereferenced just like a memory
address using the FETCHARGS syntax.


Attaching to dynamic events
---------------------------

Eprobes may attach to dynamic events as well as to normal events. It may
attach to a kprobe event, a synthetic event or a fprobe event. This is useful
if the type of a field needs to be changed. See Example 2 below.

예제 1: sched_switch field 제한

Eprobe의 기본 사용법은 tracing buffer에 기록할 data를 제한하는 것이다. 예제의 `sched_switch` event에는 모든 event에 공통인 네 field와 이전·다음 task의 이름, pid, priority, 이전 task state가 있다.

공통 네 field는 제한할 수 없다. 나머지는 60 byte이며 task 전환 전후의 이름, pid, priority, 이전 state를 기록한다. pid만 필요하다면 나머지 field가 ring buffer를 차지할 이유가 없다.

`e:sched/switch sched.sched_switch prev=$prev_pid:u32 next=$next_pid:u32`는 `sched_switch`에 연결해 `prev`와 `next` pid만 u32로 기록하는 Eprobe를 만든다.

Eprobe는 기록량을 줄이지만 성능을 개선하지는 않는다. Eprobe를 처리하기 위해 원래 모든 field를 temporary buffer에 먼저 기록하기 때문이다.

예시 trace에는 각 context switch마다 `prev`와 `next` pid만 나타난다. `prev_pid`와 `next_pid` 뒤에 `u32`를 붙이지 않으면 값은 기본적으로 16진수로 표시된다.

Usage examples
==============

Example 1
---------

The basic usage of eprobes is to limit the data that is being recorded into
the tracing buffer. For example, a common event to trace is the sched_switch
trace event. That has a format of::

	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:char prev_comm[16];	offset:8;	size:16;	signed:0;
	field:pid_t prev_pid;	offset:24;	size:4;	signed:1;
	field:int prev_prio;	offset:28;	size:4;	signed:1;
	field:long prev_state;	offset:32;	size:8;	signed:1;
	field:char next_comm[16];	offset:40;	size:16;	signed:0;
	field:pid_t next_pid;	offset:56;	size:4;	signed:1;
	field:int next_prio;	offset:60;	size:4;	signed:1;

The first four fields are common to all events and can not be limited. But the
rest of the event has 60 bytes of information. It records the names of the
previous and next tasks being scheduled out and in, as well as their pids and
priorities. It also records the state of the previous task. If only the pids
of the tasks are of interest, why waste the ring buffer with all the other
fields?

An eprobe can limit what gets recorded. Note, it does not help in performance,
as all the fields are recorded in a temporary buffer to process the eprobe.
::

 # echo 'e:sched/switch sched.sched_switch prev=$prev_pid:u32 next=$next_pid:u32' >> /sys/kernel/tracing/dynamic_events
 # echo 1 > /sys/kernel/tracing/events/sched/switch/enable
 # cat /sys/kernel/tracing/trace

 # tracer: nop
 #
 # entries-in-buffer/entries-written: 2721/2721   #P:8
 #
 #                                _-----=> irqs-off/BH-disabled
 #                               / _----=> need-resched
 #                              | / _---=> hardirq/softirq
 #                              || / _--=> preempt-depth
 #                              ||| / _-=> migrate-disable
 #                              |||| /     delay
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
     sshd-session-1082    [004] d..4.  5041.239906: switch: (sched.sched_switch) prev=1082 next=0
             bash-1085    [001] d..4.  5041.240198: switch: (sched.sched_switch) prev=1085 next=141
    kworker/u34:5-141     [001] d..4.  5041.240259: switch: (sched.sched_switch) prev=141 next=1085
           <idle>-0       [004] d..4.  5041.240354: switch: (sched.sched_switch) prev=0 next=1082
             bash-1085    [001] d..4.  5041.240385: switch: (sched.sched_switch) prev=1085 next=141
    kworker/u34:5-141     [001] d..4.  5041.240410: switch: (sched.sched_switch) prev=141 next=1085
             bash-1085    [001] d..4.  5041.240478: switch: (sched.sched_switch) prev=1085 next=0
     sshd-session-1082    [004] d..4.  5041.240526: switch: (sched.sched_switch) prev=1082 next=0
           <idle>-0       [001] d..4.  5041.247524: switch: (sched.sched_switch) prev=0 next=90
           <idle>-0       [002] d..4.  5041.247545: switch: (sched.sched_switch) prev=0 next=16
      kworker/1:1-90      [001] d..4.  5041.247580: switch: (sched.sched_switch) prev=90 next=0
        rcu_sched-16      [002] d..4.  5041.247591: switch: (sched.sched_switch) prev=16 next=0
           <idle>-0       [002] d..4.  5041.257536: switch: (sched.sched_switch) prev=0 next=16
        rcu_sched-16      [002] d..4.  5041.257573: switch: (sched.sched_switch) prev=16 next=0

Note, without adding the "u32" after the prev_pid and next_pid, the values
would default showing in hexadecimal.

예제 2: raw_syscalls openat와 page fault 제약

특정 system call을 기록하고 싶지만 syscall event가 활성화되지 않았다면 `raw_syscalls`를 사용할 수 있다. syscall event는 일반 event가 아니라 kernel 내부에서 raw_syscalls event로부터 생성된다.

`raw_syscalls.sys_enter` format에는 공통 field, syscall `id`, 여섯 개의 `args`가 있다. `sys_openat(int dirfd, const char *path, int flags, mode_t mode)`에서 원하는 pathname은 두 번째 argument다.

x86_64 word size가 8 byte이므로 `filename=+8($args):ustring`은 `$args`에서 8 byte offset의 두 번째 argument를 user string으로 역참조한다. 이 platform의 `__NR_openat`은 257이므로 filter `nr == 257`을 적용한다.

event를 활성화하면 `nr=0x101`과 함께 filename이 `(fault)`로 보인다. pathname page가 아직 memory에 들어오지 않았을 가능성이 높고, 현재 trace event는 존재하지 않는 memory를 fault-in할 수 없기 때문이다.

Eprobe가 아직 fault-in되지 않은 memory를 읽으려 하면 `(fault)` text를 출력한다. kernel이 syscall 처리 중 pathname을 memory로 가져올 가능성이 있으므로, entry에서 filename address를 synthetic event로 전달해 syscall return 시점에 문자열을 읽으면 이 제약을 우회할 수 있다.

Example 2
---------

If a specific system call is to be recorded but the syscalls events are not
enabled, the raw_syscalls can still be used (syscalls are system call
events are not normal events, but are created from the raw_syscalls events
within the kernel). In order to trace the openat system call, one can create
an event probe on top of the raw_syscalls event:
::

 # cd /sys/kernel/tracing
 # cat events/raw_syscalls/sys_enter/format
 name: sys_enter
 ID: 395
 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:long id;	offset:8;	size:8;	signed:1;
	field:unsigned long args[6];	offset:16;	size:48;	signed:0;

 print fmt: "NR %ld (%lx, %lx, %lx, %lx, %lx, %lx)", REC->id, REC->args[0], REC->args[1], REC->args[2], REC->args[3], REC->args[4], REC->args[5]

From the source code, the sys_openat() has:
::

 int sys_openat(int dirfd, const char *path, int flags, mode_t mode)
 {
	return my_syscall4(__NR_openat, dirfd, path, flags, mode);
 }

The path is the second parameter, and that is what is wanted.
::

 # echo 'e:openat raw_syscalls.sys_enter nr=$id filename=+8($args):ustring' >> dynamic_events

This is being run on x86_64 where the word size is 8 bytes and the openat
system call __NR_openat is set at 257.
::

 # echo 'nr == 257' > events/eprobes/openat/filter

Now enable the event and look at the trace.
::

 # echo 1 > events/eprobes/openat/enable
 # cat trace

 # tracer: nop
 #
 # entries-in-buffer/entries-written: 4/4   #P:8
 #
 #                                _-----=> irqs-off/BH-disabled
 #                               / _----=> need-resched
 #                              | / _---=> hardirq/softirq
 #                              || / _--=> preempt-depth
 #                              ||| / _-=> migrate-disable
 #                              |||| /     delay
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
              cat-1298    [003] ...2.  2060.875970: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault)
              cat-1298    [003] ...2.  2060.876197: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault)
              cat-1298    [003] ...2.  2060.879126: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault)
              cat-1298    [003] ...2.  2060.879639: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault)

The filename shows "(fault)". This is likely because the filename has not been
pulled into memory yet and currently trace events cannot fault in memory that
is not present. When an eprobe tries to read memory that has not been faulted
in yet, it will show the "(fault)" text.

To get around this, as the kernel will likely pull in this filename and make
it present, attaching it to a synthetic event that can pass the address of the
filename from the entry of the event to the end of the event, this can be used
to show the filename when the system call returns.

Synthetic event로 filename address 전달

먼저 기존 `openat` Eprobe를 제거한다. 이번에는 `openat_start` Eprobe에서 filename 자체가 아니라 그 address를 `x64`로 저장한다.

`s:filename u64 file`로 address를 운반할 synthetic event를 만든다. entry trigger는 `common_pid`를 key로 filename address를 저장하고, exit trigger는 같은 pid의 값을 찾아 synthetic `filename` event를 발생시킨다.

address가 syscall 끝까지 전달된 뒤 synthetic event에 두 번째 `openat` Eprobe를 붙인다. `filename=+0($file):ustring`으로 그 address의 user string을 읽는다.

결과 trace에는 `/etc/ld.so.cache`, libc path, locale archive, `trace`처럼 실제 filename이 표시된다. syscall 처리 중 pathname page가 memory에 들어왔기 때문에 exit 시점의 역참조가 성공한다.

Remove the old eprobe::

 # echo 1 > events/eprobes/openat/enable
 # echo '-:openat' >> dynamic_events

This time make an eprobe where the address of the filename is saved::

 # echo 'e:openat_start raw_syscalls.sys_enter nr=$id filename=+8($args):x64' >> dynamic_events

Create a synthetic event that passes the address of the filename to the
end of the event::

 # echo 's:filename u64 file' >> dynamic_events
 # echo 'hist:keys=common_pid:f=filename if nr == 257' > events/eprobes/openat_start/trigger
 # echo 'hist:keys=common_pid:file=$f:onmatch(eprobes.openat_start).trace(filename,$file) if id == 257' > events/raw_syscalls/sys_exit/trigger

Now that the address of the filename has been passed to the end of the
system call, create another eprobe to attach to the exit event to show the
string::

 # echo 'e:openat synthetic.filename filename=+0($file):ustring' >> dynamic_events
 # echo 1 > events/eprobes/openat/enable
 # cat trace

 # tracer: nop
 #
 # entries-in-buffer/entries-written: 4/4   #P:8
 #
 #                                _-----=> irqs-off/BH-disabled
 #                               / _----=> need-resched
 #                              | / _---=> hardirq/softirq
 #                              || / _--=> preempt-depth
 #                              ||| / _-=> migrate-disable
 #                              |||| /     delay
 #           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
 #              | |         |   |||||     |         |
              cat-1331    [001] ...5.  2944.787977: openat: (synthetic.filename) filename="/etc/ld.so.cache"
              cat-1331    [001] ...5.  2944.788480: openat: (synthetic.filename) filename="/lib/x86_64-linux-gnu/libc.so.6"
              cat-1331    [001] ...5.  2944.793426: openat: (synthetic.filename) filename="/usr/lib/locale/locale-archive"
              cat-1331    [001] ...5.  2944.831362: openat: (synthetic.filename) filename="trace"

예제 3: syscall event가 있는 경우

syscall trace event를 사용할 수 있다면 예제 2의 첫 번째 raw_syscalls Eprobe는 필요 없다. 다만 synthetic event에서 filename string을 읽는 마지막 Eprobe는 여전히 필요하다.

`sys_enter_openat` trigger가 pid별 filename address를 저장하고 `sys_exit_openat` trigger가 synthetic `filename` event를 발생시킨다. 그 event에 `filename=+0($file):ustring` Eprobe를 붙이면 예제 2와 같은 결과를 얻는다.

Example 3
---------

If syscall trace events are available, the above would not need the first
eprobe, but it would still need the last one::

 # echo 's:filename u64 file' >> dynamic_events
 # echo 'hist:keys=common_pid:f=filename' > events/syscalls/sys_enter_openat/trigger
 # echo 'hist:keys=common_pid:file=$f:onmatch(syscalls.sys_enter_openat).trace(filename,$file)' > events/syscalls/sys_exit_openat/trigger
 # echo 'e:openat synthetic.filename filename=+0($file):ustring' >> dynamic_events
 # echo 1 > events/eprobes/openat/enable

And this would produce the same result as Example 2.