Merge pull request #229 from brendangregg/master

opensnoop

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).

man/man8/opensnoop.8

+.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)

tools/opensnoop

+#!/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 <uapi/linux/ptrace.h>
+
+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))

tools/opensnoop_example.txt

+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