Performance tracing of Podman using eBPF

Performance tracing is an essential process that involves the collection, analysis and interpretation of system data. The primary objective of performance tracing is to identify bottlenecks, diagnose problems and optimize performance to ensure that systems operate within their limits.

The following example serves as an introduction to the broader concept of performance tracing only. There are various technologies available to facilitate performance tracing and selecting the right one is critical.

To demonstrate how performance tracing can be implemented using an extended Berkeley Packet Filter (eBPF), we will measure the startup time of containers. eBPF is a Linux kernel technology that allows developers to insert custom code into the kernel to trace and analyze system events. Using this mechanism, developers can collect detailed performance data on system components—even containerized applications—without needing external monitoring tools or profilers.

We recently published how Podman's performance is important to the automotive industry—which uses a fork/exec model to create new containers. Measuring the startup time of a container in eBPF is done by following the dependency graph of parent processes and their children back to the initial Podman command executed in  its own process. This logic is implemented in fork_exec_snoop.bt. In the bpftrace file, a high-level tracing language is used to interact with the Linux BPF system.

The logic in this eBPF program is split into two parts:

• The first part of the program waits for the first execution of a Podman command, which acts as a trigger by setting the value of the global variable @time_normalized to the current time. 
• The second part of the program is invoked as soon as @time_normalized is initialized and it prints information about syscalls: sys_enter_clone, syscalls:sys_exit_clone, syscalls:sys_enter_exec* and syscalls:sys_exit_exec* events.

The output of the fork_exec_snoop.bt eBPF program looks similar to this:

Attaching 9 probes...

TRACEPOINT                T            DT           PID      PPID     TGID     PTGID    CMD

syscalls:sys_exit_exec*   0            1507         39324    38662    39324    38662    podman

syscalls:sys_enter_clone  40544                     39326    38662    39324    38662    podman

<redacted>

The details show the time between syscalls:sys_exit_clone and syscalls:sys_enter_exec*. This includes the time it takes for the kernel to perform various tasks associated with the syscalls:sys_enter_exec* system call, such as:

• Loading the new executable into memory
• Setting up the process' address space
• Initializing the stack and heap
• Loading shared libraries
• Starting the new program's execution

The duration can vary depending on several factors, including the size and complexity of the new executable, the amount of shared libraries to load and the system's overall load and resources. This information is helpful when optimizing the performance of Podman in general.

For developers who want to measure the performance on their systems, there are two additional valuable metrics that can be derived from the output.

The first one is the time Podman requires to start the container's process command, true. This is the timestamp of the syscalls:sys_exit_exec* event before syscalls:sys_enter_exec* with the true command. In this case, it takes Podman roughly 0.16 seconds to start the container’s process command. This time largely depends on the specifications of the system being tested. Running Podman for the first time after a reboot always takes significantly more time than subsequent runs in which the caches are already populated.

TRACEPOINT                T            DT           PID      PPID     TGID     PTGID    CMD

syscalls:sys_exit_exec*   163698       899          39368    39326    39368    39324    3

The second important piece of information is related to the application in the container itself. The time between syscalls:sys_enter_exec* and syscalls:sys_exit_exec* measures the execution time of the program. In this case, it took 1107 microseconds, or about 0.001 seconds, to run the true command.

TRACEPOINT                T            DT           PID      PPID     TGID     PTGID    CMD

syscalls:sys_exit_exec*   168723       1107         39367    39362    39367    39362    true

To run this performance analysis yourself, replicate the process on Fedora, Red Hat Enterprise Linux or any equivalent operating system.

Download the container image used in this demo, as well as the eBPF program:

podman pull quay.io/fedora/fedora:latest


curl -X GET https://raw.githubusercontent.com/containers/podman/main/hack/fork_exec_snoop.bt -o fork_exec_snoop.bt

chmod +x fork_exec_snoop.bt

Run the eBPF program:

# first terminal

./fork_exec_snoop.bt > fork_exec.log

The eBPF program will now wait for a Podman command in a forked process.

NOTE: Make sure that no other process is calling Podman during the measurement, because it might pollute the log output even though it would not tamper the results.

In a second terminal, run Podman:

# second terminal

podman run --pull=never --network=host --security-opt seccomp=unconfined quay.io/fedora/fedora:latest true

After the Podman command has returned, press Ctrl+C to stop the tracing in the first terminal and inspect the log:

less fork_exec.log

Although this is meant to be an introduction into eBPF for developers who want to tweak container performance, there are many other potential use cases for using eBPF. For developers of container images and other systems with fast startup requirements, it is worth examining the outcomes of this measurement in detail to improve the performance of the system.