I've been taking some time to study the BPF Performance Tools book by Brendan Gregg.
There's a been a lot of partial resources and tips about using BPF, and it has already helped me to find an epic memory leak. I always wanted to get a chance to learn it deeper and the release of Gregg's book was a good cause. My colleague from Shopify's ProdEng team Dale Hamel helped to review the book too, which only pumped my interest about the technology.
When it comes to observability, the most impact (IMO) from being able to trace something really quickly and find the root cause is during incidents, when it's not clear what's happening and pulling the right observability tool from your hat is the top skill. That's the muscle that I'd want to extract from the book, and writing notes in "what I've learned" format will hopefully help.
This post is a collection of notes taken while getting my hands dirty with each of the tools, as the book goes.
0. Getting bpfcc-tools ready
Turns out that apt-get install bpfcc-tools on Ubuntu 18.04 Bionic is broken, as I'm writing this in December 2019. Thankfully it's fixed in the upstream, and I documented steps how to install a nightly package.
1. execsnoop
execsnoop prints all processes that were launched (aka trace exec() syscalls). In the real life, it might come handy to inspect external calls coming from the application server (for instance, imagemagick).
Steps I've taken:
-
Open a terminal tab, SSH to the devbox, run
sudo /usr/share/bcc/tools/execsnoop -
SSH to the same VM from another terminal tab, observe
execsnoopin tab 1) printing all the commands that were executed during the login:
PCOMM PID PPID RET ARGS
sshd 5429 1430 0 /usr/sbin/sshd -D -R
sh 5431 5429 0
env 5432 5431 0 /usr/bin/env -i PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin run-parts --lsbsysinit /etc/update-motd.d
run-parts 5432 5431 0 /bin/run-parts --lsbsysinit /etc/update-motd.d
00-header 5433 5432 0 /etc/update-motd.d/00-header
uname 5434 5433 0 /bin/uname -o
uname 5435 5433 0 /bin/uname -r
uname 5436 5433 0 /bin/uname -m
10-help-text 5437 5432 0 /etc/update-motd.d/10-help-text
50-landscape-sy 5438 5432 0 /etc/update-motd.d/50-landscape-sysinfo
grep 5439 5438 0 /bin/grep -c ^processor /proc/cpuinfo
cut 5443 5441 0 /usr/bin/cut -f1 -d /proc/loadavg
bc 5442 5440 0 /usr/bin/bc
date 5444 5438 0 /bin/date
landscape-sysin 5445 5438 0 /usr/bin/landscape-sysinfo
ldconfig 5446 5445 0 /sbin/ldconfig -p
ldconfig.real 5446 5445 0 /sbin/ldconfig.real -p
ldconfig 5447 5445 0 /sbin/ldconfig -p
ldconfig.real 5447 5445 0 /sbin/ldconfig.real -p
who 5449 5445 0 /usr/bin/who -q
50-motd-news 5450 5432 0 /etc/update-motd.d/50-motd-news
cat 5451 5450 0 /bin/cat /var/cache/motd-news
tr 5453 5450 0 /usr/bin/tr -d \000-\011\013\014\016-\037
head 5452 5450 0 /usr/bin/head -n 10
cut 5454 5450 0 /usr/bin/cut -c -80
80-esm 5455 5432 0 /etc/update-motd.d/80-esm
lsb_release 5456 5455 0 /usr/bin/lsb_release -cs
lsb_release 5457 5455 0 /usr/bin/lsb_release -ds
80-livepatch 5458 5432 0 /etc/update-motd.d/80-livepatch
90-updates-avai 5459 5432 0 /etc/update-motd.d/90-updates-available
cat 5460 5459 0 /bin/cat /var/lib/update-notifier/updates-available
91-release-upgr 5461 5432 0 /etc/update-motd.d/91-release-upgrade
cut 5464 5462 0 /usr/bin/cut -d -f4
lsb_release 5463 5462 0 /usr/bin/lsb_release -sd
release-upgrade 5461 5432 0 /usr/lib/ubuntu-release-upgrader/release-upgrade-motd
date 5465 5461 0 /bin/date +%s
stat 5466 5461 0 /usr/bin/stat -c %Y /var/lib/ubuntu-release-upgrader/release-upgrade-available
expr 5467 5461 0 /usr/bin/expr 1577101965 + 86400
95-hwe-eol 5468 5432 0 /etc/update-motd.d/95-hwe-eol
update-motd-hwe 5468 5432 0 /usr/lib/update-notifier/update-motd-hwe-eol
apt-config 5469 5468 0 /usr/bin/apt-config shell StateDir Dir::State
dpkg 5470 5469 0 /usr/bin/dpkg --print-foreign-architectures
apt-config 5471 5468 0 /usr/bin/apt-config shell ListDir Dir::State::Lists
dpkg 5472 5471 0 /usr/bin/dpkg --print-foreign-architectures
apt-config 5473 5468 0 /usr/bin/apt-config shell DpkgStatus Dir::State::status
dpkg 5474 5473 0 /usr/bin/dpkg --print-foreign-architectures
apt-config 5475 5468 0 /usr/bin/apt-config shell EtcDir Dir::Etc
dpkg 5476 5475 0 /usr/bin/dpkg --print-foreign-architectures
apt-config 5477 5468 0 /usr/bin/apt-config shell SourceList Dir::Etc::sourcelist
dpkg 5478 5477 0 /usr/bin/dpkg --print-foreign-architectures
find 5479 5468 0 /usr/bin/find /var/lib/apt/lists/ /etc/apt/sources.list //var/lib/dpkg/status -type f -newer /var/lib/update-notifier/hwe-eol -print -quit
dirname 5481 5480 0 /usr/bin/dirname /var/lib/update-notifier/hwe-eol
mktemp 5480 5468 0 /bin/mktemp -p /var/lib/update-notifier
cat 5482 5468 0 /bin/cat /var/lib/update-notifier/hwe-eol
rm 5483 5468 0 /bin/rm -f /var/lib/update-notifier/tmp.RjVbtK5reS
97-overlayroot 5484 5432 0 /etc/update-motd.d/97-overlayroot
egrep 5486 5485 0 /bin/egrep overlayroot|/media/root-ro|/media/root-rw /proc/mounts
sort 5487 5485 0 /usr/bin/sort -r
grep 5486 5485 0 /bin/grep -E overlayroot|/media/root-ro|/media/root-rw /proc/mounts
98-fsck-at-rebo 5488 5432 0 /etc/update-motd.d/98-fsck-at-reboot
update-motd-fsc 5488 5432 0 /usr/lib/update-notifier/update-motd-fsck-at-reboot
stat 5489 5488 0 /usr/bin/stat -c %Y /var/lib/update-notifier/fsck-at-reboot
awk 5491 5490 0 /usr/bin/awk {print $1} /proc/uptime
date 5490 5488 0 /bin/date -d now - 1614.44 seconds +%s
date 5492 5488 0 /bin/date +%s
cat 5493 5488 0 /bin/cat /var/lib/update-notifier/fsck-at-reboot
98-reboot-requi 5494 5432 0 /etc/update-motd.d/98-reboot-required
update-motd-reb 5494 5432 0 /usr/lib/update-notifier/update-motd-reboot-required
bash 5496 5495 0 /bin/bash
groups 5498 5497 0 /usr/bin/groups
locale-check 5500 5499 0 /usr/bin/locale-check C.UTF-8
locale 5501 5496 0 /usr/bin/locale
lesspipe 5504 5503 0 /usr/bin/lesspipe
basename 5505 5504 0 /usr/bin/basename /usr/bin/lesspipe
dirname 5507 5506 0 /usr/bin/dirname /usr/bin/lesspipe
dircolors 5509 5508 0 /usr/bin/dircolors -b
Turns out there's a lot of stuff involved when you ssh and login into a terminal session.
2. biolatency
biolatency prints stats about I/O latency as a diagram. In the past, I've seen my colleagues using it to debug slow disks in cloud, which might be especially critical for latency-sensitive workloads like DBs.
Steps I've taken:
-
Install
fio(I/O tester) on a VM with standard disk (pd-standardon Google Cloud) and run a sample test:$ fio --randrepeat=1 --ioengine=libaio --direct=1 --gtod_reduce=1 --name=test --filename=random_read_write.fio --bs=4k --iodepth=64 --size=4G --readwrite=randrw --rwmixread=75 -
Run
biolatencyin another tab:
$ sudo /usr/share/bcc/tools/biolatency -D
Tracing block device I/O... Hit Ctrl-C to end.
^C
disk = 'sda'
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 1 | |
32 -> 63 : 14 | |
64 -> 127 : 7 | |
128 -> 255 : 1 | |
256 -> 511 : 0 | |
512 -> 1023 : 8 | |
1024 -> 2047 : 9 | |
2048 -> 4095 : 30 | |
4096 -> 8191 : 49 | |
8192 -> 16383 : 172 | |
16384 -> 32767 : 298 |* |
32768 -> 65535 : 395 |* |
65536 -> 131071 : 758 |*** |
131072 -> 262143 : 1290 |***** |
262144 -> 524287 : 9138 |****************************************|
The latency seems pretty high!
- Provision another VM with a local SSD and re-run the command:
disk = 'nvme0n1'
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 47812 |**** |
64 -> 127 : 171016 |*************** |
128 -> 255 : 448958 |****************************************|
256 -> 511 : 136858 |************ |
512 -> 1023 : 50191 |**** |
1024 -> 2047 : 69666 |****** |
2048 -> 4095 : 57147 |***** |
4096 -> 8191 : 7615 | |
8192 -> 16383 : 246 | |
16384 -> 32767 : 47 | |
32768 -> 65535 : 41 | |
65536 -> 131071 : 120 | |
131072 -> 262143 : 298 | |
262144 -> 524287 : 511 | |
524288 -> 1048575 : 1263 | |
1048576 -> 2097151 : 1658 | |
2097152 -> 4194303 : 152 | |
As expected, switching to SSD gives much lower latency.
3. opensnoop
opensnoop traces all files that were open on the system (aka trace open() syscalls).
Steps I've taken:
- In one tab, run
sudo /usr/share/bcc/tools/opensnoop(optionally pass-nto scope it to a specific app) - In another tab, run some user app (in my case it was ProxySQL since I've already had it compiled on that devbox)
- Observe files that ProxySQL attempted to open:
$ sudo /usr/share/bcc/tools/opensnoop -n proxysql
PID COMM FD ERR PATH
2470 proxysql 3 0 /etc/ld.so.cache
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libgnutls.so.30
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libpthread.so.0
2470 proxysql 3 0 /lib/x86_64-linux-gnu/librt.so.1
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libdl.so.2
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libstdc++.so.6
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libm.so.6
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libgcc_s.so.1
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libc.so.6
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libz.so.1
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libp11-kit.so.0
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libidn2.so.0
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libunistring.so.2
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libtasn1.so.6
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libnettle.so.6
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libhogweed.so.4
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libgmp.so.10
2470 proxysql 3 0 /usr/lib/x86_64-linux-gnu/libffi.so.6
2470 proxysql 3 0 /proc/sys/vm/overcommit_memory
2470 proxysql 3 0 /sys/kernel/mm/transparent_hugepage/enabled
2470 proxysql 3 0 /etc/nsswitch.conf
2470 proxysql 3 0 /etc/ld.so.cache
2470 proxysql -1 2 /lib/x86_64-linux-gnu/tls/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/tls/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64-linux-gnu/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/tls/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/tls/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64-linux-gnu/libnss_db.so.2
2470 proxysql -1 2 /lib/tls/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/tls/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/x86_64/libnss_db.so.2
2470 proxysql -1 2 /lib/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/tls/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/tls/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/tls/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/x86_64/libnss_db.so.2
2470 proxysql -1 2 /usr/lib/libnss_db.so.2
2470 proxysql 3 0 /etc/ld.so.cache
2470 proxysql 3 0 /lib/x86_64-linux-gnu/libnss_files.so.2
2470 proxysql 3 0 /etc/services
2470 proxysql -1 2 /usr/local/ssl/openssl.cnf
2470 proxysql 3 0 /etc/localtime
2470 proxysql 3 0 /dev/urandom
2470 proxysql 3 0 /home/kir/proxysql-key.pem
2470 proxysql 3 0 /home/kir/proxysql-cert.pem
2470 proxysql 3 0 /usr/bin/proxysql
2470 proxysql 4 0 /home/kir/proxysql.pid
Under the hood, opensnoop is just a fancy wrapper around sudo bpftrace -e 'tracepoint:syscalls:sys_enter_open*.
However, tracing open() syscalls only shows files that were opened, but not files that were attempted to open but didn't exist. This might come useful if you want to trace an app that's failing due some config file that doesn't exist.
A common scanerio could be:
if File.exist?(path/to/config)
File.open(path/to/config)
else
# some other behaviour
end
In my case, it was ProxySQL failing to start because it couldn't find the config file:
$ proxysql
2019-12-25 18:26:58 main.cpp:829:ProxySQL_Main_process_global_variables(): [WARNING] Unable to open config file /etc/proxysql.cnf
[Warning]: Cannot open any default config file . Using default datadir in current working directory /home/kir
...
Let's find a syscall that attempts (and fails) to read /etc/proxysql.cnf. From what I found, it's the access syscall that is used to check for file existance. It was easy enough to come up with a BPF instruction.
$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_access { printf("%s %s\n", comm, str
Attaching 1 probe...
proxysql /etc/ld.so.preload
proxysql /etc/proxysql.cnf
proxysql /home/kir/proxysql-key.pem
proxysql /home/kir/proxysql-cert.pem
proxysql /home/kir/proxysql-ca.pem
Also at this point, I've started to peak and learn syntax for bpftrace, as opposed to user-friendly tools around it like opensnoop.
Maybe I could even find the stacktrace?
$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_access { printf("%s %s %s\n", comm, str(args->filename), ustack); }'
Attaching 1 probe...
proxysql /etc/ld.so.preload
0x7f4cdaf6e9d7
0x7f4cdaf6c9ef
0x40
proxysql /etc/proxysql.cnf
access+7
0x6e632e6c71737978
...
Not much info from the stack trace anyways. Debugging symbols must be missing. Let's try to recompile ProxySQL with make debug:
$ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_access { printf("%s %s %s\n", comm, str(args->filename), ustack); }'
proxysql /etc/ld.so.preload
0x7f95ff32f9d7
0x7f95ff32d9ef
0x40
proxysql /etc/proxysql.cnf
0x7f95fed0a0e7
_ZN19ProxySQL_ConfigFile8OpenFileEPKc+94
_Z38ProxySQL_Main_process_global_variablesiPPKc+125
main+115
0x7f95fec23b6b
0x41fd89415541f689
Yay! Now we can know that it's the ProxySQL_ConfigFile8OpenFileEPK function that checks for existance of /etc/proxysql.cnf using access() syscall.
Inspecting failed DNS queries
I wanted to play more with the raw bpftrace -e and I came up with an actual problem from production that would be interesting to debug.
At work, I observed a tiny percentage of RPCs failing due DNS lookups timing out. I don't have an idea yet why that might be happening, but with BPF I could at least observe those events better.
DNS resolution is done by getaddrinfo(3). I found gethostlatency.bt in bpftrace samples code which observes DNS resolution latency - something close to my case.
Here is the gist of it:
uprobe:/lib/x86_64-linux-gnu/libc.so.6:getaddrinfo,
uprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname,
uprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname2
{
@start[tid] = nsecs;
@name[tid] = arg0;
}
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:getaddrinfo,
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname,
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname2
/@start[tid]/
{
$latms = (nsecs - @start[tid]) / 1000000;
time("%H:%M:%S ");
printf("%-6d %-16s %6d %s\n", pid, comm, $latms, str(@name[tid]));
delete(@start[tid]);
delete(@name[tid]);
}
The way I understand it, it does the following:
- Capture the start of a user-land probe
getaddrinfo/gethostbyname/gethostbyname2 - Record the timestamp and the host
- Capture the end of
getaddrinfo/gethostbyname/gethostbyname2probe - Print the summary about the trace, including the delta of timestamps
What I'm looking for, is to only print failed DNS lookups. Luckily, the end capture (uretprobe) contains the retval (return value) field. According to getaddrinfo(3) docs, non-zero return code means it failed. Let's filter by that:
BEGIN
{
printf("Tracing getaddr/gethost calls... Hit Ctrl-C to end.\n");
printf("%-9s %-6s %-16s %6s %s\n", "TIME", "PID", "COMM", "LATms",
"HOST");
}
uprobe:/lib/x86_64-linux-gnu/libc.so.6:getaddrinfo,
uprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname,
uprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname2
{
@name[tid] = arg0;
}
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:getaddrinfo,
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname,
uretprobe:/lib/x86_64-linux-gnu/libc.so.6:gethostbyname2
{
if (retval != 0 ) { // for some reason retval < 0 didn't work in if statement
time("%H:%M:%S ");
printf("failed | %-6d %-16s (error: %d) %s\n", pid, comm, retval, str(@name[tid]));
};
delete(@name[tid]);
}
Now, how do I locally reproduce a failing DNS lookup? The way to stub that I've learned earlier it is to point resolv to a non-existing DNS server:
// find your original DNS server
$ cat /etc/resolv.conf |grep -i '^nameserver'|head -n1|cut -d ' ' -f2
// to take DNS down and point it to 127.0.0.1:
$ echo "$(sed 's/<your-original-DNS-server>/127.0.0.1/g' /etc/resolv.conf)" > /etc/resolv.conf
// to take DNS back up:
$ echo "$(sed 's/127.0.0.1/<your-original-DNS-server>/g' /etc/resolv.conf)" > /etc/resolv.conf
Now, with the probe running, we can try to hit curl google.com (which will fail on name lookup) and see the following output from bpftrace:
20:28:19 failed | 24087 curl (error -3) google.com
Hurray!
There's probably another story for how to long-run that safely in production environment, which I'm yet to learn.
These are my notes for what I've learned so far from the BPF book, and I'm only 1/4 way through. Let's see what the rest of the book brings.
The goal of publishing this is mostly for me to be able to come back and revisit some steps from what I've documented, but I hope it could be useful for others too.
I'm eager to learn if there's anything here that I misunderstood or something that could be done better - please feel free to contact me on Twitter and point it out.
Also, thanks to my friend Javier Honduco for walking me over and explaining some of those things I've learned.
