Skip to content

B
bcc
Commit a5ed723c authored by 4ast's avatar 4ast Committed by GitHub
Browse files
Options

Merge pull request #865 from goldshtn/trace-timestamp 

trace: -L, -t, -T switches
parents b2fe72fc 49d50ba3
Hide whitespace changes
Inline Side-by-side
Showing with 69 additions and 53 deletions
man/man8/trace.8
View file @ a5ed723c
......@@ -2,8 +2,8 @@
.SH NAME
trace \- Trace a function and print its arguments or return value, optionally evaluating a filter. Uses Linux eBPF/bcc.
.SH SYNOPSIS
.B trace [-h] [-p PID] [-t TID] [-v] [-Z STRING_SIZE] [-S]
[-M MAX_EVENTS] [-o] [-K] [-U] [-I header]
.B trace [-h] [-p PID] [-L TID] [-v] [-Z STRING_SIZE] [-S]
[-M MAX_EVENTS] [-t] [-T] [-K] [-U] [-I header]
probe [probe ...]
.SH DESCRIPTION
trace probes functions you specify and displays trace messages if a particular
......@@ -21,7 +21,7 @@ Print usage message.
\-p PID
Trace only functions in the process PID.
.TP
\-t TID
\-L TID
Trace only functions in the thread TID.
.TP
\-v
......@@ -39,9 +39,11 @@ consider that trace is writing to the standard output.
\-M MAX_EVENTS
Print up to MAX_EVENTS trace messages and then exit.
.TP
\-o
Print times relative to the beginning of the trace (offsets), in seconds. The
default is to print absolute time.
\-t
Print times relative to the beginning of the trace (offsets), in seconds.
.TP
\-T
Print the time column.
.TP
\-K
Print the kernel stack for each event.
......
tools/trace.py
View file @ a5ed723c
......@@ -3,8 +3,8 @@
# trace Trace a function and print a trace message based on its
# parameters, with an optional filter.
#
# usage: trace [-h] [-p PID] [-t TID] [-v] [-Z STRING_SIZE] [-S]
# [-M MAX_EVENTS] [-o] [-K] [-U] [-I header]
# usage: trace [-h] [-p PID] [-L TID] [-v] [-Z STRING_SIZE] [-S]
# [-M MAX_EVENTS] [-T] [-t] [-K] [-U] [-I header]
# probe [probe ...]
#
# Licensed under the Apache License, Version 2.0 (the "License")
......@@ -58,7 +58,8 @@ class Probe(object):
@classmethod
def configure(cls, args):
cls.max_events = args.max_events
cls.use_localtime = not args.offset
cls.print_time = args.timestamp or args.time
cls.use_localtime = not args.timestamp
cls.first_ts = Time.monotonic_time()
cls.tgid = args.tgid or -1
cls.pid = args.pid or -1
......@@ -485,11 +486,16 @@ BPF_PERF_OUTPUT(%s);
values = map(lambda i: getattr(event, "v%d" % i),
range(0, len(self.values)))
msg = self._format_message(bpf, event.tgid, values)
time = strftime("%H:%M:%S") if Probe.use_localtime else \
Probe._time_off_str(event.timestamp_ns)
print("%-8s %-6d %-6d %-12s %-16s %s" %
(time[:8], event.tgid, event.pid, event.comm,
self._display_function(), msg))
if not Probe.print_time:
print("%-6d %-6d %-12s %-16s %s" %
(event.tgid, event.pid, event.comm,
self._display_function(), msg))
else:
time = strftime("%H:%M:%S") if Probe.use_localtime else \
Probe._time_off_str(event.timestamp_ns)
print("%-8s %-6d %-6d %-12s %-16s %s" %
(time[:8], event.tgid, event.pid, event.comm,
self._display_function(), msg))
if self.kernel_stack:
self.print_stack(bpf, event.kernel_stack_id, -1)
......@@ -579,7 +585,7 @@ trace 'u:pthread:pthread_create (arg4 != 0)'
# their kernel names -- tgid and pid -- inside the script
parser.add_argument("-p", "--pid", type=int, metavar="PID",
dest="tgid", help="id of the process to trace (optional)")
parser.add_argument("-t", "--tid", type=int, metavar="TID",
parser.add_argument("-L", "--tid", type=int, metavar="TID",
dest="pid", help="id of the thread to trace (optional)")
parser.add_argument("-v", "--verbose", action="store_true",
help="print resulting BPF program code before executing")
......@@ -590,8 +596,10 @@ trace 'u:pthread:pthread_create (arg4 != 0)'
help="do not filter trace's own pid from the trace")
parser.add_argument("-M", "--max-events", type=int,
help="number of events to print before quitting")
parser.add_argument("-o", "--offset", action="store_true",
help="use relative time from first traced message")
parser.add_argument("-t", "--timestamp", action="store_true",
help="print timestamp column (offset from trace start)")
parser.add_argument("-T", "--time", action="store_true",
help="print time column")
parser.add_argument("-K", "--kernel-stack",
action="store_true", help="output kernel stack trace")
parser.add_argument("-U", "--user-stack",
......@@ -653,9 +661,14 @@ trace 'u:pthread:pthread_create (arg4 != 0)'
self.probes))
# Print header
print("%-8s %-6s %-6s %-12s %-16s %s" %
("TIME", "PID", "TID", "COMM", "FUNC",
"-" if not all_probes_trivial else ""))
if self.args.timestamp or self.args.time:
print("%-8s %-6s %-6s %-12s %-16s %s" %
("TIME", "PID", "TID", "COMM", "FUNC",
"-" if not all_probes_trivial else ""))
else:
print("%-6s %-6s %-12s %-16s %s" %
("PID", "TID", "COMM", "FUNC",
"-" if not all_probes_trivial else ""))
while True:
self.bpf.kprobe_poll()
......
tools/trace_example.txt
View file @ a5ed723c
......@@ -9,20 +9,20 @@ For example, suppose you want to trace all commands being exec'd across the
system:
# trace 'sys_execve "%s", arg1'
TIME PID COMM FUNC -
05:11:51 4402 bash sys_execve /usr/bin/man
05:11:51 4411 man sys_execve /usr/local/bin/less
05:11:51 4411 man sys_execve /usr/bin/less
05:11:51 4410 man sys_execve /usr/local/bin/nroff
05:11:51 4410 man sys_execve /usr/bin/nroff
05:11:51 4409 man sys_execve /usr/local/bin/tbl
05:11:51 4409 man sys_execve /usr/bin/tbl
05:11:51 4408 man sys_execve /usr/local/bin/preconv
05:11:51 4408 man sys_execve /usr/bin/preconv
05:11:51 4415 nroff sys_execve /usr/bin/locale
05:11:51 4416 nroff sys_execve /usr/bin/groff
05:11:51 4418 groff sys_execve /usr/bin/grotty
05:11:51 4417 groff sys_execve /usr/bin/troff
PID COMM FUNC -
4402 bash sys_execve /usr/bin/man
4411 man sys_execve /usr/local/bin/less
4411 man sys_execve /usr/bin/less
4410 man sys_execve /usr/local/bin/nroff
4410 man sys_execve /usr/bin/nroff
4409 man sys_execve /usr/local/bin/tbl
4409 man sys_execve /usr/bin/tbl
4408 man sys_execve /usr/local/bin/preconv
4408 man sys_execve /usr/bin/preconv
4415 nroff sys_execve /usr/bin/locale
4416 nroff sys_execve /usr/bin/groff
4418 groff sys_execve /usr/bin/grotty
4417 groff sys_execve /usr/bin/troff
^C
The ::sys_execve syntax specifies that you want an entry probe (which is the
......@@ -38,11 +38,11 @@ the read system call and inspect the third argument, which is the number of
bytes to be read:
# trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
TIME PID COMM FUNC -
05:18:23 4490 dd sys_read read 1048576 bytes
05:18:23 4490 dd sys_read read 1048576 bytes
05:18:23 4490 dd sys_read read 1048576 bytes
05:18:23 4490 dd sys_read read 1048576 bytes
PID COMM FUNC -
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
4490 dd sys_read read 1048576 bytes
^C
During the trace, I executed "dd if=/dev/zero of=/dev/null bs=1M count=4".
......@@ -55,9 +55,9 @@ script, which attaches to the readline function in bash and prints its return
value, effectively snooping all bash shell input across the system:
# trace 'r:bash:readline "%s", retval'
TIME PID COMM FUNC -
05:24:50 2740 bash readline echo hi!
05:24:53 2740 bash readline man ls
PID COMM FUNC -
2740 bash readline echo hi!
2740 bash readline man ls
^C
The special retval keywords stands for the function's return value, and can
......@@ -67,10 +67,10 @@ specify executables too, as long as they can be found in the PATH. Or, you
can specify the full path to the executable (e.g. "/usr/bin/bash").
Multiple probes can be combined on the same command line. For example, let's
trace failed read and write calls on the libc level:
trace failed read and write calls on the libc level, and include a time column:
# trace 'r:c:read ((int)retval < 0) "read failed: %d", retval' \
'r:c:write ((int)retval < 0) "write failed: %d", retval'
'r:c:write ((int)retval < 0) "write failed: %d", retval' -T
TIME PID COMM FUNC -
05:31:57 3388 bash write write failed: -1
05:32:00 3388 bash write write failed: -1
......@@ -84,7 +84,7 @@ trace has also some basic support for kernel tracepoints. For example, let's
trace the block:block_rq_complete tracepoint and print out the number of sectors
transferred:
# trace 't:block:block_rq_complete "sectors=%d", args->nr_sector'
# trace 't:block:block_rq_complete "sectors=%d", args->nr_sector' -T
TIME PID COMM FUNC -
01:23:51 0 swapper/0 block_rq_complete sectors=8
01:23:55 10017 kworker/u64: block_rq_complete sectors=1
......@@ -110,7 +110,7 @@ More and more high-level libraries are instrumented with USDT probe support.
These probes can be traced by trace just like kernel tracepoints. For example,
trace new threads being created and their function name:
# trace 'u:pthread:pthread_create "%U", arg3'
# trace 'u:pthread:pthread_create "%U", arg3' -T
TIME PID COMM FUNC -
02:07:29 4051 contentions pthread_create primes_thread+0x0
02:07:29 4051 contentions pthread_create primes_thread+0x0
......@@ -125,7 +125,7 @@ Ruby, Node, and OpenJDK are also instrumented with USDT. For example, let's
trace Ruby methods being called (this requires a version of Ruby built with
the --enable-dtrace configure flag):
# trace 'u:ruby:method__entry "%s.%s", arg1, arg2' -p $(pidof irb)
# trace 'u:ruby:method__entry "%s.%s", arg1, arg2' -p $(pidof irb) -T
TIME PID COMM FUNC -
12:08:43 18420 irb method__entry IRB::Context.verbose?
12:08:43 18420 irb method__entry RubyLex.ungetc
......@@ -139,7 +139,7 @@ for the Ruby method being invoked.
Occasionally, it can be useful to filter specific strings. For example, you
might be interested in open() calls that open a specific file:
# trace 'p:c:open (STRCMP("test.txt", arg1)) "opening %s", arg1'
# trace 'p:c:open (STRCMP("test.txt", arg1)) "opening %s", arg1' -T
TIME PID COMM FUNC -
01:43:15 10938 cat open opening test.txt
01:43:20 10939 cat open opening test.txt
......@@ -149,7 +149,7 @@ TIME PID COMM FUNC -
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:
# trace -p 2740 'do_sys_open "%s", arg2'
# trace -p 2740 'do_sys_open "%s", arg2' -T
TIME PID COMM FUNC -
05:36:16 15872 ls do_sys_open /etc/ld.so.cache
05:36:16 15872 ls do_sys_open /lib64/libselinux.so.1
......@@ -171,8 +171,8 @@ libraries and then accessing the /home/vagrant directory listing.
USAGE message:
# trace -h
usage: trace [-h] [-p PID] [-t TID] [-v] [-Z STRING_SIZE] [-S]
[-M MAX_EVENTS] [-o] [-K] [-U] [-I header]
usage: trace [-h] [-p PID] [-L TID] [-v] [-Z STRING_SIZE] [-S]
[-M MAX_EVENTS] [-t] [-T] [-K] [-U] [-I header]
probe [probe ...]
Attach to functions and print trace messages.
......@@ -183,14 +183,15 @@ positional arguments:
optional arguments:
-h, --help show this help message and exit
-p PID, --pid PID id of the process to trace (optional)
-t TID, --tid TID id of the thread to trace (optional)
-L TID, --tid TID id of the thread to trace (optional)
-v, --verbose print resulting BPF program code before executing
-Z STRING_SIZE, --string-size STRING_SIZE
maximum size to read from strings
-S, --include-self do not filter trace's own pid from the trace
-M MAX_EVENTS, --max-events MAX_EVENTS
number of events to print before quitting
-o, --offset use relative time from first traced message
-t, --timestamp print timestamp column (offset from trace start)
-T, --time print time column
-K, --kernel-stack output kernel stack trace
-U, --user-stack output user stack trace
-I header, --include header
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7