This is the third and final part of our SystemTap series. This article assumes that you are familiar with SystemTap basics and that you have installed Docker on your AWS EC2 instance with a minimal Red Hat Enterprise Linux 7 platform container. Now we’ll explore working with actual SystemTap scripts to monitor processes and events.
Locating the sample SystemTap scripts
Writing SystemTap scripts for the first time can be a rather daunting experience, especially if you do not have much development experience. Fortunately, SystemTap comes with a large collection of sample scripts that you can use right out of the box. These scripts are all archived into the systemtap-client RPM package. The package is installed, along with other related RPM packages, when you install the SystemTap package.
$ rpm -q --whatrequires systemtap-client systemtap-2.6-10.el7_1.x86_64
To find out where the examples are stored, we can list the files in the systemtap-client package.
$ rpm -ql systemtap-client | grep examples | head -5 /usr/share/doc/systemtap-client-2.6/examples /usr/share/doc/systemtap-client-2.6/examples/README /usr/share/doc/systemtap-client-2.6/examples/general /usr/share/doc/systemtap-client-2.6/examples/general/alias_suffixes.meta /usr/share/doc/systemtap-client-2.6/examples/general/alias_suffixes.stp
Once inside the examples directory, take a quick look at the index.txt file, which contains an index of all the examples, along with a short description of what each does, and instructions.
$ cd /usr/share/doc/systemtap-client-2.6/examples $ head index.txt SYSTEMTAP EXAMPLES INDEX (see also keyword-index.txt) general/alias_suffixes.stp - Count I/O Syscalls using Alias Suffixes keywords: io statistics alias_suffixes.stp is a demonstration of how alias suffixes in the systemtap language might be used. The script tracks the wall clock time for each invocation of the system calls open, close, read, and write. When the script exists it prints out the minimum, average, and
We will run these examples on our docker service and the container. So the output examples below will make sense to you, remember that “PID 1752” refers to the docker service, and “PID 4847” refers to the docker container.
$ ps aux | grep docker | head -2
$ ps aux | grep docker | head -2 root 1752 0.2 2.2 510948 22644 ? Ssl 04:17 0:01 /usr/bin/docker -d --selinux-enabled --add-registry registry.access.redhat.com root 1752 0.2 2.2 510948 22644 ? Ssl 04:17 0:01 /usr/bin/docker -d --selinux-enabled --add-registry registry.access.redhat.com ec2-user 4847 0.0 0.7 136348 7412 pts/0 Sl+ 04:27 0:00 docker run -ti rhel7 /bin/bash
pfiles.stp
The pfiles.stp script was written to produce outputs similar to a well-known Solaris tool. It reports on all open files, selected by the process ID. This tool is useful because it gives you more detail than what you would get by looking at the /proc/PID/fd directory, or by using the netstat command.
pfiles.stp is able to list all the open file descriptors along with permissions, user and group IDs, and flags used with the open(3) function call. We also get information about things like open sockets, the peername, and sock options.
$ stap -g pfiles.stp -x 4847 # docker service
4847: docker
Current rlimit: 256 file descriptors
0: S_IFCHR mode:0620 dev:0,11 ino:3 uid:1000 gid:1000 rdev:136,0
O_RDWR|O_LARGEFILE
/dev/pts/0
1: S_IFCHR mode:0620 dev:0,11 ino:3 uid:1000 gid:1000 rdev:136,0
O_RDWR|O_LARGEFILE
/dev/pts/0
2: S_IFCHR mode:0620 dev:0,11 ino:3 uid:1000 gid:1000 rdev:136,0
O_RDWR|O_LARGEFILE
/dev/pts/0
3: S_IFSOCK mode:0777 dev:0,6 ino:67819 uid:1000 gid:1000 rdev:0,0
O_RDWR|O_NONBLOCK FD_CLOEXEC
socket:[67819]
SO_BROADCAST,SO_TYPE(2),SO_SNDBUF(212992),SO_RCVBUF(212992)
sockname: AF_UNIX
peername: AF_UNIX /run/systemd/journal/socket
4: mode:0600 dev:0,9 ino:4680 uid:1000 gid:1000 rdev:0,0
O_RDWR FD_CLOEXEC
anon_inode:[eventpoll]
5: S_IFSOCK mode:0777 dev:0,6 ino:67907 uid:1000 gid:1000 rdev:0,0
O_RDWR|O_NONBLOCK FD_CLOEXEC
socket:[67907]
SO_BROADCAST,SO_TYPE(1),SO_SNDBUF(212992),SO_RCVBUF(212992)
sockname: AF_UNIX
peername: AF_UNIX /var/run/docker.sock
peercred pid: 1752
6: S_IFSOCK mode:0777 dev:0,6 ino:67820 uid:1000 gid:1000 rdev:0,0
O_RDWR|O_NONBLOCK FD_CLOEXEC
socket:[67820]
SO_BROADCAST,SO_TYPE(1),SO_SNDBUF(212992),SO_RCVBUF(212992)
sockname: AF_UNIX
peername: AF_UNIX /var/run/docker.sock
peercred pid: 1752
plimit.stp
The plimit.stp script is another tool inspired by the Solaris world. You can use the script to display the user limits of any running process in the instance. This is useful if you are trying to troubleshoot a process that was not started on the command-line. For example, if a process crashes randomly, and you were unable to capture the coredump of the process, running plimit.stp will tell you the user limits of the process without modifying any files.
$ stap -g plimit.stp -x 4847 # docker container 4847: -docker resource current maximum coredump(blocks) 0 unlimited data(bytes) unlimited unlimited max nice 0 0 file size(blocks) unlimited unlimited pending signals 3836 3836 max locked memory(bytes) 65536 65536 max memory size(bytes) unlimited unlimited open files 1024 4096 POSIX message queues(bytes) 819200 819200 max rt priority 0 0 stack size(bytes) 8388608 unlimited cpu time(seconds) unlimited unlimited max user processes 3836 3836 virtual memory(bytes) unlimited unlimited file locks unlimited unlimited
errsnoop.stp
The errsnoop.stp script prints out a list of failing system calls every five seconds. You can find out what these error strings mean by referring to the errno(3) manpages. This is particularly useful if a process takes a long time to start or has trouble accessing certain resources. Here, it’s interesting to see that our docker service is unable to open /proc/stat:
$ ./errsnoop.stp | grep docker 5 13/EACCES open docker 1752 "/proc/stat", O_RDONLY|O_CLOEXEC 5 128/EKEYREVOKED read docker 1752 13, 0xc20814f800, 128 5 1/EPERM futex docker 1752 0x12c4100, FUTEX_WAKE, 1 5 1/EPERM futex docker 1752 0xc208582b58, FUTEX_WAKE, 1 1 110/ETIMEDOUT futex docker 1752 0x12c3db8, FUTEX_WAIT, 0, [0.999796991] 1 110/ETIMEDOUT futex docker 1752 0x12c3db8, FUTEX_WAIT, 0, [0.999827729] 1 110/ETIMEDOUT futex docker 1752 0x12c3db8, FUTEX_WAIT, 0, [0.999799954] 1 110/ETIMEDOUT futex docker 1752 0x12c3db8, FUTEX_WAIT, 0, [0.999841908]
procmod_watcher.stp
The procmod_watcher.stp script logs whenever a process is created or terminated and whenever a kernel module is loaded or unloaded.
In this example, we ran the script with the command “sudo systemctl restart docker.” Unless you are very familiar with systemctl, it may not be so easy to figure out exactly what systemctl is doing when you restart docker. Fortunately, SystemTap can help:
$ stap procmod_watcher.stp -c "sudo systemctl restart docker" | grep docker
0.011810: EXEC: (8171) stapio: file "/usr/local/bin/sudo" "systemctl" "restart" "docker"
0.011819: EXEC: (8171) stapio: file "/usr/bin/sudo" "systemctl" "restart" "docker"
0.017636: EXEC: (8174) sudo: file "/bin/systemctl" "restart" "docker"
0.035394: EXIT: (8114) docker: exit code 0
0.035434: EXIT: (8114) docker: exit code 0
0.035451: EXIT: (8114) docker: exit code 0
0.035456: EXIT: (8114) docker: exit code 0
0.035460: EXIT: (8114) docker: exit code 0
0.035468: EXIT: (8114) docker: exit code 0
0.041299: EXEC: (8178) (ge-setup): file "/usr/bin/docker-storage-setup"
0.045473: EXEC: (8179) docker-storage-: file "/usr/bin/awk" "$2 ~ /^\\/$/ && $1 !~ /rootfs/ { print $1 }" "/proc/mounts"
0.046951: EXEC: (8181) docker-storage-: file "/usr/sbin/lvs" "--noheadings" "-o" "vg_name" "/dev/xvda2"
0.049275: EXEC: (8182) docker-storage-: file "/usr/bin/sed" "-e" "s/^ *//" "-e" "s/ *$//"
0.053543: EXIT: (8180) docker-storage-: exit code 0
0.054163: EXEC: (8186) docker-storage-: file "/usr/bin/awk" "$2 ~ /^$/ { print $1 }"
0.054828: EXEC: (8185) docker-storage-: file "/usr/sbin/pvs" "--noheadings" "-o" "pv_name,vg_name"
0.060271: EXIT: (8184) docker-storage-: exit code 0
0.060702: EXEC: (8188) docker-storage-: file "/usr/bin/grep" "-e" "^DOCKER_STORAGE_OPTIONS=.*dm\\.datadev" "-e" "^DOCKER_STORAGE_OPTIONS=.*dm\\.metadatadev" "/etc/sysconfig/docker-storage"
0.062484: EXEC: (8192) docker-storage-: file "/usr/bin/grep" "-e" "^DOCKER_STORAGE_OPTIONS=" "/etc/sysconfig/docker-storage"
0.063171: EXEC: (8193) docker-storage-: file "/usr/bin/sed" "s/DOCKER_STORAGE_OPTIONS=//"
0.063873: EXEC: (8194) docker-storage-: file "/usr/bin/sed" "s/^ *//"
0.064545: EXIT: (8191) docker-storage-: exit code 0
0.064686: EXIT: (8190) docker-storage-: exit code 0
0.064822: EXIT: (8189) docker-storage-: exit code 0
0.065364: EXEC: (8196) docker-storage-: file "/usr/sbin/lvs" "--noheadings" "-o" "lv_name,lv_attr" "--separator" ","
0.067287: EXEC: (8197) docker-storage-: file "/usr/bin/sed" "-e" "s/^ *//"
0.069905: EXIT: (8195) docker-storage-: exit code 0
0.070225: EXEC: (8199) docker-storage-: file "/usr/sbin/lvs" "-a" "/docker-poolmeta" "--noheadings"
0.074710: EXIT: (8201) docker-storage-: exit code 0
0.075442: EXEC: (8202) docker-storage-: file "/usr/sbin/vgs" "--noheadings" "--nosuffix" "--units" "b" "-o" "vg_free"
0.079933: EXEC: (8206) docker-storage-: file "/usr/sbin/vgs" "--noheadings" "--nosuffix" "--units" "b" "-o" "vg_free"
0.084066: EXIT: (8205) docker-storage-: exit code 0
0.084248: EXIT: (8204) docker-storage-: exit code 0
0.084526: EXEC: (8208) docker-storage-: file "/usr/sbin/lvcreate" "-y" "-L" "2G" "-n" "docker-pool"
0.088921: EXIT: (8178) docker-storage-: exit code 3
0.092796: EXEC: (8210) (docker): file "/usr/bin/docker" "-d" "--selinux-enabled" "--add-registry" "registry.access.redhat.com"
0.136584: EXEC: (8232) docker: file "/usr/sbin/blkid" "-s" "UUID" "-o" "value" "/dev/mapper/docker-202:2-51421425-base"
0.143531: EXEC: (8235) docker: file "/usr/sbin/modprobe" "-va" "bridge" "nf_nat" "br_netfilter"
0.150252: EXEC: (8237) docker: file "/usr/sbin/iptables" "--wait" "-L" "-n"
0.152227: EXEC: (8238) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-D" "PREROUTING" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER"
0.153454: EXEC: (8239) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-D" "OUTPUT" "-m" "addrtype" "--dst-type" "LOCAL" "!" "--dst" "127.0.0.0/8" "-j" "DOCKER"
0.154539: EXEC: (8240) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-D" "OUTPUT" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER"
0.155566: EXEC: (8241) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-D" "PREROUTING"
0.157902: EXEC: (8242) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-D" "OUTPUT"
0.158890: EXEC: (8243) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-F" "DOCKER"
0.159845: EXEC: (8244) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-X" "DOCKER"
0.161416: EXEC: (8245) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-C" "POSTROUTING" "-s" "172.17.42.1/16" "!" "-o" "docker0" "-j" "MASQUERADE"
0.162433: EXEC: (8246) docker: file "/usr/sbin/iptables" "--wait" "-D" "FORWARD" "-i" "docker0" "-o" "docker0" "-j" "DROP"
0.163386: EXEC: (8247) docker: file "/usr/sbin/iptables" "--wait" "-t" "filter" "-C" "FORWARD" "-i" "docker0" "-o" "docker0" "-j" "ACCEPT"
0.164340: EXEC: (8248) docker: file "/usr/sbin/iptables" "--wait" "-t" "filter" "-C" "FORWARD" "-i" "docker0" "!" "-o" "docker0" "-j" "ACCEPT"
0.165282: EXEC: (8249) docker: file "/usr/sbin/iptables" "--wait" "-t" "filter" "-C" "FORWARD" "-o" "docker0" "-m" "conntrack" "--ctstate" "RELATED,ESTABLISHED" "-j" "ACCEPT"
0.166313: EXEC: (8250) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-n" "-L" "DOCKER"
0.167186: EXEC: (8251) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-N" "DOCKER"
0.168139: EXEC: (8252) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-C" "PREROUTING" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER"
0.169198: EXEC: (8253) docker: file "/usr/sbin/iptables" "-t" "nat" "-S" "PREROUTING"
0.170098: EXEC: (8254) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-A" "PREROUTING" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER"
0.171181: EXEC: (8255) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-C" "OUTPUT" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER" "!" "--dst" "127.0.0.0/8"
0.172222: EXEC: (8256) docker: file "/usr/sbin/iptables" "-t" "nat" "-S" "OUTPUT"
0.173137: EXEC: (8257) docker: file "/usr/sbin/iptables" "--wait" "-t" "nat" "-A" "OUTPUT" "-m" "addrtype" "--dst-type" "LOCAL" "-j" "DOCKER" "!" "--dst" "127.0.0.0/8"
0.174241: EXEC: (8258) docker: file "/usr/sbin/iptables" "--wait" "-t" "filter" "-n" "-L" "DOCKER"
0.175224: EXEC: (8259) docker: file "/usr/sbin/iptables" "--wait" "-t" "filter" "-C" "FORWARD" "-o" "docker0" "-j" "DOCKER"
WARNING: Number of errors: 0, skipped probes: 2
I do wonder, however, why we are not using firewall-cmd – since that is the new way to interact with netfilter. Perhaps you might have some insights to share in our comments.
I hope this gives you a sense of just how powerful SystemTap can be. Let this be the beginning of your learning journey.
