From bedd150395624791a73be4f7a58983445198b48c Mon Sep 17 00:00:00 2001 From: Brendan Gregg Date: Thu, 17 Sep 2015 21:52:52 -0700 Subject: [PATCH] opensnoop --- README.md | 1 + man/man8/opensnoop.8 | 86 +++++++++++++++++++++++++++ tools/opensnoop | 109 ++++++++++++++++++++++++++++++++++ tools/opensnoop_example.txt | 115 ++++++++++++++++++++++++++++++++++++ 4 files changed, 311 insertions(+) create mode 100644 man/man8/opensnoop.8 create mode 100755 tools/opensnoop create mode 100644 tools/opensnoop_example.txt diff --git a/README.md b/README.md index 98290556553f..5ddc811df260 100644 --- a/README.md +++ b/README.md @@ -66,6 +66,7 @@ Tools: - tools/[biosnoop](tools/biosnoop): Trace block device I/O with PID and latency. [Examples](tools/biosnoop_example.txt). - tools/[funccount](tools/funccount): Count kernel function calls. [Examples](tools/funccount_example.txt). +- tools/[opensnoop](tools/opensnoop): Trace open() syscalls. [Examples](tools/opensnoop_example.txt). - tools/[pidpersec](tools/pidpersec): Count new processes (via fork). [Examples](tools/pidpersec_example.txt). - tools/[syncsnoop](tools/syncsnoop): Trace sync() syscall. [Examples](tools/syncsnoop_example.txt). - tools/[vfscount](tools/vfscount) tools/[vfscount.c](tools/vfscount.c): Count VFS calls. [Examples](tools/vfscount_example.txt). diff --git a/man/man8/opensnoop.8 b/man/man8/opensnoop.8 new file mode 100644 index 000000000000..d22cb179bb7a --- /dev/null +++ b/man/man8/opensnoop.8 @@ -0,0 +1,86 @@ +.TH opensnoop 8 "2015-08-18" "USER COMMANDS" +.SH NAME +opensnoop \- Trace open() syscalls. Uses Linux eBPF/bcc. +.SH SYNOPSIS +.B opensnoop [\-h] [\-t] [\-x] [\-p PID] +.SH DESCRIPTION +opensnoop traces the open() syscall, showing which processes are attempting +to open which files. This can be useful for determining the location of config +and log files, or for troubleshooting applications that are failing, especially +on startup. + +This works by tracing the kernel sys_open() function using dynamic tracing, and +will need updating to match any changes to this function. + +Since this uses BPF, only the root user can use this tool. +.SH REQUIREMENTS +CONFIG_BPF and bcc. +.SH OPTIONS +.TP +\-h +Print usage message. +.TP +\-t +Include a timestamp column. +.TP +\-x +Only print failed opens. +.TP +\-p PID +Trace this process ID only (filtered in-kernel). +.SH EXAMPLES +.TP +Trace all open() syscalls: +# +.B opensnoop +.TP +Trace all open() syscalls, and include timestamps: +# +.B opensnoop \-t +.TP +Trace only open() syscalls that failed: +# +.B opensnoop \-x +.TP +Trace PID 181 only: +# +.B opensnoop \-p 181 +.SH FIELDS +.TP +TIME(s) +Time of the call, in seconds. +.TP +PID +Process ID +.TP +COMM +Process name +.TP +FD +File descriptor (if success), or -1 (if failed) +.TP +ERR +Error number (see the system's errno.h) +.TP +PATH +Open path +.SH OVERHEAD +This traces the kernel open function and prints output for each event. As the +rate of this is generally expected to be low (< 1000/s), the overhead is also +expected to be negligible. If you have an application that is calling a high +rate of open()s, then test and understand overhead before use. +.SH SOURCE +This is from bcc. +.IP +https://github.com/iovisor/bcc +.PP +Also look in the bcc distribution for a companion _examples.txt file containing +example usage, output, and commentary for this tool. +.SH OS +Linux +.SH STABILITY +Unstable - in development. +.SH AUTHOR +Brendan Gregg +.SH SEE ALSO +funccount(1) diff --git a/tools/opensnoop b/tools/opensnoop new file mode 100755 index 000000000000..8b1a5be50613 --- /dev/null +++ b/tools/opensnoop @@ -0,0 +1,109 @@ +#!/usr/bin/python +# +# opensnoop Trace open() syscalls. +# For Linux, uses BCC, eBPF. Embedded C. +# +# USAGE: opensnoop [-h] [-t] [-x] [-p PID] +# +# Copyright (c) 2015 Brendan Gregg. +# Licensed under the Apache License, Version 2.0 (the "License") +# +# 17-Sep-2015 Brendan Gregg Created this. + +from __future__ import print_function +from bcc import BPF +import argparse + +# arguments +examples = """examples: + ./opensnoop # trace all open() syscalls + ./opensnoop -t # include timestamps + ./opensnoop -x # only show failed opens + ./opensnoop -p 181 # only trace PID 181 +""" +parser = argparse.ArgumentParser( + description="Trace open() syscalls", + formatter_class=argparse.RawDescriptionHelpFormatter, + epilog=examples) +parser.add_argument("-t", "--timestamp", action="store_true", + help="include timestamp on output") +parser.add_argument("-x", "--failed", action="store_true", + help="only show failed opens") +parser.add_argument("-p", "--pid", + help="trace this PID only") +args = parser.parse_args() +debug = 0 + +# define BPF program +bpf_text = """ +#include + +BPF_HASH(args_filename, u32, const char *); + +int kprobe__sys_open(struct pt_regs *ctx, const char __user *filename) +{ + u32 pid = bpf_get_current_pid_tgid(); + + FILTER + args_filename.update(&pid, &filename); + + return 0; +}; + +int kretprobe__sys_open(struct pt_regs *ctx) +{ + const char **filenamep; + int ret = ctx->ax; + u32 pid = bpf_get_current_pid_tgid(); + + filenamep = args_filename.lookup(&pid); + if (filenamep == 0) { + // missed entry + return 0; + } + + bpf_trace_printk("%s %d\\n", *filenamep, ret); + args_filename.delete(&pid); + + return 0; +} +""" +if args.pid: + bpf_text = bpf_text.replace('FILTER', + 'if (pid != %s) { return 0; }' % args.pid) +else: + bpf_text = bpf_text.replace('FILTER', '') +if debug: + print(bpf_text) + +# initialize BPF +b = BPF(text=bpf_text) + +# header +if args.timestamp: + print("%-14s" % ("TIME(s)"), end="") +print("%-6s %-16s %4s %3s %s" % ("PID", "COMM", "FD", "ERR", "PATH")) + +start_ts = 0 + +# format output +while 1: + (task, pid, cpu, flags, ts, msg) = b.trace_fields() + (filenamp, ret_s) = msg.split(" ") + + ret = int(ret_s) + if (args.failed and (ret >= 0)): + continue + + # split return value into FD and errno columns + if ret >= 0: + fd_s = ret; err = 0 + else: + fd_s = "-1"; err = - ret + + # print columns + if args.timestamp: + if start_ts == 0: + start_ts = ts + print("%-14.9f" % (ts - start_ts), end="") + print("%-6d %-16s %4s %3s %s" % (pid, task, fd_s, err, filenamp)) diff --git a/tools/opensnoop_example.txt b/tools/opensnoop_example.txt new file mode 100644 index 000000000000..5a0c7820fdf5 --- /dev/null +++ b/tools/opensnoop_example.txt @@ -0,0 +1,115 @@ +Demonstrations of opensnoop, the Linux eBPF/bcc version. + + +opensnoop traces the open() syscall system-wide, and prints various details. +Example output: + +# ./opensnoop +PID COMM FD ERR PATH +17326 <...> 7 0 /sys/kernel/debug/tracing/trace_pipe +1576 snmpd 9 0 /proc/net/dev +1576 snmpd 11 0 /proc/net/if_inet6 +1576 snmpd 11 0 /proc/sys/net/ipv4/neigh/eth0/retrans_time_ms +1576 snmpd 11 0 /proc/sys/net/ipv6/neigh/eth0/retrans_time_ms +1576 snmpd 11 0 /proc/sys/net/ipv6/conf/eth0/forwarding +1576 snmpd 11 0 /proc/sys/net/ipv6/neigh/eth0/base_reachable_time_ms +1576 snmpd 11 0 /proc/sys/net/ipv4/neigh/lo/retrans_time_ms +1576 snmpd 11 0 /proc/sys/net/ipv6/neigh/lo/retrans_time_ms +1576 snmpd 11 0 /proc/sys/net/ipv6/conf/lo/forwarding +1576 snmpd 11 0 /proc/sys/net/ipv6/neigh/lo/base_reachable_time_ms +1576 snmpd 9 0 /proc/diskstats +1576 snmpd 9 0 /proc/stat +1576 snmpd 9 0 /proc/vmstat +1956 supervise 9 0 supervise/status.new +1956 supervise 9 0 supervise/status.new +17358 run 3 0 /etc/ld.so.cache +17358 run 3 0 /lib/x86_64-linux-gnu/libtinfo.so.5 +17358 run 3 0 /lib/x86_64-linux-gnu/libdl.so.2 +17358 run 3 0 /lib/x86_64-linux-gnu/libc.so.6 +17358 run -1 6 /dev/tty +17358 run 3 0 /proc/meminfo +17358 run 3 0 /etc/nsswitch.conf +17358 run 3 0 /etc/ld.so.cache +17358 run 3 0 /lib/x86_64-linux-gnu/libnss_compat.so.2 +17358 run 3 0 /lib/x86_64-linux-gnu/libnsl.so.1 +17358 run 3 0 /etc/ld.so.cache +17358 run 3 0 /lib/x86_64-linux-gnu/libnss_nis.so.2 +17358 run 3 0 /lib/x86_64-linux-gnu/libnss_files.so.2 +17358 run 3 0 /etc/passwd +17358 run 3 0 ./run +^C + +While tracing, the snmpd process opened various /proc files (reading metrics), +and a "run" process read various libraries and config files (looks like it +was starting up: a new process). + +opensnoop can be useful for discovering configuration and log files, if used +during application startup. + + +The -p option can be used to filter on a PID, which is filtered in-kernel. Here +I've used it with -t to print timestamps: + + ./opensnoop -tp 1956 +TIME(s) PID COMM FD ERR PATH +0.000000000 1956 supervise 9 0 supervise/status.new +0.000289999 1956 supervise 9 0 supervise/status.new +1.023068000 1956 supervise 9 0 supervise/status.new +1.023381997 1956 supervise 9 0 supervise/status.new +2.046030000 1956 supervise 9 0 supervise/status.new +2.046363000 1956 supervise 9 0 supervise/status.new +3.068203997 1956 supervise 9 0 supervise/status.new +3.068544999 1956 supervise 9 0 supervise/status.new + +This shows the supervise process is opening the status.new file twice every +second. + + +The -x option only prints failed opens: + +# ./opensnoop -x +PID COMM FD ERR PATH +18372 run -1 6 /dev/tty +18373 run -1 6 /dev/tty +18373 multilog -1 13 lock +18372 multilog -1 13 lock +18384 df -1 2 /usr/share/locale/en_US.UTF-8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale/en_US.utf8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale/en_US/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale/en.UTF-8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale/en.utf8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale/en/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en_US.UTF-8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en_US.utf8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en_US/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en.UTF-8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en.utf8/LC_MESSAGES/coreutils.mo +18384 df -1 2 /usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo +18385 run -1 6 /dev/tty +18386 run -1 6 /dev/tty + +This caught a df command failing to open a coreutils.mo file, and trying from +different directories. + +The ERR column is the system error number. Error number 2 is ENOENT: no such +file or directory. + + +USAGE message: + +# ./opensnoop -h +usage: opensnoop [-h] [-t] [-x] [-p PID] + +Trace open() syscalls + +optional arguments: + -h, --help show this help message and exit + -t, --timestamp include timestamp on output + -x, --failed only show failed opens + -p PID, --pid PID trace this PID only + +examples: + ./opensnoop # trace all open() syscalls + ./opensnoop -t # include timestamps + ./opensnoop -x # only show failed opens + ./opensnoop -p 181 # only trace PID 181