Skip to content

Commit

Permalink
trace: Allow function signatures in uprobes and kprobes
Browse files Browse the repository at this point in the history
§`trace` now allows uprobes and kprobes to have function signatures,
which means function parameters can be named and typed, rather than
relying on the positional arg1, arg2, etc. arguments. This also
enables structure field access, which is impossible with the unnamed
arguments due to rewriter limitations.

The example requested by @brendangregg, which now works, is the
following:

§Â```
PID    TID    COMM         FUNC             -
777    785    automount    SyS_nanosleep    sleep for 500000000 ns
777    785    automount    SyS_nanosleep    sleep for 500000000 ns
777    785    automount    SyS_nanosleep    sleep for 500000000 ns
777    785    automount    SyS_nanosleep    sleep for 500000000 ns
^C
```
  • Loading branch information
goldshtn committed Jan 17, 2017
1 parent 7e78f3a commit 23e72b8
Show file tree
Hide file tree
Showing 3 changed files with 54 additions and 10 deletions.
12 changes: 11 additions & 1 deletion man/man8/trace.8
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ information. See PROBE SYNTAX below.
.SH PROBE SYNTAX
The general probe syntax is as follows:

.B [{p,r}]:[library]:function [(predicate)] ["format string"[, arguments]]
.B [{p,r}]:[library]:function[(signature)] [(predicate)] ["format string"[, arguments]]

.B {t:category:event,u:library:probe} [(predicate)] ["format string"[, arguments]]
.TP
Expand All @@ -84,6 +84,12 @@ The tracepoint category. For example, "sched" or "irq".
.B function
The function to probe.
.TP
.B signature
The optional signature of the function to probe. This can make it easier to
access the function's arguments, instead of using the "arg1", "arg2" etc.
argument specifiers. For example, "(struct timespec *ts)" in the signature
position lets you use "ts" in the filter or print expressions.
.TP
.B event
The tracepoint event. For example, "block_rq_complete".
.TP
Expand Down Expand Up @@ -159,6 +165,10 @@ Trace the block:block_rq_complete tracepoint and print the number of sectors com
Trace the pthread_create USDT probe from the pthread library and print the address of the thread's start function:
#
.B trace 'u:pthread:pthread_create """start addr = %llx"", arg3'
.TP
Trace the nanosleep system call and print the sleep duration in nanoseconds:
#
.B trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
.SH SOURCE
This is from bcc.
.IP
Expand Down
29 changes: 21 additions & 8 deletions tools/trace.py
Original file line number Diff line number Diff line change
Expand Up @@ -93,15 +93,24 @@ def _bail(self, error):
def _parse_probe(self):
text = self.raw_probe

# Everything until the first space is the probe specifier
first_space = text.find(' ')
spec = text[:first_space] if first_space >= 0 else text
# There might be a function signature preceding the actual
# filter/print part, or not. Find the probe specifier first --
# it ends with either a space or an open paren ( for the
# function signature part.
# opt. signature
# probespec | rest
# --------- ---------- --
(spec, sig, rest) = re.match(r'([^ \t\(]+)(\([^\(]*\))?(.*)',
text).groups()

self._parse_spec(spec)
if first_space >= 0:
text = text[first_space:].lstrip()
else:
text = ""
self.signature = sig[1:-1] if sig else None # remove the parens
if self.signature and self.probe_type in ['u', 't']:
self._bail("USDT and tracepoint probes can't have " +
"a function signature; use arg1, arg2, " +
"... instead")

text = rest.lstrip()
# If we now have a (, wait for the balanced closing ) and that
# will be the predicate
self.filter = None
Expand Down Expand Up @@ -394,6 +403,8 @@ def generate_program(self, include_self):

prefix = ""
signature = "struct pt_regs *ctx"
if self.signature:
signature += ", " + self.signature

data_fields = ""
for i, expr in enumerate(self.values):
Expand Down Expand Up @@ -559,7 +570,7 @@ class Tool(object):
Trace the open syscall and print the filename being opened
trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
Trace the read syscall and print a message for reads >20000 bytes
trace 'r::do_sys_return "%llx", retval'
trace 'r::do_sys_open "%llx", retval'
Trace the return from the open syscall and print the return value
trace 'c:open (arg2 == 42) "%s %d", arg1, arg2'
Trace the open() call from libc only if the flags (arg2) argument is 42
Expand All @@ -575,6 +586,8 @@ class Tool(object):
Trace the block_rq_complete kernel tracepoint and print # of tx sectors
trace 'u:pthread:pthread_create (arg4 != 0)'
Trace the USDT probe pthread_create when its 4th argument is non-zero
trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
Trace the nanosleep syscall and print the sleep duration in ns
"""

def __init__(self):
Expand Down
23 changes: 22 additions & 1 deletion tools/trace_example.txt
Original file line number Diff line number Diff line change
Expand Up @@ -146,6 +146,25 @@ TIME PID COMM FUNC -
^C


In the preceding example, as well as in many others, readability may be
improved by providing the function's signature, which names the arguments and
lets you access structure sub-fields, which is hard with the "arg1", "arg2"
convention. For example:

# trace 'p:c:open(char *filename) "opening %s", filename'
PID TID COMM FUNC -
17507 17507 cat open opening FAQ.txt
^C

# trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
PID TID COMM FUNC -
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
777 785 automount SyS_nanosleep sleep for 500000000 ns
^C


As a final example, let's trace open syscalls for a specific process. By
default, tracing is system-wide, but the -p switch overrides this:

Expand Down Expand Up @@ -205,7 +224,7 @@ trace 'do_sys_open "%s", arg2'
Trace the open syscall and print the filename being opened
trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
Trace the read syscall and print a message for reads >20000 bytes
trace 'r::do_sys_return "%llx", retval'
trace 'r::do_sys_open "%llx", retval'
Trace the return from the open syscall and print the return value
trace 'c:open (arg2 == 42) "%s %d", arg1, arg2'
Trace the open() call from libc only if the flags (arg2) argument is 42
Expand All @@ -221,3 +240,5 @@ trace 't:block:block_rq_complete "sectors=%d", args->nr_sector'
Trace the block_rq_complete kernel tracepoint and print # of tx sectors
trace 'u:pthread:pthread_create (arg4 != 0)'
Trace the USDT probe pthread_create when its 4th argument is non-zero
trace 'p::SyS_nanosleep(struct timespec *ts) "sleep for %lld ns", ts->tv_nsec'
Trace the nanosleep syscall and print the sleep duration in ns

0 comments on commit 23e72b8

Please sign in to comment.