trace: -L, -t, -T switches
The `-t` switch for specifying a thread id has been renamed
to `-L`. The `-T` switch specifies that a time column should
be provided, whereas the `-t` switch requests a relative
timestamp (from the beginning of the trace). This is more
consistent with other tools, and lets the user choose the
desired format for the time column, if any.
diff --git a/man/man8/trace.8 b/man/man8/trace.8
index c65f849..536bbb8 100644
--- a/man/man8/trace.8
+++ b/man/man8/trace.8
@@ -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 @@
\-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 @@
\-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.
diff --git a/tools/trace.py b/tools/trace.py
index ba93998..cd211fd 100755
--- a/tools/trace.py
+++ b/tools/trace.py
@@ -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 @@
@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 @@
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 @@
# 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 @@
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 @@
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()
diff --git a/tools/trace_example.txt b/tools/trace_example.txt
index 08b9061..46dc843 100644
--- a/tools/trace_example.txt
+++ b/tools/trace_example.txt
@@ -9,20 +9,20 @@
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 @@
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 @@
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 @@
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 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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