Skip to content

Commit

Permalink
tools/trace.py: add msg filter of event
Browse files Browse the repository at this point in the history
In the normal develop, will produce many event on the same tracepoint,
like do_sys_open, a executable program will open many files but
developer only has interesting on the specific file. So this filter
will
help developer to get their interesting msg

Signed-off-by: tty5 <tty.fqq@gmail.com>
  • Loading branch information
tty5 authored and yonghong-song committed Dec 6, 2019
1 parent 9ce7b7e commit 5cf529e
Show file tree
Hide file tree
Showing 3 changed files with 35 additions and 2 deletions.
3 changes: 3 additions & 0 deletions man/man8/trace.8
Expand Up @@ -61,6 +61,9 @@ Trace only functions in processes under CGROUP_PATH hierarchy.
\-n NAME
Only print process names containing this name.
.TP
\-f MSG_FILTER
Only print message of event containing this string.
.TP
\-B
Treat argument of STRCMP helper as a binary value
.TP
Expand Down
11 changes: 9 additions & 2 deletions tools/trace.py
Expand Up @@ -58,7 +58,7 @@ def configure(cls, args):
cls.build_id_enabled = args.sym_file_list is not None

def __init__(self, probe, string_size, kernel_stack, user_stack,
cgroup_map_name, name):
cgroup_map_name, name, msg_filter):
self.usdt = None
self.streq_functions = ""
self.raw_probe = probe
Expand All @@ -74,6 +74,7 @@ def __init__(self, probe, string_size, kernel_stack, user_stack,
self.probe_name)
self.cgroup_map_name = cgroup_map_name
self.name = name
self.msg_filter = msg_filter
# compiler can generate proper codes for function
# signatures with "syscall__" prefix
if self.is_syscall_kprobe:
Expand Down Expand Up @@ -576,6 +577,8 @@ 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 self.msg_filter and bytes(self.msg_filter) not in msg:
return
if Probe.print_time:
time = strftime("%H:%M:%S") if Probe.use_localtime else \
Probe._time_off_str(event.timestamp_ns)
Expand Down Expand Up @@ -653,6 +656,8 @@ class Tool(object):
Trace the open syscall and print the filename being opened
trace 'do_sys_open "%s", arg2' -n main
Trace the open syscall and only print event that process names containing "main"
trace 'do_sys_open "%s", arg2' -f config
Trace the open syscall and print the filename being opened filtered by "config"
trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
Trace the read syscall and print a message for reads >20000 bytes
trace 'r::do_sys_open "%llx", retval'
Expand Down Expand Up @@ -731,6 +736,8 @@ def __init__(self):
help="cgroup path")
parser.add_argument("-n", "--name", type=str,
help="only print process names containing this name")
parser.add_argument("-f", "--msg-filter", type=str, dest="msg_filter",
help="only print the msg of event containing this string")
parser.add_argument("-B", "--bin_cmp", action="store_true",
help="allow to use STRCMP with binary values")
parser.add_argument('-s', "--sym_file_list", type=str, \
Expand Down Expand Up @@ -768,7 +775,7 @@ def _create_probes(self):
self.probes.append(Probe(
probe_spec, self.args.string_size,
self.args.kernel_stack, self.args.user_stack,
self.cgroup_map_name, self.args.name))
self.cgroup_map_name, self.args.name, self.args.msg_filter))

def _generate_program(self):
self.program = """
Expand Down
23 changes: 23 additions & 0 deletions tools/trace_example.txt
Expand Up @@ -50,6 +50,25 @@ The individual reads are visible, with the custom format message printed for
each read. The parenthesized expression "(arg3 > 20000)" is a filter that is
evaluated for each invocation of the probe before printing anything.

Event message filter is useful while you only interesting the specific event.
Like the program open thousands file and you only want to see the "temp" file
and print stack.

# trace 'do_sys_open "%s", arg2' -UK -f temp
PID TID COMM FUNC -
9557 9557 a.out do_sys_open temp.1
do_sys_open+0x1 [kernel]
do_syscall_64+0x5b [kernel]
entry_SYSCALL_64_after_hwframe+0x44 [kernel]
__open_nocancel+0x7 [libc-2.17.so]
__libc_start_main+0xf5 [libc-2.17.so]
9558 9558 a.out do_sys_open temp.2
do_sys_open+0x1 [kernel]
do_syscall_64+0x5b [kernel]
entry_SYSCALL_64_after_hwframe+0x44 [kernel]
__open_nocancel+0x7 [libc-2.17.so]
__libc_start_main+0xf5 [libc-2.17.so]

Process name filter is porting from tools/opensnoop

# trace 'do_sys_open "%s", arg2' -UK -n out
Expand Down Expand Up @@ -300,6 +319,8 @@ optional arguments:
-t, --timestamp print timestamp column (offset from trace start)
-T, --time print time column
-n NAME, --name NAME only print process names containing this name
-f MSG_FILTER, --msg-filter MSG_FILTER
only print message of event containing this string
-C, --print_cpu print CPU id
-B, --bin_cmp allow to use STRCMP with binary values
-K, --kernel-stack output kernel stack trace
Expand All @@ -318,6 +339,8 @@ trace 'do_sys_open "%s", arg2'
Trace the open syscall and print the filename being opened
trace 'do_sys_open "%s", arg2' -n main
Trace the open syscall and only print event that process names containing "main"
trace 'do_sys_open "%s", arg2' -f config
Trace the open syscall and print the filename being opened filtered by "config"
trace 'sys_read (arg3 > 20000) "read %d bytes", arg3'
Trace the read syscall and print a message for reads >20000 bytes
trace 'r::do_sys_open "%llx", retval'
Expand Down

0 comments on commit 5cf529e

Please sign in to comment.