1 .. SPDX-License-Identifier: GPL-2.0
3 ==========================
4 Fprobe-based Event Tracing
5 ==========================
7 .. Author: Masami Hiramatsu <mhiramat@kernel.org>
12 Fprobe event is similar to the kprobe event, but limited to probe on
13 the function entry and exit only. It is good enough for many use cases
14 which only traces some specific functions.
16 This document also covers tracepoint probe events (tprobe) since this
17 is also works only on the tracepoint entry. User can trace a part of
18 tracepoint argument, or the tracepoint without trace-event, which is
19 not exposed on tracefs.
21 As same as other dynamic events, fprobe events and tracepoint probe
22 events are defined via `dynamic_events` interface file on tracefs.
24 Synopsis of fprobe-events
25 -------------------------
28 f[:[GRP1/][EVENT1]] SYM [FETCHARGS] : Probe on function entry
29 f[MAXACTIVE][:[GRP1/][EVENT1]] SYM%return [FETCHARGS] : Probe on function exit
30 t[:[GRP2/][EVENT2]] TRACEPOINT [FETCHARGS] : Probe on tracepoint
32 GRP1 : Group name for fprobe. If omitted, use "fprobes" for it.
33 GRP2 : Group name for tprobe. If omitted, use "tracepoints" for it.
34 EVENT1 : Event name for fprobe. If omitted, the event name is
35 "SYM__entry" or "SYM__exit".
36 EVENT2 : Event name for tprobe. If omitted, the event name is
37 the same as "TRACEPOINT", but if the "TRACEPOINT" starts
38 with a digit character, "_TRACEPOINT" is used.
39 MAXACTIVE : Maximum number of instances of the specified function that
40 can be probed simultaneously, or 0 for the default value
41 as defined in Documentation/trace/fprobe.rst
43 FETCHARGS : Arguments. Each probe can have up to 128 args.
44 ARG : Fetch "ARG" function argument using BTF (only for function
45 entry or tracepoint.) (\*1)
46 @ADDR : Fetch memory at ADDR (ADDR should be in kernel)
47 @SYM[+|-offs] : Fetch memory at SYM +|- offs (SYM should be a data symbol)
48 $stackN : Fetch Nth entry of stack (N >= 0)
49 $stack : Fetch stack address.
50 $argN : Fetch the Nth function argument. (N >= 1) (\*2)
51 $retval : Fetch return value.(\*3)
52 $comm : Fetch current task comm.
53 +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*4)(\*5)
54 \IMM : Store an immediate value to the argument.
55 NAME=FETCHARG : Set NAME as the argument name of FETCHARG.
56 FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types
57 (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types
58 (x8/x16/x32/x64), "char", "string", "ustring", "symbol", "symstr"
59 and bitfield are supported.
61 (\*1) This is available only when BTF is enabled.
62 (\*2) only for the probe on function entry (offs == 0). Note, this argument access
63 is best effort, because depending on the argument type, it may be passed on
64 the stack. But this only support the arguments via registers.
65 (\*3) only for return probe. Note that this is also best effort. Depending on the
66 return value type, it might be passed via a pair of registers. But this only
67 accesses one register.
68 (\*4) this is useful for fetching a field of data structures.
69 (\*5) "u" means user-space dereference.
71 For the details of TYPE, see :ref:`kprobetrace documentation <kprobetrace_types>`.
75 BTF (BPF Type Format) argument allows user to trace function and tracepoint
76 parameters by its name instead of ``$argN``. This feature is available if the
77 kernel is configured with CONFIG_BPF_SYSCALL and CONFIG_DEBUG_INFO_BTF.
78 If user only specify the BTF argument, the event's argument name is also
79 automatically set by the given name. ::
81 # echo 'f:myprobe vfs_read count pos' >> dynamic_events
83 f:fprobes/myprobe vfs_read count=count pos=pos
85 It also chooses the fetch type from BTF information. For example, in the above
86 example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus,
87 both are converted to 64bit unsigned long, but only ``pos`` has "%Lx"
88 print-format as below ::
90 # cat events/fprobes/myprobe/format
94 field:unsigned short common_type; offset:0; size:2; signed:0;
95 field:unsigned char common_flags; offset:2; size:1; signed:0;
96 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
97 field:int common_pid; offset:4; size:4; signed:1;
99 field:unsigned long __probe_ip; offset:8; size:8; signed:0;
100 field:u64 count; offset:16; size:8; signed:0;
101 field:u64 pos; offset:24; size:8; signed:0;
103 print fmt: "(%lx) count=%Lu pos=0x%Lx", REC->__probe_ip, REC->count, REC->pos
105 If user unsures the name of arguments, ``$arg*`` will be helpful. The ``$arg*``
106 is expanded to all function arguments of the function or the tracepoint. ::
108 # echo 'f:myprobe vfs_read $arg*' >> dynamic_events
110 f:fprobes/myprobe vfs_read file=file buf=buf count=count pos=pos
112 BTF also affects the ``$retval``. If user doesn't set any type, the retval
113 type is automatically picked from the BTF. If the function returns ``void``,
114 ``$retval`` is rejected.
116 You can access the data fields of a data structure using allow operator ``->``
117 (for pointer type) and dot operator ``.`` (for data structure type.)::
119 # echo 't sched_switch preempt prev_pid=prev->pid next_pid=next->pid' >> dynamic_events
121 The field access operators, ``->`` and ``.`` can be combined for accessing deeper
122 members and other structure members pointed by the member. e.g. ``foo->bar.baz->qux``
123 If there is non-name union member, you can directly access it as the C code does.
133 To access ``a`` and ``b``, use ``foo->a`` and ``foo->b`` in this case.
135 This data field access is available for the return value via ``$retval``,
136 e.g. ``$retval->name``.
138 For these BTF arguments and fields, ``:string`` and ``:ustring`` change the
139 behavior. If these are used for BTF argument or field, it checks whether
140 the BTF type of the argument or the data field is ``char *`` or ``char []``,
141 or not. If not, it rejects applying the string types. Also, with the BTF
142 support, you don't need a memory dereference operator (``+0(PTR)``) for
143 accessing the string pointed by a ``PTR``. It automatically adds the memory
144 dereference operator according to the BTF type. e.g. ::
146 # echo 't sched_switch prev->comm:string' >> dynamic_events
147 # echo 'f getname_flags%return $retval->name:string' >> dynamic_events
149 The ``prev->comm`` is an embedded char array in the data structure, and
150 ``$retval->name`` is a char pointer in the data structure. But in both
151 cases, you can use ``:string`` type to get the string.
156 Here is an example to add fprobe events on ``vfs_read()`` function entry
157 and exit, with BTF arguments.
160 # echo 'f vfs_read $arg*' >> dynamic_events
161 # echo 'f vfs_read%return $retval' >> dynamic_events
163 f:fprobes/vfs_read__entry vfs_read file=file buf=buf count=count pos=pos
164 f:fprobes/vfs_read__exit vfs_read%return arg1=$retval
165 # echo 1 > events/fprobes/enable
166 # head -n 20 trace | tail
167 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
169 sh-70 [000] ...1. 335.883195: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
170 sh-70 [000] ..... 335.883208: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
171 sh-70 [000] ...1. 335.883220: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
172 sh-70 [000] ..... 335.883224: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
173 sh-70 [000] ...1. 335.883232: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c687a count=1 pos=0xffffc900005aff08
174 sh-70 [000] ..... 335.883237: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
175 sh-70 [000] ...1. 336.050329: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08
176 sh-70 [000] ..... 336.050343: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1
178 You can see all function arguments and return values are recorded as signed int.
180 Also, here is an example of tracepoint events on ``sched_switch`` tracepoint.
181 To compare the result, this also enables the ``sched_switch`` traceevent too.
184 # echo 't sched_switch $arg*' >> dynamic_events
185 # echo 1 > events/sched/sched_switch/enable
186 # echo 1 > events/tracepoints/sched_switch/enable
188 # head -n 20 trace | tail
189 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
191 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
192 sh-70 [000] d..3. 3912.083995: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff88800664e100 next=0xffffffff828229c0 prev_state=1
193 <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
194 <idle>-0 [000] d..3. 3912.084184: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0
195 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
196 rcu_preempt-16 [000] d..3. 3912.084196: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff888004208000 next=0xffffffff828229c0 prev_state=1026
197 <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
198 <idle>-0 [000] d..3. 3912.085191: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0
200 As you can see, the ``sched_switch`` trace-event shows *cooked* parameters, on
201 the other hand, the ``sched_switch`` tracepoint probe event shows *raw*
202 parameters. This means you can access any field values in the task
203 structure pointed by the ``prev`` and ``next`` arguments.
205 For example, usually ``task_struct::start_time`` is not traced, but with this
206 traceprobe event, you can trace that field as below.
209 # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events
210 # head -n 20 trace | tail
211 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
213 sh-70 [000] d..3. 5606.686577: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000
214 rcu_preempt-16 [000] d..3. 5606.686602: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="sh" usage=1 start_time=1596095526
215 sh-70 [000] d..3. 5606.686637: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
216 <idle>-0 [000] d..3. 5606.687190: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000
217 rcu_preempt-16 [000] d..3. 5606.687202: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
218 <idle>-0 [000] d..3. 5606.690317: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000
219 kworker/0:1-14 [000] d..3. 5606.690339: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0
220 <idle>-0 [000] d..3. 5606.692368: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000