Skip to content

B
bcc
Commit e1a743e6 authored by yonghong-song's avatar yonghong-song Committed by GitHub
Browse files
Options

Merge pull request #1491 from palmtenor/trace_py 

Improve trace.py formatting and printing options
parents 569461de c200b6c0
Hide whitespace changes
Inline Side-by-side
Showing with 57 additions and 33 deletions
man/man8/trace.8
View file @ e1a743e6
......@@ -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
......
tools/trace.py
View file @ e1a743e6
......@@ -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 @@ class Probe(object):
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 @@ static inline bool %s(char const *ignored, uintptr_t str) {
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 @@ static inline bool %s(char const *ignored, uintptr_t str) {
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 @@ static inline bool %s(char const *ignored, uintptr_t str) {
text = """
struct %s
{
u64 timestamp_ns;
%s
%s
u32 tgid;
u32 pid;
char comm[TASK_COMM_LEN];
......@@ -316,7 +328,7 @@ struct %s
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 @@ BPF_PERF_OUTPUT(%s);
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 @@ BPF_PERF_OUTPUT(%s);
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 @@ BPF_PERF_OUTPUT(%s);
"""
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 @@ 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)
if not Probe.print_time:
print("%-6d %-6d %-12s %-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 %-6d %-6d %-12s %-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 @@ trace -I 'kernel/sched/sched.h' \\
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 @@ trace -I 'kernel/sched/sched.h' \\
# Print header
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 ""))
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()
......
tools/trace_example.txt
View file @ e1a743e6
......@@ -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
......
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