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.

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 @@ 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

@@ -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 @@ def print_event(self, bpf, cpu, data, size):
  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 @@ def __init__(self):
  # 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 @@ def __init__(self):
  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 @@ def _main_loop(self):
  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

@@ -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