diff --git a/man/man8/trace.8 b/man/man8/trace.8 index 6824ce7ac871..4ebe631796e7 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] [-L TID] [-v] [-Z STRING_SIZE] [-S] - [-M MAX_EVENTS] [-t] [-T] [-K] [-U] [-I header] +.B trace [-h] [-b BUFFER_PAGES] [-p PID] [-L TID] [-v] [-Z STRING_SIZE] [-S] + [-M MAX_EVENTS] [-t] [-T] [-C] [-K] [-U] [-I header] probe [probe ...] .SH DESCRIPTION trace probes functions you specify and displays trace messages if a particular @@ -45,6 +45,9 @@ Print times relative to the beginning of the trace (offsets), in seconds. \-T Print the time column. .TP +\-C +Print CPU id. +.TP \-K Print the kernel stack for each event. .TP diff --git a/tools/trace.py b/tools/trace.py index f8067c5e6260..a56a691c3986 100755 --- a/tools/trace.py +++ b/tools/trace.py @@ -10,6 +10,7 @@ # Licensed under the Apache License, Version 2.0 (the "License") # Copyright (C) 2016 Sasha Goldshtein. +from __future__ import print_function from bcc import BPF, USDT from functools import partial from time import sleep, strftime @@ -26,7 +27,10 @@ class Probe(object): max_events = None event_count = 0 first_ts = 0 + print_time = False use_localtime = True + time_field = False + print_cpu = False tgid = -1 pid = -1 page_cnt = None @@ -36,6 +40,8 @@ def configure(cls, args): cls.max_events = args.max_events cls.print_time = args.timestamp or args.time cls.use_localtime = not args.timestamp + cls.time_field = cls.print_time and (not cls.use_localtime) + cls.print_cpu = args.print_cpu cls.first_ts = BPF.monotonic_time() cls.tgid = args.tgid or -1 cls.pid = args.pid or -1 @@ -251,12 +257,16 @@ def _generate_python_field_decl(self, idx, fields): def _generate_python_data_decl(self): self.python_struct_name = "%s_%d_Data" % \ (self._display_function(), self.probe_num) - fields = [ - ("timestamp_ns", ct.c_ulonglong), + fields = [] + if self.time_field: + fields.append(("timestamp_ns", ct.c_ulonglong)) + if self.print_cpu: + fields.append(("cpu", ct.c_int)) + fields.extend([ ("tgid", ct.c_uint), ("pid", ct.c_uint), ("comm", ct.c_char * 16) # TASK_COMM_LEN - ] + ]) for i in range(0, len(self.types)): self._generate_python_field_decl(i, fields) if self.kernel_stack: @@ -295,7 +305,8 @@ def _generate_data_decl(self): for i, field_type in enumerate(self.types): data_fields += " " + \ self._generate_field_decl(i) - + time_str = "u64 timestamp_ns;" if self.time_field else "" + cpu_str = "int cpu;" if self.print_cpu else "" kernel_stack_str = " int kernel_stack_id;" \ if self.kernel_stack else "" user_stack_str = " int user_stack_id;" \ @@ -304,7 +315,8 @@ def _generate_data_decl(self): text = """ struct %s { - u64 timestamp_ns; +%s +%s u32 tgid; u32 pid; char comm[TASK_COMM_LEN]; @@ -316,7 +328,7 @@ def _generate_data_decl(self): BPF_PERF_OUTPUT(%s); %s """ - return text % (self.struct_name, data_fields, + return text % (self.struct_name, time_str, cpu_str, data_fields, kernel_stack_str, user_stack_str, self.events_name, stack_table) @@ -402,6 +414,10 @@ def generate_program(self, include_self): heading = "int %s(%s)" % (self.probe_name, signature) ctx_name = "ctx" + time_str = """ + __data.timestamp_ns = bpf_ktime_get_ns();""" if self.time_field else "" + cpu_str = """ + __data.cpu = bpf_get_smp_processor_id();""" if self.print_cpu else "" stack_trace = "" if self.user_stack: stack_trace += """ @@ -425,7 +441,8 @@ def generate_program(self, include_self): if (!(%s)) return 0; struct %s __data = {0}; - __data.timestamp_ns = bpf_ktime_get_ns(); + %s + %s __data.tgid = __tgid; __data.pid = __pid; bpf_get_current_comm(&__data.comm, sizeof(__data.comm)); @@ -437,7 +454,7 @@ def generate_program(self, include_self): """ text = text % (pid_filter, prefix, self._generate_usdt_filter_read(), self.filter, - self.struct_name, data_fields, + self.struct_name, time_str, cpu_str, data_fields, stack_trace, self.events_name, ctx_name) return self.streq_functions + data_decl + "\n" + text @@ -484,16 +501,15 @@ 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) - if not Probe.print_time: - print("%-7d %-7d %-15s %-16s %s" % - (event.tgid, event.pid, event.comm.decode(), - self._display_function(), msg)) - else: + if Probe.print_time: time = strftime("%H:%M:%S") if Probe.use_localtime else \ Probe._time_off_str(event.timestamp_ns) - print("%-8s %-7d %-7d %-15s %-16s %s" % - (time[:8], event.tgid, event.pid, - event.comm.decode(), self._display_function(), msg)) + print("%-8s " % time[:8], end="") + if Probe.print_cpu: + print("%-3s " % event.cpu, end="") + print("%-7d %-7d %-15s %-16s %s" % + (event.tgid, event.pid, event.comm.decode(), + self._display_function(), msg)) if self.kernel_stack: self.print_stack(bpf, event.kernel_stack_id, -1) @@ -616,6 +632,8 @@ def __init__(self): help="print timestamp column (offset from trace start)") parser.add_argument("-T", "--time", action="store_true", help="print time column") + parser.add_argument("-C", "--print_cpu", action="store_true", + help="print CPU id") parser.add_argument("-K", "--kernel-stack", action="store_true", help="output kernel stack trace") parser.add_argument("-U", "--user-stack", @@ -685,13 +703,12 @@ def _main_loop(self): # Print header if self.args.timestamp or self.args.time: - print("%-8s %-7s %-7s %-15s %-16s %s" % - ("TIME", "PID", "TID", "COMM", "FUNC", - "-" if not all_probes_trivial else "")) - else: - print("%-7s %-7s %-15s %-16s %s" % - ("PID", "TID", "COMM", "FUNC", - "-" if not all_probes_trivial else "")) + print("%-8s " % "TIME", end=""); + if self.args.print_cpu: + print("%-3s " % "CPU", end=""); + print("%-7s %-7s %-15s %-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 2d3ffad31a22..d6d7806f0579 100644 --- a/tools/trace_example.txt +++ b/tools/trace_example.txt @@ -108,14 +108,17 @@ predicate and trace arguments. 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' -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 -02:07:29 4051 contentions pthread_create primes_thread+0x0 -02:07:29 4051 contentions pthread_create primes_thread+0x0 +trace new threads being created and their function name, include time column +and on which CPU it happened: + +# trace 'u:pthread:pthread_create "%U", arg3' -T -C +TIME CPU PID TID COMM FUNC - +13:22:01 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount] +13:22:01 5 21360 21414 osqueryd pthread_create [unknown] [osqueryd] +13:22:03 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount] +13:22:04 15 21360 21414 osqueryd pthread_create [unknown] [osqueryd] +13:22:07 25 2627 2629 automount pthread_create expire_proc_indirect+0x0 [automount] +13:22:07 4 21360 21414 osqueryd pthread_create [unknown] [osqueryd] ^C The "%U" format specifier tells trace to resolve arg3 as a user-space symbol, @@ -245,6 +248,7 @@ optional arguments: number of events to print before quitting -t, --timestamp print timestamp column (offset from trace start) -T, --time print time column + -C, --print_cpu print CPU id -K, --kernel-stack output kernel stack trace -U, --user-stack output user stack trace -I header, --include header