funccount(8)

Count VFS kernel calls:

funcgraph 'vfs_*'

Count TCP kernel calls:

funccount 'tcp_*'

Count TCP send calls per second:

funccount -i 1 'tcp_send*'

Show the rate of block I/O events per second:

funccount -i 1 't:block:*'

Show the rate of libc getaddrinfo() (name resolution) per second:

funccount -i 1 c:getaddrinfo

stackcount(8)

Count stack traces that created block I/O:

Click here to view code image

stackcount t:block:block_rq_insert

Count stack traces that led to sending IP packets, with responsible PID:

stackcount -P ip_output

Count stack traces that led to the thread blocking and moving off-CPU:

Click here to view code image

stackcount t:sched:sched_switch

trace(8)

Trace the kernel do_sys_open() function with the filename:

Click here to view code image

trace 'do_sys_open "%s", arg2'

Trace the return of the kernel function do_sys_open() and print the return value:

Click here to view code image

trace 'r::do_sys_open "ret: %d", retval'

Trace the kernel function do_nanosleep() with mode and user-level stacks:

Click here to view code image

trace -U 'do_nanosleep "mode: %d", arg2'

Trace authentication requests via the pam library:

Click here to view code image

trace 'pam:pam_start "%s: %s", arg1, arg2'

argdist(8)

Summarize VFS reads by return value (size or error):

argdist -H 'r::vfs_read()'

Summarize libc read() by return value (size or error) for PID 1005:

Click here to view code image

argdist -p 1005 -H 'r:c:read()'

Count syscalls by syscall ID:

Click here to view code image

argdist.py -C 't:raw_syscalls:sys_enter():int:args->id'

Summarize the kernel function tcp_sendmsg() size argument using counts:

Click here to view code image

argdist -C 'p::tcp_sendmsg(struct sock *sk, struct msghdr *msg, size_t size):u32:size'

Summarize tcp_sendmsg() size as a power-of-two histogram:

Click here to view code image

argdist -H 'p::tcp_sendmsg(struct sock *sk, struct msghdr *msg, size_t size):u32:size'

Count the libc write() call for PID 181 by file descriptor:

Click here to view code image

argdist -p 181 -C 'p:c:write(int fd):int:fd'

Summarize reads by process where latency was >100 μs:

Click here to view code image

argdist -C 'r::__vfs_read():u32:$PID:$latency > 100000

CPUs

Trace new processes with arguments:

Click here to view code image

bpftrace -e 'tracepoint:syscalls:sys_enter_execve { join(args->argv); }'

Count syscalls by process:

Click here to view code image

bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[pid, comm] = count(); }'

Sample user-level stacks at 49 Hertz, for PID 189:

Click here to view code image

bpftrace -e 'profile:hz:49 /pid == 189/ { @[ustack] = count(); }'

Memory

Count process heap expansion (brk()) by code path:

Click here to view code image

bpftrace -e tracepoint:syscalls:sys_enter_brk { @[ustack, comm] = count(); }

Count user page faults by user-level stack trace:

Click here to view code image

bpftrace -e 'tracepoint:exceptions:page_fault_user { @[ustack, comm] =
    count(); }'

Count vmscan operations by tracepoint:

Click here to view code image

bpftrace -e 'tracepoint:vmscan:* { @[probe]++; }'

File Systems

Trace files opened via openat(2) with process name:

Click here to view code image

bpftrace -e 't:syscalls:sys_enter_openat { printf("%s %s
", comm,
    str(args->filename)); }'

Show the distribution of read() syscall read bytes (and errors):

Click here to view code image

bpftrace -e 'tracepoint:syscalls:sys_exit_read { @ = hist(args->ret); }'

Count VFS calls:

Click here to view code image

bpftrace -e 'kprobe:vfs_* { @[probe] = count(); }'

Count ext4 tracepoint calls:

Click here to view code image

bpftrace -e 'tracepoint:ext4:* { @[probe] = count(); }'

Disk

Summarize block I/O size as a histogram:

Click here to view code image

bpftrace -e 't:block:block_rq_issue { @bytes = hist(args->bytes); }'

Count block I/O request user stack traces:

Click here to view code image

bpftrace -e 't:block:block_rq_issue { @[ustack] = count(); }'

Count block I/O type flags:

Click here to view code image

bpftrace -e 't:block:block_rq_issue { @[args->rwbs] = count(); }'

Networking

Count socket accept(2)s by PID and process name:

Click here to view code image

bpftrace -e 't:syscalls:sys_enter_accept* { @[pid, comm] = count(); }'

Count socket send/receive bytes by on-CPU PID and process name:

Click here to view code image

bpftrace -e 'kr:sock_sendmsg,kr:sock_recvmsg /retval > 0/ {
    @[pid, comm] = sum(retval); }'

TCP send bytes as a histogram:

Click here to view code image

bpftrace -e 'k:tcp_sendmsg { @send_bytes = hist(arg2); }'

TCP receive bytes as a histogram:

Click here to view code image

bpftrace -e 'kr:tcp_recvmsg /retval >= 0/ { @recv_bytes = hist(retval); }'

UDP send bytes as a histogram:

Click here to view code image

bpftrace -e 'k:udp_sendmsg { @send_bytes = hist(arg2); }'

Applications

Sum malloc() requested bytes by user stack trace (high overhead):

Click here to view code image

bpftrace -e 'u:/lib/x86_64-linux-gnu/libc-2.27.so:malloc { @[ustack(5)] =
    sum(arg0); }'

Trace kill() signals showing sender process name, target PID, and signal number:

Click here to view code image

bpftrace -e 't:syscalls:sys_enter_kill { printf("%s -> PID %d SIG %d
",
    comm, args->pid, args->sig); }'

Kernel

Count system calls by syscall function:

Click here to view code image

bpftrace -e 'tracepoint:raw_syscalls:sys_enter {
    @[ksym(*(kaddr("sys_call_table") + args->id * 8))] = count(); }'

Count kernel function calls starting with “attach”:

Click here to view code image

bpftrace -e 'kprobe:attach* { @[probe] = count(); }'

Frequency count the third argument to vfs_write() (the size):

Click here to view code image

bpftrace -e 'kprobe:vfs_write { @[arg2] = count(); }'

Time the kernel function vfs_read() and summarize as a histogram:

Click here to view code image

bpftrace -e 'k:vfs_read { @ts[tid] = nsecs; } kr:vfs_read /@ts[tid]/ {
    @ = hist(nsecs - @ts[tid]); delete(@ts[tid]); }'

Count context switch stack traces:

Click here to view code image

bpftrace -e 't:sched:sched_switch { @[kstack, ustack, comm] = count(); }'

Sample kernel-level stacks at 99 Hertz, excluding idle:

Click here to view code image

bpftrace -e 'profile:hz:99 /pid/ { @[kstack] = count(); }'

1. Usage

The command

bpftrace -e program

will execute the program, instrumenting any events that it defines. The program will run until Ctrl-C, or until it explicitly calls exit(). A bpftrace program run as a -e argument is termed a one-liner. Alternatively, the program can be saved to a file and executed using:

bpftrace file.bt

The .bt extension is not necessary, but is helpful for later identification. By placing an interpreter line at the top of the file²

²Some people prefer using #!/usr/bin/env bpftrace, so that bpftrace can be found from $PATH. However, env(1) comes with various problems, and its usage in other projects has been reverted.

#!/usr/local/bin/bpftrace

the file can be made executable (chmod a+x file.bt) and run like any other program:

./file.bt

bpftrace must be executed by the root user (super-user).³ For some environments, the root shell may be used to execute the program directly, whereas other environments may have a preference for running privileged commands via sudo(1):

sudo ./file.bt

³bpftrace checks for UID 0; a future update may check for specific privileges.

2. Program Structure

A bpftrace program is a series of probes with associated actions:

probes { actions }
probes { actions }
...

When the probes fire, the associated action is executed. An optional filter expression can be included before the action:

probes /filter/ { actions }

The action only fires if the filter expression is true. This resembles the awk(1) program structure:

/pattern/ { actions }

awk(1) programming is also similar to bpftrace programming: Multiple action blocks can be defined, and they may execute in any order, triggered when their pattern, or probe + filter expression, is true.

3. Comments

For bpftrace program files, single-line comments can be added with a “//” prefix:

// this is a comment

These comments will not be executed. Multi-line comments use the same format as those in C:

/*
 * This is a
 * multi-line comment.
 */

This syntax can also be used for partial-line comments (e.g., /* comment */).

4. Probe Format

A probe begins with a probe type name and then a hierarchy of colon-delimited identifiers:

Click here to view code image

type:identifier1[:identifier2[...]]

The hierarchy is defined by the probe type. Consider these two examples:

kprobe:vfs_read
uprobe:/bin/bash:readline

The kprobe probe type instruments kernel function calls, and only needs one identifier: the kernel function name. The uprobe probe type instruments user-level function calls, and needs both the path to the binary and the function name.

Multiple probes can be specified with comma separators to execute the same actions. For example:

probe1,probe2,... { actions }

There are two special probe types that require no additional identifiers: BEGIN and END fire for the beginning and the end of the bpftrace program (just like awk(1)). For example, to print an informational message when tracing begins:

Click here to view code image

BEGIN { printf("Tracing. Hit Ctrl-C to end.
"); }

To learn more about the probe types and their usage, see Section 15.2.5, Reference, under the heading 1. Probe Types.

5. Probe Wildcards

Some probe types accept wildcards. The probe

kprobe:vfs_*

will instrument all kprobes (kernel functions) that begin with “vfs_”.

Instrumenting too many probes may cost unnecessary performance overhead. To avoid hitting this by accident, bpftrace has a tunable maximum number of probes it will enable, set via the BPFTRACE_MAX_PROBES environment variable (it currently defaults to 512⁴).

⁴More than 512 currently makes bpftrace slow to start up and shut down, as it instruments them one by one. Future kernel work is planned to batch probe instrumentation. At that point, this limit can be greatly increased, or even removed.

You can test your wildcards before using them by running bpftrace -l to list the matched probes:

Click here to view code image

# bpftrace -l 'kprobe:vfs_*'
kprobe:vfs_fallocate
kprobe:vfs_truncate
kprobe:vfs_open
kprobe:vfs_setpos
kprobe:vfs_llseek
[…]
bpftrace -l 'kprobe:vfs_*' | wc -l
56

This matched 56 probes. The probe name is in quotes to prevent unintended shell expansion.

6. Filters

Filters are Boolean expressions that gate whether an action is executed. The filter

/pid == 123/

will execute the action only if the pid built-in (process ID) is equal to 123.

If a test is not specified

/pid/

the filter will check that the contents are non-zero (/pid/ is the same as /pid != 0/). Filters can be combined with Boolean operators, such as logical AND (&&). For example:

/pid > 100 && pid < 1000/

This requires that both expressions evaluate to “true.”

7. Actions

An action can be a single statement or multiple statements separated by semicolons:

Click here to view code image

{ action one; action two; action three }

The final statement may also have a semicolon appended. The statements are written in the bpftrace language, which is similar to the C language, and can manipulate variables and execute bpftrace function calls. For example, the action

Click here to view code image

{ $x = 42; printf("$x is %d", $x); }

sets a variable, $x, to 42, and then prints it using printf(). For a summary of other available function calls, see Section 15.2.5, Reference, under headings 4. Functions and 5. Map Functions.

8. Hello, World!

You should now understand the following basic program, which prints “Hello, World!” when bpftrace begins running:

Click here to view code image

# bpftrace -e 'BEGIN { printf("Hello, World!
"); }'
Attaching 1 probe...
Hello, World!
^C

As a file, it could be formatted as:

#!/usr/local/bin/bpftrace

BEGIN
{
        printf("Hello, World!
");
}

Spanning multiple lines with an indented action block is not necessary, but it improves readability.

9 Functions

In addition to printf() for printing formatted output, other built-in functions include:

• exit(): Exits bpftrace

• str(char *): Returns a string from a pointer

• system(format[, arguments ...]): Runs a command at the shell

The action

Click here to view code image

printf("got: %llx %s
", $x, str($x)); exit();

will print the $x variable as a hex integer, and then treat it as a NULL-terminated character array pointer (char *) and print it as a string, and then exit.

10 Variables

There are three variable types: built-ins, scratch, and maps.

Built-in variables are pre-defined and provided by bpftrace, and are usually read-only sources of information. They include pid for the process id, comm for the process name, nsecs for a timestamp in nanoseconds, and curtask for the address of the current thread’s task_struct.

Scratch variables can be used for temporary calculations and have the prefix “$”. Their name and type is set on their first assignment. The statements:

Click here to view code image

$x = 1;
$y = “hello”;
$z = (struct task_struct *)curtask;

declare $x as an integer, $y as a string, and $z as a pointer to a struct task_struct. These variables can only be used in the action block in which they were assigned. If variables are referenced without an assignment, bpftrace prints an error (which can help you catch typos).

Map variables use the BPF map storage object and have the prefix “@”. They can be used for global storage, passing data between actions. The program:

probe1 { @a = 1; }
probe2 { $x = @a; }

assigns 1 to @a when probe1 fires, then assigns @a to $x when probe2 fires. If probe1 fired first and then probe2, $x would be set to 1; otherwise 0 (uninitialized).

A key can be provided with one or more elements, using maps as a hash table (an associative array). The statement

@start[tid] = nsecs;

is frequently used: the nsecs built-in is assigned to a map named @start and keyed on tid, the current thread ID. This allows threads to store custom timestamps that won’t be overwritten by other threads.

@path[pid, $fd] = str(arg0);

is an example of a multi-key map, one using both the pid builtin and the $fd variable as keys.

11 Map Functions

Maps can be assigned to special functions. These functions store and print data in custom ways. The assignment

@x = count();

counts events, and when printed will print the count. This uses a per-CPU map, and @x becomes a special object of type count. The following statement also counts events:

@x++;

However, this uses a global CPU map, instead of a per-CPU map, to provide @x as an integer. This global integer type is sometimes necessary for some programs that require an integer and not a count, but bear in mind that there may be a small error margin due to concurrent updates.

The assignment

@y = sum($x);

sums the $x variable, and when printed will print the total. The assignment

@z = hist($x);

stores $x in a power-of-two histogram, and when printed will print bucket counts and an ASCII histogram.

Some map functions operate directly on a map. For example:

print(@x);

will print the @x map. This can be used, for example, to print map contents on an interval event. This is not used often because, for convenience, all maps are automatically printed when bpftrace terminates.⁵

⁵There is also less overhead in printing maps when bpftrace terminates, as at runtime the maps are experiencing updates, which can slow down the map walk routine.

Some map functions operate on a map key. For example:

delete(@start[tid]);

deletes the key-value pair from the @start map where the key is tid.

12. Timing vfs_read()

You have now learned the syntax needed to understand a more involved and practical example. This program, vfsread.bt, times the vfs_read kernel function and prints out a histogram of its duration in microseconds (us):

Click here to view code image

#!/usr/local/bin/bpftrace

// this program times vfs_read()

kprobe:vfs_read
{
        @start[tid] = nsecs;
}

kretprobe:vfs_read
/@start[tid]/
{
        $duration_us = (nsecs - @start[tid]) / 1000;
        @us = hist($duration_us);
        delete(@start[tid]);
}

This times the duration of the vfs_read() kernel function by instrumenting its start using a kprobe and storing a timestamp in a @start hash keyed on thread ID, and then instrumenting its end by using a kretprobe and calculating the delta as: now - start. A filter is used to ensure that the start time was recorded; otherwise, the delta calculation becomes bogus for vfs_read() calls that were in progress when tracing begins, as the end is seen but not the start (the delta would become: now - 0).

Sample output:

Click here to view code image

# bpftrace vfsread.bt
Attaching 2 probes...
^C

@us:
[0]                   23 |@                                                   |
[1]                  138 |@@@@@@@@@                                           |
[2, 4)               538 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@               |
[4, 8)               744 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              641 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        |
[16, 32)             122 |@@@@@@@@                                            |
[32, 64)              13 |                                                    |
[64, 128)             17 |@                                                   |
[128, 256)             2 |                                                    |
[256, 512)             0 |                                                    |
[512, 1K)              1 |                                                    |

The program ran until Ctrl-C was entered; then it printed this output and terminated. This histogram map was named “us” as a way to include units with the output, since the map name is printed out. By giving maps meaningful names like “bytes” and “latency_ns” you can annotate the output and make it self-explanatory.

This script can be customized as needed. Consider changing the hist() assignment line to:

Click here to view code image

@us[pid, comm] = hist($duration_us);

This stores one histogram per process ID and process name pair. With traditional system tools, like iostat(1) and vmstat(1), the output is fixed and cannot be easily customized. But with bpftrace, the metrics you see can be further broken down into parts and enhanced with metrics from other probes until you have the answers you need.

See Chapter 8, File Systems, Section 8.6.15, BPFtrace, heading VFS Latency Tracing, for an extended example that breaks down vfs_read() latency by type: file system, socket, etc.

1. Probe Types

Table 15.4 lists available probe types. Many of these also have a shortcut alias, which help create shorter one-liners.

Most of these probe types are interfaces to existing kernel technologies. Chapter 4 explains how these technologies work: kprobes, uprobes, tracepoints, USDT, and PMCs (used by the hardware probe type). The kfunc/kretfunc probe type is a new low-overhead interface based on eBPF trampolines and BTF.

Some probes may fire frequently, such as for scheduler events, memory allocations, and network packets. To reduce overhead, try to solve your problems by using less-frequent events wherever possible. If you are unsure about probe frequency, you can measure it using bpftrace. For example, counting vfs_read() kprobe calls for one second only:

Click here to view code image

# bpftrace -e 'k:vfs_read { @ = count(); } interval:s:1 { exit(); }'

I chose a short duration to minimize the overhead cost, in case it was significant. What I would consider high or low frequency depends on your CPU speed, count, and headroom, and the cost of the probe instrumentation. As a rough guide for the computers of today, I would consider less than 100k kprobe or tracepoint events per second to be low frequency.

bpftrace -e 'tracepoint:syscalls:sys_enter_read { @req_bytes = hist(args->count); }'

# bpftrace -lv 'tracepoint:syscalls:sys_enter_read'
tracepoint:syscalls:sys_enter_read
    int __syscall_nr;
    unsigned int fd;
    char * buf;
    size_t count;

2. Flow Control

There are three types of tests in bpftrace: filters, ternary operators, and if statements. These tests conditionally change the flow of the program based on Boolean expressions, which support those shown in Table 15.5.

Expressions may be grouped using parentheses.

probe /filter/ { action }

test ? true_statement : false_statement

$abs = $x >= 0 ? $x : - $x;

if (test) { true_statements }
if (test) { true_statements } else { false_statements }

if ($inet_family == $AF_INET) {
    // IPv4
    ...
} else {
    // assume IPv6
    ...
}

while (test) {
    statements
}

3. Variables

The built-in variables provided by bpftrace are usually for read-only access of information. Important built-in variables are listed in Table 15.7.

All integers are currently uint64. These variables all refer to the currently running thread, probe, function, and CPU when the probe fires.

Various builtins have been demonstrated earlier in this chapter: retval, comm, tid, and nsecs. See the online “bpftrace Reference Guide” for the full and updated list of built-in variables [Iovisor 20c].

4. Functions

Table 15.8 lists selected built-in functions for various tasks. Some of these have been used in earlier examples, such as printf().

⁸WARNING: Only use this if you know what you are doing: a small mistake could panic or corrupt the kernel.

Some of these functions are asynchronous: The kernel queues the event, and a short time later it is processed in user space. The asynchronous functions are printf(), time(), cat(), join(), and system(). The functions kstack(), ustack(), ksym(), and usym() record addresses synchronously, but do symbol translation asynchronously.

As an example, the following uses both the printf() and str() functions to show the filename of openat(2) syscalls:

Click here to view code image

# bpftrace -e 't:syscalls:sys_enter_open { printf("%s %s
", comm,
    str(args->filename)); }'
Attaching 1 probe...
top /etc/ld.so.cache
top /lib/x86_64-linux-gnu/libprocps.so.7
top /lib/x86_64-linux-gnu/libtinfo.so.6
top /lib/x86_64-linux-gnu/libc.so.6
[...]

See the online “bpftrace Reference Guide” for the full and updated list of functions [Iovisor 20c].

5. Map Functions

Maps are special hash table storage objects from BPF that can be used for different purposes—for example, as hash tables to store key/value pairs or for statistical summaries. bpftrace provides built-in functions for map assignment and manipulation, mostly for supporting statistical summary maps. The most important map functions are listed in Table 15.9.

Some of these functions are asynchronous: The kernel queues the event, and a short time later it is processed in user space. The asynchronous actions are print(), clear(), and zero(). Bear this delay in mind when you are writing programs.

As another example of using a map function, the following uses lhist() to create a linear histogram of syscall read(2) sizes by process name, with a step size of one so that each file descriptor number can be seen independently:

Click here to view code image

# bpftrace -e 'tracepoint:syscalls:sys_enter_read {
    @fd[comm] = lhist(args->fd, 0, 100, 1); }'
Attaching 1 probe...
^C
[...]
@fd[sshd]:
[4, 5)                22 |                                                    |
[5, 6)                 0 |                                                    |
[6, 7)                 0 |                                                    |
[7, 8)                 0 |                                                    |
[8, 9)                 0 |                                                    |
[9, 10)                0 |                                                    |
[10, 11)               0 |                                                    |
[11, 12)               0 |                                                    |
[12, 13)            7760 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

The output shows that on this system sshd processes were typically reading from file descriptor 12. The output uses set notation, where “[” means >= and “)” means < (aka a bounded left-closed, right-open interval).

See the online “bpftrace Reference Guide” for the full and updated list of map functions [Iovisor 20c].