^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 1) =========================================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 2) Uprobe-tracer: Uprobe-based Event Tracing
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 3) =========================================
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 4)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 5) :Author: Srikar Dronamraju
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 6)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 7)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 8) Overview
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 9) --------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 10) Uprobe based trace events are similar to kprobe based trace events.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 11) To enable this feature, build your kernel with CONFIG_UPROBE_EVENTS=y.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 12)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 13) Similar to the kprobe-event tracer, this doesn't need to be activated via
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 14) current_tracer. Instead of that, add probe points via
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 15) /sys/kernel/debug/tracing/uprobe_events, and enable it via
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 16) /sys/kernel/debug/tracing/events/uprobes/<EVENT>/enable.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 17)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 18) However unlike kprobe-event tracer, the uprobe event interface expects the
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 19) user to calculate the offset of the probepoint in the object.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 20)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 21) You can also use /sys/kernel/debug/tracing/dynamic_events instead of
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 22) uprobe_events. That interface will provide unified access to other
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 23) dynamic events too.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 24)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 25) Synopsis of uprobe_tracer
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 26) -------------------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 27) ::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 28)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 29) p[:[GRP/]EVENT] PATH:OFFSET [FETCHARGS] : Set a uprobe
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 30) r[:[GRP/]EVENT] PATH:OFFSET [FETCHARGS] : Set a return uprobe (uretprobe)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 31) p[:[GRP/]EVENT] PATH:OFFSET%return [FETCHARGS] : Set a return uprobe (uretprobe)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 32) -:[GRP/]EVENT : Clear uprobe or uretprobe event
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 33)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 34) GRP : Group name. If omitted, "uprobes" is the default value.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 35) EVENT : Event name. If omitted, the event name is generated based
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 36) on PATH+OFFSET.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 37) PATH : Path to an executable or a library.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 38) OFFSET : Offset where the probe is inserted.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 39) OFFSET%return : Offset where the return probe is inserted.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 40)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 41) FETCHARGS : Arguments. Each probe can have up to 128 args.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 42) %REG : Fetch register REG
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 43) @ADDR : Fetch memory at ADDR (ADDR should be in userspace)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 44) @+OFFSET : Fetch memory at OFFSET (OFFSET from same file as PATH)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 45) $stackN : Fetch Nth entry of stack (N >= 0)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 46) $stack : Fetch stack address.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 47) $retval : Fetch return value.(\*1)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 48) $comm : Fetch current task comm.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 49) +|-[u]OFFS(FETCHARG) : Fetch memory at FETCHARG +|- OFFS address.(\*2)(\*3)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 50) \IMM : Store an immediate value to the argument.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 51) NAME=FETCHARG : Set NAME as the argument name of FETCHARG.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 52) FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 53) (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 54) (x8/x16/x32/x64), "string" and bitfield are supported.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 55)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 56) (\*1) only for return probe.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 57) (\*2) this is useful for fetching a field of data structures.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 58) (\*3) Unlike kprobe event, "u" prefix will just be ignored, becuse uprobe
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 59) events can access only user-space memory.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 60)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 61) Types
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 62) -----
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 63) Several types are supported for fetch-args. Uprobe tracer will access memory
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 64) by given type. Prefix 's' and 'u' means those types are signed and unsigned
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 65) respectively. 'x' prefix implies it is unsigned. Traced arguments are shown
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 66) in decimal ('s' and 'u') or hexadecimal ('x'). Without type casting, 'x32'
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 67) or 'x64' is used depends on the architecture (e.g. x86-32 uses x32, and
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 68) x86-64 uses x64).
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 69) String type is a special type, which fetches a "null-terminated" string from
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 70) user space.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 71) Bitfield is another special type, which takes 3 parameters, bit-width, bit-
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 72) offset, and container-size (usually 32). The syntax is::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 73)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 74) b<bit-width>@<bit-offset>/<container-size>
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 75)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 76) For $comm, the default type is "string"; any other type is invalid.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 77)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 78)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 79) Event Profiling
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 80) ---------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 81) You can check the total number of probe hits per event via
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 82) /sys/kernel/debug/tracing/uprobe_profile. The first column is the filename,
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 83) the second is the event name, the third is the number of probe hits.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 84)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 85) Usage examples
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 86) --------------
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 87) * Add a probe as a new uprobe event, write a new definition to uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 88) as below (sets a uprobe at an offset of 0x4245c0 in the executable /bin/bash)::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 89)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 90) echo 'p /bin/bash:0x4245c0' > /sys/kernel/debug/tracing/uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 91)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 92) * Add a probe as a new uretprobe event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 93)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 94) echo 'r /bin/bash:0x4245c0' > /sys/kernel/debug/tracing/uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 95)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 96) * Unset registered event::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 97)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 98) echo '-:p_bash_0x4245c0' >> /sys/kernel/debug/tracing/uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 99)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 100) * Print out the events that are registered::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 101)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 102) cat /sys/kernel/debug/tracing/uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 103)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 104) * Clear all events::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 105)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 106) echo > /sys/kernel/debug/tracing/uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 107)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 108) Following example shows how to dump the instruction pointer and %ax register
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 109) at the probed text address. Probe zfree function in /bin/zsh::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 110)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 111) # cd /sys/kernel/debug/tracing/
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 112) # cat /proc/`pgrep zsh`/maps | grep /bin/zsh | grep r-xp
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 113) 00400000-0048a000 r-xp 00000000 08:03 130904 /bin/zsh
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 114) # objdump -T /bin/zsh | grep -w zfree
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 115) 0000000000446420 g DF .text 0000000000000012 Base zfree
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 116)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 117) 0x46420 is the offset of zfree in object /bin/zsh that is loaded at
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 118) 0x00400000. Hence the command to uprobe would be::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 119)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 120) # echo 'p:zfree_entry /bin/zsh:0x46420 %ip %ax' > uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 121)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 122) And the same for the uretprobe would be::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 123)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 124) # echo 'r:zfree_exit /bin/zsh:0x46420 %ip %ax' >> uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 125)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 126) .. note:: User has to explicitly calculate the offset of the probe-point
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 127) in the object.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 128)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 129) We can see the events that are registered by looking at the uprobe_events file.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 130) ::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 131)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 132) # cat uprobe_events
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 133) p:uprobes/zfree_entry /bin/zsh:0x00046420 arg1=%ip arg2=%ax
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 134) r:uprobes/zfree_exit /bin/zsh:0x00046420 arg1=%ip arg2=%ax
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 135)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 136) Format of events can be seen by viewing the file events/uprobes/zfree_entry/format.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 137) ::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 138)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 139) # cat events/uprobes/zfree_entry/format
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 140) name: zfree_entry
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 141) ID: 922
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 142) format:
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 143) field:unsigned short common_type; offset:0; size:2; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 144) field:unsigned char common_flags; offset:2; size:1; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 145) field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 146) field:int common_pid; offset:4; size:4; signed:1;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 147) field:int common_padding; offset:8; size:4; signed:1;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 148)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 149) field:unsigned long __probe_ip; offset:12; size:4; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 150) field:u32 arg1; offset:16; size:4; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 151) field:u32 arg2; offset:20; size:4; signed:0;
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 152)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 153) print fmt: "(%lx) arg1=%lx arg2=%lx", REC->__probe_ip, REC->arg1, REC->arg2
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 154)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 155) Right after definition, each event is disabled by default. For tracing these
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 156) events, you need to enable it by::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 157)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 158) # echo 1 > events/uprobes/enable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 159)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 160) Lets start tracing, sleep for some time and stop tracing.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 161) ::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 162)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 163) # echo 1 > tracing_on
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 164) # sleep 20
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 165) # echo 0 > tracing_on
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 166)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 167) Also, you can disable the event by::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 168)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 169) # echo 0 > events/uprobes/enable
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 170)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 171) And you can see the traced information via /sys/kernel/debug/tracing/trace.
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 172) ::
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 173)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 174) # cat trace
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 175) # tracer: nop
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 176) #
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 177) # TASK-PID CPU# TIMESTAMP FUNCTION
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 178) # | | | | |
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 179) zsh-24842 [006] 258544.995456: zfree_entry: (0x446420) arg1=446420 arg2=79
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 180) zsh-24842 [007] 258545.000270: zfree_exit: (0x446540 <- 0x446420) arg1=446540 arg2=0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 181) zsh-24842 [002] 258545.043929: zfree_entry: (0x446420) arg1=446420 arg2=79
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 182) zsh-24842 [004] 258547.046129: zfree_exit: (0x446540 <- 0x446420) arg1=446540 arg2=0
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 183)
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 184) Output shows us uprobe was triggered for a pid 24842 with ip being 0x446420
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 185) and contents of ax register being 79. And uretprobe was triggered with ip at
^8f3ce5b39 (kx 2023-10-28 12:00:06 +0300 186) 0x446540 with counterpart function entry at 0x446420.