1.. SPDX-License-Identifier: GPL-2.0 2 3========================== 4Fprobe-based Event Tracing 5========================== 6 7.. Author: Masami Hiramatsu <mhiramat@kernel.org> 8 9Overview 10-------- 11 12Fprobe event is similar to the kprobe event, but limited to probe on 13the function entry and exit only. It is good enough for many use cases 14which only traces some specific functions. 15 16This document also covers tracepoint probe events (tprobe) since this 17is also works only on the tracepoint entry. User can trace a part of 18tracepoint argument, or the tracepoint without trace-event, which is 19not exposed on tracefs. 20 21As same as other dynamic events, fprobe events and tracepoint probe 22events are defined via `dynamic_events` interface file on tracefs. 23 24Synopsis of fprobe-events 25------------------------- 26:: 27 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 31 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 42 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 $current : Fetch the address of the current task_struct. 54 +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*4)(\*5) 55 this_cpu_read(FETCHARG) : Read the value of the per-CPU variable FETCHARG on the current CPU. 56 this_cpu_ptr(FETCHARG) : Get the address of the per-CPU variable FETCHARG on the current CPU. 57 \IMM : Store an immediate value to the argument. 58 NAME=FETCHARG : Set NAME as the argument name of FETCHARG. 59 FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types 60 (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types 61 (x8/x16/x32/x64), "char", "string", "ustring", "symbol", "symstr" 62 and bitfield are supported. 63 (STRUCT[,ASGN])FIELD->MEMBER[->MEMBER] : If BTF is supported, typecast FIELD to 64 a pointer to STRUCT and then derference the pointer defined by 65 ->MEMBER. ASGN can be specified optionally. If ASGN is specified, 66 FIELD will be cast to the same offset position as the ASGN member, 67 rather than to the beginning of the STRUCT. 68 (STRUCT[,ASGN])(FETCHARG)->MEMBER[->MEMBER] : typecast can nest, so the above can 69 also be used with another FETCHARG instead of FIELD. 70 71 (\*1) This is available only when BTF is enabled. 72 (\*2) only for the probe on function entry (offs == 0). Note, this argument access 73 is best effort, because depending on the argument type, it may be passed on 74 the stack. But this only support the arguments via registers. 75 (\*3) only for return probe. Note that this is also best effort. Depending on the 76 return value type, it might be passed via a pair of registers. But this only 77 accesses one register. 78 (\*4) this is useful for fetching a field of data structures. 79 (\*5) "u" means user-space dereference. 80 81For the details of TYPE, see :ref:`kprobetrace documentation <kprobetrace_types>`. 82 83Function arguments at exit 84-------------------------- 85Function arguments can be accessed at exit probe using $arg<N> fetcharg. This 86is useful to record the function parameter and return value at once, and 87trace the difference of structure fields (for debugging a function whether it 88correctly updates the given data structure or not) 89See the :ref:`sample<fprobetrace_exit_args_sample>` below for how it works. 90 91BTF arguments 92------------- 93BTF (BPF Type Format) argument allows user to trace function and tracepoint 94parameters by its name instead of ``$argN``. This feature is available if the 95kernel is configured with CONFIG_BPF_SYSCALL and CONFIG_DEBUG_INFO_BTF. 96If user only specify the BTF argument, the event's argument name is also 97automatically set by the given name. :: 98 99 # echo 'f:myprobe vfs_read count pos' >> dynamic_events 100 # cat dynamic_events 101 f:fprobes/myprobe vfs_read count=count pos=pos 102 103It also chooses the fetch type from BTF information. For example, in the above 104example, the ``count`` is unsigned long, and the ``pos`` is a pointer. Thus, 105both are converted to 64bit unsigned long, but only ``pos`` has "%Lx" 106print-format as below :: 107 108 # cat events/fprobes/myprobe/format 109 name: myprobe 110 ID: 1313 111 format: 112 field:unsigned short common_type; offset:0; size:2; signed:0; 113 field:unsigned char common_flags; offset:2; size:1; signed:0; 114 field:unsigned char common_preempt_count; offset:3; size:1; signed:0; 115 field:int common_pid; offset:4; size:4; signed:1; 116 117 field:unsigned long __probe_ip; offset:8; size:8; signed:0; 118 field:u64 count; offset:16; size:8; signed:0; 119 field:u64 pos; offset:24; size:8; signed:0; 120 121 print fmt: "(%lx) count=%Lu pos=0x%Lx", REC->__probe_ip, REC->count, REC->pos 122 123If user unsures the name of arguments, ``$arg*`` will be helpful. The ``$arg*`` 124is expanded to all function arguments of the function or the tracepoint. :: 125 126 # echo 'f:myprobe vfs_read $arg*' >> dynamic_events 127 # cat dynamic_events 128 f:fprobes/myprobe vfs_read file=file buf=buf count=count pos=pos 129 130BTF also affects the ``$retval``. If user doesn't set any type, the retval 131type is automatically picked from the BTF. If the function returns ``void``, 132``$retval`` is rejected. 133 134You can access the data fields of a data structure using allow operator ``->`` 135(for pointer type) and dot operator ``.`` (for data structure type.):: 136 137# echo 't sched_switch preempt prev_pid=prev->pid next_pid=next->pid' >> dynamic_events 138 139The field access operators, ``->`` and ``.`` can be combined for accessing deeper 140members and other structure members pointed by the member. e.g. ``foo->bar.baz->qux`` 141If there is non-name union member, you can directly access it as the C code does. 142For example:: 143 144 struct { 145 union { 146 int a; 147 int b; 148 }; 149 } *foo; 150 151To access ``a`` and ``b``, use ``foo->a`` and ``foo->b`` in this case. 152 153This data field access is available for the return value via ``$retval``, 154e.g. ``$retval->name``. 155 156For these BTF arguments and fields, ``:string`` and ``:ustring`` change the 157behavior. If these are used for BTF argument or field, it checks whether 158the BTF type of the argument or the data field is ``char *`` or ``char []``, 159or not. If not, it rejects applying the string types. Also, with the BTF 160support, you don't need a memory dereference operator (``+0(PTR)``) for 161accessing the string pointed by a ``PTR``. It automatically adds the memory 162dereference operator according to the BTF type. e.g. :: 163 164# echo 't sched_switch prev->comm:string' >> dynamic_events 165# echo 'f getname_flags%return $retval->name:string' >> dynamic_events 166 167The ``prev->comm`` is an embedded char array in the data structure, and 168``$retval->name`` is a char pointer in the data structure. But in both 169cases, you can use ``:string`` type to get the string. 170 171 172Usage examples 173-------------- 174Here is an example to add fprobe events on ``vfs_read()`` function entry 175and exit, with BTF arguments. 176:: 177 178 # echo 'f vfs_read $arg*' >> dynamic_events 179 # echo 'f vfs_read%return $retval' >> dynamic_events 180 # cat dynamic_events 181 f:fprobes/vfs_read__entry vfs_read file=file buf=buf count=count pos=pos 182 f:fprobes/vfs_read__exit vfs_read%return arg1=$retval 183 # echo 1 > events/fprobes/enable 184 # head -n 20 trace | tail 185 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 186 # | | | ||||| | | 187 sh-70 [000] ...1. 335.883195: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08 188 sh-70 [000] ..... 335.883208: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1 189 sh-70 [000] ...1. 335.883220: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08 190 sh-70 [000] ..... 335.883224: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1 191 sh-70 [000] ...1. 335.883232: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c687a count=1 pos=0xffffc900005aff08 192 sh-70 [000] ..... 335.883237: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1 193 sh-70 [000] ...1. 336.050329: vfs_read__entry: (vfs_read+0x4/0x340) file=0xffff888005cf9a80 buf=0x7ffef36c6879 count=1 pos=0xffffc900005aff08 194 sh-70 [000] ..... 336.050343: vfs_read__exit: (ksys_read+0x75/0x100 <- vfs_read) arg1=1 195 196You can see all function arguments and return values are recorded as signed int. 197 198Also, here is an example of tracepoint events on ``sched_switch`` tracepoint. 199To compare the result, this also enables the ``sched_switch`` traceevent too. 200:: 201 202 # echo 't sched_switch $arg*' >> dynamic_events 203 # echo 1 > events/sched/sched_switch/enable 204 # echo 1 > events/tracepoints/sched_switch/enable 205 # echo > trace 206 # head -n 20 trace | tail 207 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 208 # | | | ||||| | | 209 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 210 sh-70 [000] d..3. 3912.083995: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff88800664e100 next=0xffffffff828229c0 prev_state=1 211 <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 212 <idle>-0 [000] d..3. 3912.084184: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0 213 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 214 rcu_preempt-16 [000] d..3. 3912.084196: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffff888004208000 next=0xffffffff828229c0 prev_state=1026 215 <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 216 <idle>-0 [000] d..3. 3912.085191: sched_switch: (__probestub_sched_switch+0x4/0x10) preempt=0 prev=0xffffffff828229c0 next=0xffff888004208000 prev_state=0 217 218As you can see, the ``sched_switch`` trace-event shows *cooked* parameters, on 219the other hand, the ``sched_switch`` tracepoint probe event shows *raw* 220parameters. This means you can access any field values in the task 221structure pointed by the ``prev`` and ``next`` arguments. 222 223For example, usually ``task_struct::start_time`` is not traced, but with this 224traceprobe event, you can trace that field as below. 225:: 226 227 # echo 't sched_switch comm=next->comm:string next->start_time' > dynamic_events 228 # head -n 20 trace | tail 229 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 230 # | | | ||||| | | 231 sh-70 [000] d..3. 5606.686577: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000 232 rcu_preempt-16 [000] d..3. 5606.686602: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="sh" usage=1 start_time=1596095526 233 sh-70 [000] d..3. 5606.686637: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0 234 <idle>-0 [000] d..3. 5606.687190: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="rcu_preempt" usage=1 start_time=245000000 235 rcu_preempt-16 [000] d..3. 5606.687202: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0 236 <idle>-0 [000] d..3. 5606.690317: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000 237 kworker/0:1-14 [000] d..3. 5606.690339: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="swapper/0" usage=2 start_time=0 238 <idle>-0 [000] d..3. 5606.692368: sched_switch: (__probestub_sched_switch+0x4/0x10) comm="kworker/0:1" usage=1 start_time=137000000 239 240.. _fprobetrace_exit_args_sample: 241 242The return probe allows us to access the results of some functions, which returns 243the error code and its results are passed via function parameter, such as an 244structure-initialization function. 245 246For example, vfs_open() will link the file structure to the inode and update 247mode. You can trace that changes with return probe. 248:: 249 250 # echo 'f vfs_open mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events 251 # echo 'f vfs_open%%return mode=file->f_mode:x32 inode=file->f_inode:x64' >> dynamic_events 252 # echo 1 > events/fprobes/enable 253 # cat trace 254 sh-131 [006] ...1. 1945.714346: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x2 inode=0x0 255 sh-131 [006] ...1. 1945.714358: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4d801e inode=0xffff888008470168 256 cat-143 [007] ...1. 1945.717949: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0 257 cat-143 [007] ...1. 1945.717956: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0x4a801d inode=0xffff888005f78d28 258 cat-143 [007] ...1. 1945.720616: vfs_open__entry: (vfs_open+0x4/0x40) mode=0x1 inode=0x0 259 cat-143 [007] ...1. 1945.728263: vfs_open__exit: (do_open+0x274/0x3d0 <- vfs_open) mode=0xa800d inode=0xffff888004ada8d8 260 261You can see the `file::f_mode` and `file::f_inode` are updated in `vfs_open()`. 262