From 49d50ba324c928e8deb6d741cb35123d676a4aba Mon Sep 17 00:00:00 2001 From: Sasha Goldshtein Date: Mon, 19 Dec 2016 10:17:38 +0000 Subject: [PATCH] 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 | 14 +++++---- tools/trace.py | 41 ++++++++++++++++--------- tools/trace_example.txt | 67 +++++++++++++++++++++-------------------- 3 files changed, 69 insertions(+), 53 deletions(-) diff --git a/man/man8/trace.8 b/man/man8/trace.8 index c65f849fdfb9..536bbb8fe7a4 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 @@ 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. diff --git a/tools/trace.py b/tools/trace.py index ba939987143b..cd211fdb435d 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 @@ 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() diff --git a/tools/trace_example.txt b/tools/trace_example.txt index 08b9061955bc..46dc8438af0e 100644 --- a/tools/trace_example.txt +++ b/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