1.. SPDX-License-Identifier: GPL-2.0 2 3================================== 4Eprobe - Event-based Probe Tracing 5================================== 6 7:Author: Steven Rostedt <rostedt@goodmis.org> 8 9- Written for v6.17 10 11Overview 12======== 13 14Eprobes are dynamic events that are placed on existing events to either 15dereference a field that is a pointer, or simply to limit what fields are 16recorded in the trace event. 17 18Eprobes depend on kprobe events so to enable this feature, build your kernel 19with CONFIG_EPROBE_EVENTS=y. 20 21Eprobes are created via the /sys/kernel/tracing/dynamic_events file. 22 23Synopsis of eprobe_events 24------------------------- 25:: 26 27 e[:[EGRP/][EEVENT]] GRP.EVENT [FETCHARGS] : Set a probe 28 -:[EGRP/][EEVENT] : Clear a probe 29 30 EGRP : Group name of the new event. If omitted, use "eprobes" for it. 31 EEVENT : Event name. If omitted, the event name is generated and will 32 be the same event name as the event it attached to. 33 GRP : Group name of the event to attach to. 34 EVENT : Event name of the event to attach to. 35 36 FETCHARGS : Arguments. Each probe can have up to 128 args. 37 $FIELD : Fetch the value of the event field called FIELD. 38 @ADDR : Fetch memory at ADDR (ADDR should be in kernel) 39 @SYM[+|-offs] : Fetch memory at SYM +|- offs (SYM should be a data symbol) 40 $comm : Fetch current task comm. 41 +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*3)(\*4) 42 \IMM : Store an immediate value to the argument. 43 NAME=FETCHARG : Set NAME as the argument name of FETCHARG. 44 FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types 45 (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types 46 (x8/x16/x32/x64), VFS layer common type(%pd/%pD), "char", 47 "string", "ustring", "symbol", "symstr" and "bitfield" are 48 supported. 49 (STRUCT)FIELD->MEMBER[->MEMBER] : If BTF is supported, typecast FIELD to 50 a pointer to STRUCT and then derference the pointer defined by 51 ->MEMBER. Note that when this is used, the FIELD name does not 52 need to be prefixed with a '$'. 53 54Types 55----- 56The FETCHARGS above is very similar to the kprobe events as described in 57Documentation/trace/kprobetrace.rst. 58 59The difference between eprobes and kprobes FETCHARGS is that eprobes has a 60$FIELD command that returns the content of the event field of the event 61that is attached. Eprobes do not have access to registers, stacks and function 62arguments that kprobes has. 63 64If a field argument is a pointer, it may be dereferenced just like a memory 65address using the FETCHARGS syntax. 66 67 68Attaching to dynamic events 69--------------------------- 70 71Eprobes may attach to dynamic events as well as to normal events. It may 72attach to a kprobe event, a synthetic event or a fprobe event. This is useful 73if the type of a field needs to be changed. See Example 2 below. 74 75Usage examples 76============== 77 78Example 1 79--------- 80 81The basic usage of eprobes is to limit the data that is being recorded into 82the tracing buffer. For example, a common event to trace is the sched_switch 83trace event. That has a format of:: 84 85 field:unsigned short common_type; offset:0; size:2; signed:0; 86 field:unsigned char common_flags; offset:2; size:1; signed:0; 87 field:unsigned char common_preempt_count; offset:3; size:1; signed:0; 88 field:int common_pid; offset:4; size:4; signed:1; 89 90 field:char prev_comm[16]; offset:8; size:16; signed:0; 91 field:pid_t prev_pid; offset:24; size:4; signed:1; 92 field:int prev_prio; offset:28; size:4; signed:1; 93 field:long prev_state; offset:32; size:8; signed:1; 94 field:char next_comm[16]; offset:40; size:16; signed:0; 95 field:pid_t next_pid; offset:56; size:4; signed:1; 96 field:int next_prio; offset:60; size:4; signed:1; 97 98The first four fields are common to all events and can not be limited. But the 99rest of the event has 60 bytes of information. It records the names of the 100previous and next tasks being scheduled out and in, as well as their pids and 101priorities. It also records the state of the previous task. If only the pids 102of the tasks are of interest, why waste the ring buffer with all the other 103fields? 104 105An eprobe can limit what gets recorded. Note, it does not help in performance, 106as all the fields are recorded in a temporary buffer to process the eprobe. 107:: 108 109 # echo 'e:sched/switch sched.sched_switch prev=$prev_pid:u32 next=$next_pid:u32' >> /sys/kernel/tracing/dynamic_events 110 # echo 1 > /sys/kernel/tracing/events/sched/switch/enable 111 # cat /sys/kernel/tracing/trace 112 113 # tracer: nop 114 # 115 # entries-in-buffer/entries-written: 2721/2721 #P:8 116 # 117 # _-----=> irqs-off/BH-disabled 118 # / _----=> need-resched 119 # | / _---=> hardirq/softirq 120 # || / _--=> preempt-depth 121 # ||| / _-=> migrate-disable 122 # |||| / delay 123 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 124 # | | | ||||| | | 125 sshd-session-1082 [004] d..4. 5041.239906: switch: (sched.sched_switch) prev=1082 next=0 126 bash-1085 [001] d..4. 5041.240198: switch: (sched.sched_switch) prev=1085 next=141 127 kworker/u34:5-141 [001] d..4. 5041.240259: switch: (sched.sched_switch) prev=141 next=1085 128 <idle>-0 [004] d..4. 5041.240354: switch: (sched.sched_switch) prev=0 next=1082 129 bash-1085 [001] d..4. 5041.240385: switch: (sched.sched_switch) prev=1085 next=141 130 kworker/u34:5-141 [001] d..4. 5041.240410: switch: (sched.sched_switch) prev=141 next=1085 131 bash-1085 [001] d..4. 5041.240478: switch: (sched.sched_switch) prev=1085 next=0 132 sshd-session-1082 [004] d..4. 5041.240526: switch: (sched.sched_switch) prev=1082 next=0 133 <idle>-0 [001] d..4. 5041.247524: switch: (sched.sched_switch) prev=0 next=90 134 <idle>-0 [002] d..4. 5041.247545: switch: (sched.sched_switch) prev=0 next=16 135 kworker/1:1-90 [001] d..4. 5041.247580: switch: (sched.sched_switch) prev=90 next=0 136 rcu_sched-16 [002] d..4. 5041.247591: switch: (sched.sched_switch) prev=16 next=0 137 <idle>-0 [002] d..4. 5041.257536: switch: (sched.sched_switch) prev=0 next=16 138 rcu_sched-16 [002] d..4. 5041.257573: switch: (sched.sched_switch) prev=16 next=0 139 140Note, without adding the "u32" after the prev_pid and next_pid, the values 141would default showing in hexadecimal. 142 143Example 2 144--------- 145 146If a specific system call is to be recorded but the syscalls events are not 147enabled, the raw_syscalls can still be used (syscalls are system call 148events are not normal events, but are created from the raw_syscalls events 149within the kernel). In order to trace the openat system call, one can create 150an event probe on top of the raw_syscalls event: 151:: 152 153 # cd /sys/kernel/tracing 154 # cat events/raw_syscalls/sys_enter/format 155 name: sys_enter 156 ID: 395 157 format: 158 field:unsigned short common_type; offset:0; size:2; signed:0; 159 field:unsigned char common_flags; offset:2; size:1; signed:0; 160 field:unsigned char common_preempt_count; offset:3; size:1; signed:0; 161 field:int common_pid; offset:4; size:4; signed:1; 162 163 field:long id; offset:8; size:8; signed:1; 164 field:unsigned long args[6]; offset:16; size:48; signed:0; 165 166 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] 167 168From the source code, the sys_openat() has: 169:: 170 171 int sys_openat(int dirfd, const char *path, int flags, mode_t mode) 172 { 173 return my_syscall4(__NR_openat, dirfd, path, flags, mode); 174 } 175 176The path is the second parameter, and that is what is wanted. 177:: 178 179 # echo 'e:openat raw_syscalls.sys_enter nr=$id filename=+8($args):ustring' >> dynamic_events 180 181This is being run on x86_64 where the word size is 8 bytes and the openat 182system call __NR_openat is set at 257. 183:: 184 185 # echo 'nr == 257' > events/eprobes/openat/filter 186 187Now enable the event and look at the trace. 188:: 189 190 # echo 1 > events/eprobes/openat/enable 191 # cat trace 192 193 # tracer: nop 194 # 195 # entries-in-buffer/entries-written: 4/4 #P:8 196 # 197 # _-----=> irqs-off/BH-disabled 198 # / _----=> need-resched 199 # | / _---=> hardirq/softirq 200 # || / _--=> preempt-depth 201 # ||| / _-=> migrate-disable 202 # |||| / delay 203 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 204 # | | | ||||| | | 205 cat-1298 [003] ...2. 2060.875970: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault) 206 cat-1298 [003] ...2. 2060.876197: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault) 207 cat-1298 [003] ...2. 2060.879126: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault) 208 cat-1298 [003] ...2. 2060.879639: openat: (raw_syscalls.sys_enter) nr=0x101 filename=(fault) 209 210The filename shows "(fault)". This is likely because the filename has not been 211pulled into memory yet and currently trace events cannot fault in memory that 212is not present. When an eprobe tries to read memory that has not been faulted 213in yet, it will show the "(fault)" text. 214 215To get around this, as the kernel will likely pull in this filename and make 216it present, attaching it to a synthetic event that can pass the address of the 217filename from the entry of the event to the end of the event, this can be used 218to show the filename when the system call returns. 219 220Remove the old eprobe:: 221 222 # echo 1 > events/eprobes/openat/enable 223 # echo '-:openat' >> dynamic_events 224 225This time make an eprobe where the address of the filename is saved:: 226 227 # echo 'e:openat_start raw_syscalls.sys_enter nr=$id filename=+8($args):x64' >> dynamic_events 228 229Create a synthetic event that passes the address of the filename to the 230end of the event:: 231 232 # echo 's:filename u64 file' >> dynamic_events 233 # echo 'hist:keys=common_pid:f=filename if nr == 257' > events/eprobes/openat_start/trigger 234 # echo 'hist:keys=common_pid:file=$f:onmatch(eprobes.openat_start).trace(filename,$file) if id == 257' > events/raw_syscalls/sys_exit/trigger 235 236Now that the address of the filename has been passed to the end of the 237system call, create another eprobe to attach to the exit event to show the 238string:: 239 240 # echo 'e:openat synthetic.filename filename=+0($file):ustring' >> dynamic_events 241 # echo 1 > events/eprobes/openat/enable 242 # cat trace 243 244 # tracer: nop 245 # 246 # entries-in-buffer/entries-written: 4/4 #P:8 247 # 248 # _-----=> irqs-off/BH-disabled 249 # / _----=> need-resched 250 # | / _---=> hardirq/softirq 251 # || / _--=> preempt-depth 252 # ||| / _-=> migrate-disable 253 # |||| / delay 254 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION 255 # | | | ||||| | | 256 cat-1331 [001] ...5. 2944.787977: openat: (synthetic.filename) filename="/etc/ld.so.cache" 257 cat-1331 [001] ...5. 2944.788480: openat: (synthetic.filename) filename="/lib/x86_64-linux-gnu/libc.so.6" 258 cat-1331 [001] ...5. 2944.793426: openat: (synthetic.filename) filename="/usr/lib/locale/locale-archive" 259 cat-1331 [001] ...5. 2944.831362: openat: (synthetic.filename) filename="trace" 260 261Example 3 262--------- 263 264If syscall trace events are available, the above would not need the first 265eprobe, but it would still need the last one:: 266 267 # echo 's:filename u64 file' >> dynamic_events 268 # echo 'hist:keys=common_pid:f=filename' > events/syscalls/sys_enter_openat/trigger 269 # echo 'hist:keys=common_pid:file=$f:onmatch(syscalls.sys_enter_openat).trace(filename,$file)' > events/syscalls/sys_exit_openat/trigger 270 # echo 'e:openat synthetic.filename filename=+0($file):ustring' >> dynamic_events 271 # echo 1 > events/eprobes/openat/enable 272 273And this would produce the same result as Example 2. 274