BPF
Observability
# readahead.bt
Attaching 5 probes...
Readahead unused pages: 128
Readahead used page age (ms):
@age_ms:
[1]
2455 |@@@@@@@@@@@@@@@
[2, 4)
8424 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8)
4417 |@@@@@@@@@@@@@@@@@@@@@@@@@@@
[8, 16)
7680 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[16, 32)
4352 |@@@@@@@@@@@@@@@@@@@@@@@@@@
[32, 64)
0 |
[64, 128)
0 |
[128, 256)
384 |@@
Brendan Gregg
LSFMM
Apr 2019

eBPF

Superpowers Demo

eBPF: extended Berkeley Packet Filter
User-Defined BPF Programs
SDN Configuration
DDoS Mitigation
Kernel
Runtime
Event Targets
verifier
sockets
Intrusion Detection
Container Security
kprobes
BPF
Observability
Firewalls (bpfilter)
Device Drivers
uprobes
tracepoints
BPF
actions
perf_events

>gt;150k AWS EC2 server instances
~34% US Internet traffic at night
>gt;130M members
Performance is customer satisfaction & Netflix cost

Experience: ps(1) failure
(This is from last week...)

Experience: ps(1) failure
# wait for $pid to finish:
while ps -p $pid >gt;/dev/null; do
sleep 1
done
# do stuff...

Experience: ps(1) failure
# wait for $pid to finish:
while ps -p $pid >gt;/dev/null; do
sleep 1
done
# do stuff...
Problem: ps(1) sometimes fails to find the process
Hypothesis: kernel bug!

Experience: ps(1) failure
Which syscall is abnormally failing (without strace(1) )?
# bpftrace -e 't:syscalls:sys_exit_* /comm == "ps"/ {
@[probe, args->gt;ret >gt; 0 ? 0 : - args->gt;ret] = count(); }'
Attaching 316 probes...
[...]
@[tracepoint:syscalls:sys_exit_openat, 2]: 120
@[tracepoint:syscalls:sys_exit_newfstat, 0]: 180
@[tracepoint:syscalls:sys_exit_mprotect, 0]: 230
@[tracepoint:syscalls:sys_exit_rt_sigaction, 0]: 240
@[tracepoint:syscalls:sys_exit_mmap, 0]: 350
@[tracepoint:syscalls:sys_exit_newstat, 0]: 5000
@[tracepoint:syscalls:sys_exit_read, 0]: 10170
@[tracepoint:syscalls:sys_exit_close, 0]: 10190
@[tracepoint:syscalls:sys_exit_openat, 0]: 10190

Experience: ps(1) failure
Which syscall is abnormally failing (without multi-probe)?
# bpftrace -e 't:raw_syscalls:sys_exit /comm == "ps"/ {
@[args->gt;id, args->gt;ret >gt; 0 ? 0 : - args->gt;ret] = count(); }'
Attaching 1 probe...
[...]
@[21, 2]: 120
@[5, 0]: 180
@[10, 0]: 230
@[13, 0]: 240
@[9, 0]: 350
@[4, 0]: 5000
@[0, 0]: 10170
@[3, 0]: 10190
@[257, 0]: 10190

Experience: ps(1) failure
Which syscall is abnormally failing (without multi-probe)?
# bpftrace -e 't:raw_syscalls:sys_exit /comm == "ps"/ {
@[ksym(*(kaddr("sys_call_table") + args->gt;id * 8)),
args->gt;ret >gt; 0 ? 0 : - args->gt;ret] = count(); }'
[...]
@[sys_brk, 0]: 8202
@[sys_ioctl, 25]: 8203
@[sys_access, 2]: 32808
@[SyS_openat, 2]: 32808
@[sys_newfstat, 0]: 49213
caught 1 extra failure
@[sys_newstat, 2]: 60820
@[sys_mprotect, 0]: 62882
ioctl() was a dead end
[...]

Experience: ps(1) failure
Which syscall is successfully failing?
# bpftrace -e 't:syscalls:sys_exit_getdents /comm == "ps"/ {
printf("ret: %d\n", args->gt;ret); }'
[...]
ret: 9192
ret: 0
ret: 9216
ret: 0
ret: 9168
ret: 0
ret: 5640
ret: 0

Experience: ps(1) failure
Which syscall is successfully failing?
# bpftrace -e 't:syscalls:sys_enter_getdents /comm == "ps"/ {
@start[tid] = nsecs; }
t:syscalls:sys_exit_getdents /@start[tid]/ {
printf("%8d us, ret: %d\n", (nsecs - @start[tid]) / 1000,
args->gt;ret); delete(@start[tid]); }'
[...]
559 us, ret: 9640
3 us, ret: 0
516 us, ret: 9576
3 us, ret: 0
373 us, ret: 7720
2 us, ret: 0

Experience: ps(1) failure
/proc debugging
# funccount '*proc*'
Tracing "*proc*"... Ctrl-C to end.^C
FUNC
COUNT
[…]
proc_readdir
proc_readdir_de
proc_root_getattr
process_measurement
kick_process
wake_up_process
proc_pid_readdir
proc_root_readdir
proc_fill_cache

Experience: ps(1) failure
Some quick dead ends
# bpftrace -e 'kr:proc_fill_cache /comm == "ps"/ {
@[retval] = count(); }'
# bpftrace -e 'kr:nr_processes /comm == "ps"/ {
printf("%d\n", retval); }'
# bpftrace -e 'kr:proc_readdir_de /comm == "ps"/ {
printf("%d\n", retval); }'
# bpftrace -e 'kr:proc_root_readdir /comm == "ps"/ {
printf("%d\n", retval); }'
Note: this is all in production

Experience: ps(1) failure
Getting closer to the cause
# bpftrace -e 'k:find_ge_pid /comm == "ps"/ { printf("%d\n", arg0);
success
failure

Experience: ps(1) failure
find_ge_pid() entry argument & return value:
# bpftrace -e 'k:find_ge_pid /comm == "ps"/ { @nr[tid] = arg0; }
kr:find_ge_pid /@nr[tid]/ {
printf("%d: %llx\n", @nr[tid], retval); delete(@nr[tid]); }'
[…]
15561: ffff8a3ee70ad280
15564: ffff8a400244bb80
15569: ffff8a3f6f1a1840
15570: ffff8a3ffe890c00
15571: ffff8a3ffd23bdc0
15575: ffff8a40024fdd80
15576: 0

Experience: ps(1) failure
Kernel source:
struct pid *find_ge_pid(int nr, struct pid_namespace *ns)
return idr_get_next(&ns->gt;idr, &nr);
[…]
void *idr_get_next(struct idr *idr, int *nextid)
[…]
slot = radix_tree_iter_find(&idr->gt;idr_rt, &iter, id);
Subject [RFC 2/2] pid: Replace PID bitmap implementation with IDR API
Date
Sat, 9 Sep 2017 18:03:17 +0530
[…]

Experience: ps(1) failure
So far we have moved from:
To:
ps(1) sometimes fails. Kernel bug!
find_ge_pid() sometimes returns NULL
instead of the next struct *pid
I’ll keep digging after this keynote

Takeaway:
BPF enables better bug reports

bpftrace: BPF observability front-end
# Files opened by process
bpftrace -e 't:syscalls:sys_enter_open { printf("%s %s\n", comm,
str(args->gt;filename)) }'
# Read size distribution by process
bpftrace -e 't:syscalls:sys_exit_read { @[comm] = hist(args->gt;ret) }'
# Count VFS calls
bpftrace -e 'kprobe:vfs_* { @[func]++ }'
# Show vfs_read latency as a histogram
bpftrace -e 'k:vfs_read { @[tid] = nsecs }
kr:vfs_read /@[tid]/ { @ns = hist(nsecs - @[tid]); delete(@tid) }’
# Trace user-level function
bpftrace -e 'uretprobe:bash:readline { printf(“%s\n”, str(retval)) }’
Linux 4.9+
https://github.com/iovisor/bpftrace

Raw BPF
samples/bpf/sock_example.c
87 lines truncated

C/BPF
samples/bpf/tracex1_kern.c
58 lines truncated

bcc/BPF (C & Python)
bcc examples/tracing/bitehist.py
entire program

bpftrace/BPF
bpftrace -e 'kr:vfs_read { @ = hist(retval); }'
https://github.com/iovisor/bpftrace
entire program

(brutal)
Ease of use (less brutal)
The Tracing Landscape, Apr 2019
(my opinion)
(eBPF)
(0.9)
bpftrace
ply/BPF
sysdig
perf
(many)
stap
LTTng
recent changes
(alpha)
(mature)
(hist
trigg
ers)
ftrace
bcc/BPF
C/BPF
Stage of
Development
Raw BPF
Scope & Capability

Experience: readahead

Experience: readahead
Is readahead polluting the cache?

Experience: readahead
Is readahead polluting the cache?
# readahead.bt
Attaching 5 probes...
Readahead unused pages: 128
Readahead used page age (ms):
@age_ms:
[1]
2455 |@@@@@@@@@@@@@@@
[2, 4)
8424 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8)
4417 |@@@@@@@@@@@@@@@@@@@@@@@@@@@
[8, 16)
7680 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[16, 32)
4352 |@@@@@@@@@@@@@@@@@@@@@@@@@@
[32, 64)
0 |
[64, 128)
0 |
[128, 256)
384 |@@

#!/usr/local/bin/bpftrace
kprobe:__do_page_cache_readahead
{ @in_readahead[tid] = 1; }
kretprobe:__do_page_cache_readahead { @in_readahead[tid] = 0; }
kretprobe:__page_cache_alloc
/@in_readahead[tid]/
@birth[retval] = nsecs;
@rapages++;
kprobe:mark_page_accessed
/@birth[arg0]/
@age_ms = hist((nsecs - @birth[arg0]) / 1000000);
delete(@birth[arg0]);
@rapages--;
END
printf("\nReadahead unused pages: %d\n", @rapages);
printf("\nReadahead used page age (ms):\n");
print(@age_ms); clear(@age_ms);
clear(@birth); clear(@in_readahead); clear(@rapages);

Takeaway:
bpftrace is good for short tools

bpftrace Syntax
bpftrace -e ‘k:do_nanosleep /pid >gt; 100/ { @[comm]++ }’
Probe
Filter
(optional)
Action

Probes

Probe Type Shortcuts
tracepoint
usdt
Kernel static tracepoints
User-level statically defined tracing
kprobe
Kernel function tracing
kretprobe
Kernel function returns
uprobe
User-level function tracing
uretprobe
User-level function returns
profile
Timed sampling across all CPUs
interval
Interval output
software
Kernel software events
hardware
Processor hardware events

Filters
/pid == 181/
● /comm != “sshd”/
● /@ts[tid]/

Actions
Per-event output
printf()
system()
join()
time()
Map Summaries
@ = count() or @++
@ = hist()
The following is in the https://github.com/iovisor/bpftrace/blob/master/docs/reference_

Functions
printf(fmt, ...) Print formatted
print(@x[, top[, div]]) Print map
delete(@x)
clear(@x) Delete all keys/values
Maximum value
reg(n)
Register lookup
avg(n)
Average value
join(a)
Join string array
stats(n)
Statistics
str(s)
String
time(fmt) Print formatted time
ksym(p)
Resolve kernel addr
system(fmt)
usym(p)
Resolve user addr
cat(file) Print file contents
kaddr(n)
Resolve kernel symbol
exit() Quit bpftrace
uaddr(n)
Resolve user symbol
Log2 histogram
hist(n)
lhist(n, min, max, step) Linear hist.
count()
Count events
sum(n)
Sum value
min(n)
Minimum value
max(n)
Delete map element
Run shell command

Variable Types
Basic Variables
@global
@thread_local[tid]
$scratch
Associative Arrays
@array[key] = value
Buitins
pid

Builtin Variables
pid
Process ID (kernel tgid)
arg0, arg1, ... Function args
tid
Thread ID (kernel pid)
retval Return value
cgroup Current Cgroup ID
args
Tracepoint args
uid
User ID
func
Function name
gid
Group ID
probe
nsecs
Nanosecond timestamp
Full probe name
cpu
Processor ID
curtask Curr task_struct (u64)
comm
Process name
rand
kstack Kernel stack trace
ustack User stack trace
Random number (u32)

bpftrace: biolatency
#!/usr/local/bin/bpftrace
BEGIN
printf("Tracing block device I/O... Hit Ctrl-C to end.\n");
kprobe:blk_account_io_start
@start[arg0] = nsecs;
kprobe:blk_account_io_completion
/@start[arg0]/
@usecs = hist((nsecs - @start[arg0]) / 1000);
delete(@start[arg0]);

Experience: superping!

Experience: superping
How much is scheduler latency?
# ping 172.20.0.1
PING 172.20.0.1 (172.20.0.1) 56(84) bytes of data.
64 bytes from 172.20.0.1: icmp_seq=1 ttl=64 time=2.87 ms
64 bytes from 172.20.0.1: icmp_seq=2 ttl=64 time=1.66 ms
64 bytes from 172.20.0.1: icmp_seq=3 ttl=64 time=1.55 ms
64 bytes from 172.20.0.1: icmp_seq=4 ttl=64 time=1.11 ms
64 bytes from 172.20.0.1: icmp_seq=5 ttl=64 time=2.48 ms
64 bytes from 172.20.0.1: icmp_seq=6 ttl=64 time=2.39 ms
[...]

Experience: superping
How much is scheduler latency?
# ./superping.bt
Attaching 6 probes...
Tracing ICMP echo request latency. Hit Ctrl-C to end.
IPv4 ping, ID 9827 seq 1: 2883 us
IPv4 ping, ID 9827 seq 2: 1682 us
IPv4 ping, ID 9827 seq 3: 1568 us
IPv4 ping, ID 9827 seq 4: 1078 us
IPv4 ping, ID 9827 seq 5: 2486 us
IPv4 ping, ID 9827 seq 6: 2394 us
[...]

#!/usr/local/bin/bpftrace
#include gt;
#include gt;
#include gt;
#include gt;
#include gt;
BEGIN { printf("Tracing ICMP echo request latency. Hit Ctrl-C to end.\n"); }
kprobe:ip_send_skb
$skb = (struct sk_buff *)arg1;
// get IPv4 header; see skb_network_header():
$iph = (struct iphdr *)($skb->gt;head + $skb->gt;network_header);
if ($iph->gt;protocol == IPPROTO_ICMP) {
// get ICMP header; see skb_transport_header():
$icmph = (struct icmphdr *)($skb->gt;head + $skb->gt;transport_header);
if ($icmph->gt;type == ICMP_ECHO) {
$id = $icmph->gt;un.echo.id;
$seq = $icmph->gt;un.echo.sequence;
@start[$id, $seq] = nsecs;
Note: no debuginfo required
[...]

Takeaway:
BPF tracing can walk structs

bpftrace Internals

bpftrace Development
v0.80
Jan-2019
Dec 2016
Oct 2018
Major Features (v1)
v0.10
?Jun-2019
v0.90
Mar-2019
Minor Features (v1)
v1.0
?2019
Stable Docs
API Stability
Known Bug Fixes
Packaging
More Bug Fixes

bpftrace Tools
Linux 4.9+
https://github.com/

Experience: tcplife

Experience: tcplife
Which processes are connecting to which port?

Experience: tcplife
Which processes are connecting to which port?
# ./tcplife
PID
COMM
LADDR
22597 recordProg 127.0.0.1
3277 redis-serv 127.0.0.1
22598 curl
22604 curl
22624 recordProg 127.0.0.1
3277 redis-serv 127.0.0.1
22647 recordProg 127.0.0.1
3277 redis-serv 127.0.0.1
[...]
LPORT RADDR
46644 127.0.0.1
28527 127.0.0.1
61620 52.205.89.26
44400 52.204.43.121
46648 127.0.0.1
28527 127.0.0.1
46650 127.0.0.1
28527 127.0.0.1
RPORT TX_KB RX_KB MS
0 0.23
0 0.28
1 91.79
1 121.38
0 0.22
0 0.27
0 0.21
0 0.26

bcc
Linux 4.4+
https://github.com/iovisor/bcc

bcc: tcplife
int kprobe__tcp_set_state(struct pt_regs *ctx, struct sock *sk, int state)
u32 pid = bpf_get_current_pid_tgid() >gt;>gt; 32;
// lport is either used in a filter here, or later
u16 lport = sk->gt;__sk_common.skc_num;
[…]
struct tcp_sock *tp = (struct tcp_sock *)sk;
rx_b = tp->gt;bytes_received;
tx_b = tp->gt;bytes_acked;
u16 family = sk->gt;__sk_common.skc_family;
[…]
if (family == AF_INET) {
struct ipv4_data_t data4 = {};
data4.span_us = delta_us;
data4.rx_b = rx_b;
data4.tx_b = tx_b;
data4.ts_us = bpf_ktime_get_ns() / 1000;
data4.saddr = sk->gt;__sk_common.skc_rcv_saddr;
data4.daddr = sk->gt;__sk_common.skc_daddr;

Experience: tcplife
From kprobes to tracepoints
# bpftrace -lv t:tcp:tcp_set_state
tracepoint:tcp:tcp_set_state
const void * skaddr;
int oldstate;
int newstate;
__u16 sport;
__u16 dport;
__u8 saddr[4];
__u8 daddr[4];
__u8 saddr_v6[16];
__u8 daddr_v6[16];
Linux 4.15
# bpftrace -lv t:sock:inet_sock_set_state
tracepoint:sock:inet_sock_set_state
const void * skaddr;
int oldstate;
int newstate;
__u16 sport;
__u16 dport;
__u16 family;
__u8 protocol;
__u8 saddr[4];
__u8 daddr[4];
__u8 saddr_v6[16];
__u8 daddr_v6[16];
Linux 4.16+

Takeaways:
bcc for complex tools
kprobes can prototype tracepoints
tracepoints can change (best effort)

Experience: cachestat

Experience: cachestat
What is the page cache hit ratio?

Experience: cachestat
What is the page cache hit ratio?
# cachestat
HITS
MISSES
[...]
DIRTIES HITRATIO
4 100.00%
36 100.00%
28 100.00%
55.51%
1 100.00%
83 100.00%
1 100.00%
BUFFERS_MB
CACHED_MB

b.attach_kprobe(event="add_to_page_cache_lru", fn_name="do_count")
b.attach_kprobe(event="mark_page_accessed", fn_name="do_count")
b.attach_kprobe(event="account_page_dirtied", fn_name="do_count")
b.attach_kprobe(event="mark_buffer_dirty", fn_name="do_count")
[…]
# total = total cache accesses without counting dirties
# misses = total of add to lru because of read misses
total = mpa - mbd
misses = apcl - apd
if misses 

Takeaway:
BPF tracing can prototype /proc stats

Reality Check
Many of our perf wins are from CPU flame graphs
not CLI tracing

Stack depth (0 - max)
CPU Flame Graphs
Kernel
Java
JVM
Alphabetical frame sort (A - Z)

BPF-based CPU Flame Graphs
Linux 2.6
Linux 4.9
perf record
profile.py
perf.data
perf script
stackcollapse-perf.pl
flamegraph.pl
flamegraph.pl

Takeaway:
BPF all the things!

Take Aways
BPF observability:
– bpftrace: one-liners, short scripts
– bcc: complex tools
– Production safe, and no debuginfo needed
kprobe tools can prototype tracepoints, /proc stats
I’m ok with tracepoints are best effort
BPF all the things!

URLs
https://github.com/iovisor/bpftrace
https://github.com/iovisor/bpftrace/blob/master/docs/tutorial_one_liners.md
https://github.com/iovisor/bpftrace/blob/master/docs/reference_guide.md
https://github.com/iovisor/bcc
https://github.com/iovisor/bcc/blob/master/docs/tutorial.md
https://github.com/iovisor/bcc/blob/master/docs/reference_guide.md
http://www.brendangregg.com/ebpf.html
Update: this keynote was summarized by
https://lwn.net/Articles/787131/

Thanks
bpftrace
– Alastair Robertson (creator)
– Netflix: myself, Mary Marchini
– Sthima: Willian Gaspar
– Facebook: Jon Haslam, Dan Xu
– Augusto Mecking Caringi, Dale Hamel, ...
eBPF & bcc
– Facebook: Alexei Starovoitov, Teng Qin, Yonghong Song, Martin Lau,
Mark Drayton, …
– Netflix: myself
– VMware: Brenden Blanco
– Daniel Borkmann, David S. Miller, Sasha Goldsthein, Paul Chaignon, ...