mirror of
https://github.com/eunomia-bpf/bpf-developer-tutorial.git
synced 2026-10-31 12:45:23 +08:00
docs: improve tutorials 50 through 54
This commit is contained in:
yuxi4096
@@ -1,42 +1,101 @@
|
||||
# eBPF Tutorial: Tracing Slow vfs_read Calls with fsession
|
||||
|
||||
Suppose a file-backed service shows read-latency spikes. Application-level timing tells you that requests slowed down, but it cannot distinguish whether the kernel read path blocked or user-space logic took too long. The useful questions are: which thread issued the read, how many bytes did it request, what did the call return, and how long did that single `vfs_read` invocation take?
|
||||
When a file-backed service shows read-latency spikes, application-level timing tells you that requests slowed down, but it cannot distinguish whether the kernel blocked on I/O or user-space logic took too long. The useful questions are: which thread issued the read, how many bytes did it request, what did the call return, and how long did that single `vfs_read` invocation take?
|
||||
|
||||
This tutorial demonstrates how to measure `vfs_read` call latency using the fsession mechanism introduced in Linux 7.0. The tool timestamps function entry, computes latency at return, filters by TGID and threshold, and reports slow-read events.
|
||||
This tutorial demonstrates how to measure `vfs_read` call latency using the **fsession** mechanism introduced in Linux 7.0. fsession is a new eBPF program type that runs once at function entry and once at return, with built-in per-invocation storage for correlating the two phases. The tool we build timestamps function entry, computes latency at return, filters by process and threshold, and reports slow-read events through a ring buffer.
|
||||
|
||||
> Complete source: <https://github.com/eunomia-bpf/bpf-developer-tutorial/tree/main/src/52-fsession-latency>
|
||||
|
||||
## Why fsession Is Needed
|
||||
## The Problem: Correlating Function Entry and Return
|
||||
|
||||
Traditional approaches to measuring function latency all have notable limitations.
|
||||
To measure how long a kernel function takes, you need to record a timestamp when it starts and compute the difference when it returns. This sounds simple, but the traditional approaches in eBPF all have drawbacks.
|
||||
|
||||
**Separate fentry and fexit programs** are the most common approach. You write two BPF programs: one attached to function entry, one to function return. The two programs pass timestamps through a per-thread hash map: entry stores a mapping from `bpf_get_current_pid_tgid()` to timestamp, and return looks up and deletes the entry. This pattern has several problems. First, you must maintain an extra hash map, incurring lookup and deletion overhead on every call. Second, if a thread dies between entry and return (for example, if it is killed), the hash-map entry leaks. Third, the two programs have no intrinsic relationship; state passing depends entirely on an external data structure.
|
||||
### Traditional Approach: Two Programs with a Hash Map
|
||||
|
||||
**kprobe and kretprobe** also require two separate programs and an external hash map. Compared to fentry/fexit, kprobes have higher overhead because they work through a breakpoint mechanism, whereas fentry hooks directly into the function prologue using JIT-optimized call sequences on x86_64.
|
||||
The most common pattern uses two separate BPF programs - one attached to function entry (fentry), one to function return (fexit). The entry program records the timestamp in a hash map keyed by thread ID; the return program looks up the timestamp, computes latency, and deletes the entry:
|
||||
|
||||
**User-space sampling** such as `perf record` or periodic stack sampling with `bpftrace` provides only a statistical profile and cannot precisely measure the latency of each call. For scenarios that need to capture tail-latency events, sampling may completely miss critical slow calls.
|
||||
```
|
||||
Entry program: Return program:
|
||||
1. Get thread ID 1. Get thread ID
|
||||
2. Get timestamp 2. Look up timestamp from map
|
||||
3. Store timestamp in hash map 3. Compute latency
|
||||
4. Delete entry from map
|
||||
5. Report event
|
||||
```
|
||||
|
||||
**The fsession mechanism** solves this problem fundamentally. Linux 7.0 introduced fsession, which executes the same BPF program once at function entry and once at return, providing an 8-byte per-invocation scratch area through `bpf_session_cookie(ctx)`. This cookie persists from entry to return, completely replacing external hash maps. The program uses `bpf_session_is_return(ctx)` to distinguish the two phases and handles all logic within a single program.
|
||||
This works, but has several problems:
|
||||
|
||||
## How fsession Works
|
||||
- **Map overhead**: Every function call requires a hash map insertion at entry and a lookup plus deletion at return. For high-frequency functions like `vfs_read`, this overhead adds up.
|
||||
- **State leaks**: If a thread is killed between entry and return (e.g., `kill -9`), the hash map entry is never deleted and leaks memory.
|
||||
- **No intrinsic relationship**: The two programs are completely independent. The only thing connecting them is the external hash map - there's no guarantee they're actually tracking the same function invocation.
|
||||
|
||||
fsession is a special ftracing program type. When you declare a program with `SEC("fsession/vfs_read")`, the kernel calls your BPF program once at `vfs_read` entry and once at return.
|
||||
### kprobe/kretprobe: Same Pattern, Higher Overhead
|
||||
|
||||
`bpf_session_is_return(ctx)` returns false during the entry phase and true during the return phase. The program uses this helper to determine which phase it is in and execute the appropriate logic.
|
||||
The kprobe mechanism has the same two-program structure and requires the same external hash map for correlation. Additionally, kprobes work through a software breakpoint mechanism (replacing the first instruction with an interrupt), which has higher overhead than fentry hooks that use the kernel's ftrace infrastructure and JIT-optimized call sequences.
|
||||
|
||||
`bpf_session_cookie(ctx)` returns a pointer to an 8-byte scratch area. This scratch area is unique to each invocation and persists from entry to return. You can write data (such as a timestamp) during entry and read it during return.
|
||||
### User-Space Sampling: Statistical, Not Precise
|
||||
|
||||
The return-phase context includes not only the original function arguments but also the function's return value. For `vfs_read`, you can see the `file`, `buf`, `count`, and `pos` arguments at entry; at return you can also see the `ret` return value. This means you do not need to store arguments in a map - the return phase can access them directly.
|
||||
Tools like `perf record` sample stack traces periodically and can build statistical profiles of where time is spent. However, sampling cannot measure the latency of individual function calls. If you need to capture tail-latency events - the occasional 100ms read that causes a timeout - statistical sampling may miss them entirely.
|
||||
|
||||
The `fsession_latency` tool leverages these capabilities for latency measurement. At entry, it checks whether the TGID matches the target process; matching calls store a `bpf_ktime_get_ns()` timestamp in the cookie. At return, it reads the timestamp from the cookie to compute latency, increments aggregate counters, and reports detailed events through a ring buffer for calls exceeding the threshold.
|
||||
## The fsession Solution
|
||||
|
||||
Linux 7.0 introduced **fsession**, which solves the correlation problem at the kernel level. When you declare a BPF program with `SEC("fsession/vfs_read")`, the kernel:
|
||||
|
||||
1. Calls your program once when `vfs_read` enters
|
||||
2. Allocates an 8-byte scratch area (the "session cookie") tied to this specific invocation
|
||||
3. Calls your program again when `vfs_read` returns
|
||||
4. Deallocates the session cookie
|
||||
|
||||
The key insight is that the session cookie is automatically managed and scoped to exactly one function invocation. Your program distinguishes entry from return using `bpf_session_is_return(ctx)`, and reads or writes the cookie using `bpf_session_cookie(ctx)`.
|
||||
|
||||
### What the Session Cookie Replaces
|
||||
|
||||
In the traditional approach, you'd use a hash map like this:
|
||||
|
||||
```c
|
||||
// Traditional: hash map keyed by thread ID
|
||||
struct {
|
||||
__uint(type, BPF_MAP_TYPE_HASH);
|
||||
__uint(max_entries, 10240);
|
||||
__type(key, u64); // pid_tgid
|
||||
__type(value, u64); // timestamp
|
||||
} start SEC(".maps");
|
||||
```
|
||||
|
||||
With fsession, this entire map disappears. The timestamp lives in the session cookie:
|
||||
|
||||
```c
|
||||
// fsession: per-invocation cookie, no map needed
|
||||
__u64 *started = bpf_session_cookie(ctx);
|
||||
*started = bpf_ktime_get_ns();
|
||||
```
|
||||
|
||||
The cookie persists from entry to return and is automatically cleaned up afterward - no leaks possible.
|
||||
|
||||
### Return-Phase Context Includes Function Arguments
|
||||
|
||||
Another fsession advantage: the return-phase context includes both the original function arguments and the return value. In the traditional approach, if you need access to function arguments at return time (e.g., to include the requested byte count in your event), you must store them in the hash map at entry. With fsession, arguments are directly available:
|
||||
|
||||
```c
|
||||
SEC("fsession/vfs_read")
|
||||
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
loff_t *pos, ssize_t ret)
|
||||
{
|
||||
// At return, 'count' and 'ret' are both available
|
||||
// No need to store 'count' anywhere at entry
|
||||
}
|
||||
```
|
||||
|
||||
## Code Implementation
|
||||
|
||||
This tool consists of three files: a shared header defining event and statistics structures, a BPF program that measures latency and submits events, and a user-space loader that manages the lifecycle and prints results.
|
||||
This tool consists of three files:
|
||||
- `fsession_latency.h`: Shared data structures for BPF and user space
|
||||
- `fsession_latency.bpf.c`: The BPF program that measures latency
|
||||
- `fsession_latency.c`: User-space loader that manages the BPF lifecycle and prints results
|
||||
|
||||
### Shared Header
|
||||
|
||||
`fsession_latency.h` defines the event and statistics structures shared between BPF and user space. `latency_event` contains a 32-bit PID and TGID, 64-bit requested bytes, a signed 64-bit return value, nanosecond-precision latency, and the process name. `latency_stats` contains four counters for aggregate statistics.
|
||||
`fsession_latency.h` defines the event structure sent through the ring buffer and the aggregate statistics structure:
|
||||
|
||||
```c
|
||||
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
|
||||
@@ -64,11 +123,17 @@ struct latency_stats {
|
||||
#endif /* __FSESSION_LATENCY_H */
|
||||
```
|
||||
|
||||
The four counters record: `calls` for total invocations, `slow` for calls reaching the threshold, `errors` for calls returning negative values, and `dropped` for ring-buffer reservation failures. `FSESSION_COMM_LEN` is set to 16 to match the kernel's `TASK_COMM_LEN`.
|
||||
The four counters track:
|
||||
- `calls`: Total `vfs_read` invocations observed
|
||||
- `slow`: Calls that met or exceeded the latency threshold
|
||||
- `errors`: Calls where `vfs_read` returned a negative error code
|
||||
- `dropped`: Events that couldn't be submitted because the ring buffer was full
|
||||
|
||||
`FSESSION_COMM_LEN` is 16 to match the kernel's `TASK_COMM_LEN`.
|
||||
|
||||
### BPF Program
|
||||
|
||||
`fsession_latency.bpf.c` uses `SEC("fsession/vfs_read")` to declare itself as an fsession type. The kernel calls this program once at `vfs_read` entry and once at return.
|
||||
`fsession_latency.bpf.c` is the core of the tool. Let's walk through it section by section.
|
||||
|
||||
```c
|
||||
// SPDX-License-Identifier: GPL-2.0
|
||||
@@ -82,7 +147,11 @@ The four counters record: `calls` for total invocations, `slow` for calls reachi
|
||||
#include "fsession_latency.h"
|
||||
|
||||
char LICENSE[] SEC("license") = "GPL";
|
||||
```
|
||||
|
||||
The macro dance at the top is a compatibility workaround. The repository's `vmlinux.h` snapshot was generated before Linux 7.0 added a `ctx` argument to `bpf_session_is_return` and `bpf_session_cookie`. The macros rename the old declarations during the include, then we provide the correct signatures below. A `vmlinux.h` regenerated from kernel 7.0+ wouldn't need this.
|
||||
|
||||
```c
|
||||
const volatile __u64 threshold_ns;
|
||||
const volatile __u32 target_tgid;
|
||||
|
||||
@@ -92,7 +161,15 @@ struct {
|
||||
__uint(type, BPF_MAP_TYPE_RINGBUF);
|
||||
__uint(max_entries, 256 * 1024);
|
||||
} events SEC(".maps");
|
||||
```
|
||||
|
||||
`const volatile` variables in BPF programs have special semantics. They're placed in the `.rodata` section and can be set by user space after opening the skeleton but before loading. Once loaded, the verifier treats them as compile-time constants, enabling optimizations like dead-code elimination when `target_tgid` is 0.
|
||||
|
||||
`stats` is a global variable in the `.bss` section, directly readable from user space after the program runs.
|
||||
|
||||
The ring buffer (`events`) is sized at 256 KB - enough for thousands of events before overflow.
|
||||
|
||||
```c
|
||||
/*
|
||||
* The repository vmlinux.h snapshot predates the ctx argument on these
|
||||
* kfunc prototypes. Rename those stale declarations while including the
|
||||
@@ -100,7 +177,11 @@ struct {
|
||||
*/
|
||||
extern bool bpf_session_is_return(void *ctx) __ksym;
|
||||
extern __u64 *bpf_session_cookie(void *ctx) __ksym;
|
||||
```
|
||||
|
||||
These are **kfunc** declarations - kernel functions exported for BPF programs to call. The `__ksym` attribute tells the verifier to resolve these symbols from the running kernel at load time, rather than expecting them to be defined in the BPF object.
|
||||
|
||||
```c
|
||||
SEC("fsession/vfs_read")
|
||||
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
loff_t *pos, ssize_t ret)
|
||||
@@ -109,7 +190,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
__u64 *started = bpf_session_cookie(ctx);
|
||||
struct latency_event *event;
|
||||
__u64 latency;
|
||||
```
|
||||
|
||||
The `SEC("fsession/vfs_read")` tells the kernel this is an fsession program attached to `vfs_read`. The `BPF_PROG` macro expands to set up the standard tracing context; `ctx` is implicitly available for passing to kfuncs.
|
||||
|
||||
The function signature lists `vfs_read`'s parameters followed by its return value. At entry, `ret` is undefined; at return, all parameters and the return value are valid.
|
||||
|
||||
```c
|
||||
if (!bpf_session_is_return(ctx)) {
|
||||
if (target_tgid && pid_tgid >> 32 != target_tgid) {
|
||||
*started = 0;
|
||||
@@ -118,7 +205,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
*started = bpf_ktime_get_ns();
|
||||
return 0;
|
||||
}
|
||||
```
|
||||
|
||||
**Entry phase**: First, check if we should filter this call. If `target_tgid` is set (non-zero) and the current process's TGID doesn't match, write 0 to the cookie to mark this invocation as "skip" and return. Otherwise, write the current monotonic timestamp to the cookie.
|
||||
|
||||
The TGID is in the upper 32 bits of `bpf_get_current_pid_tgid()`'s return value; the lower 32 bits are the thread ID (PID in kernel terms).
|
||||
|
||||
```c
|
||||
if (!*started)
|
||||
return 0;
|
||||
|
||||
@@ -128,7 +221,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
__sync_fetch_and_add(&stats.errors, 1);
|
||||
if (latency < threshold_ns)
|
||||
return 0;
|
||||
```
|
||||
|
||||
**Return phase**: If the cookie is 0, the entry phase filtered this call - return immediately. Otherwise, compute latency and update the aggregate counters. The `__sync_fetch_and_add` provides atomic updates since multiple CPUs may execute this program concurrently.
|
||||
|
||||
If the latency is below the threshold, we're done - the call is counted but no event is emitted. This keeps the ring buffer focused on slow calls.
|
||||
|
||||
```c
|
||||
__sync_fetch_and_add(&stats.slow, 1);
|
||||
event = bpf_ringbuf_reserve(&events, sizeof(*event), 0);
|
||||
if (!event) {
|
||||
@@ -147,160 +246,28 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
}
|
||||
```
|
||||
|
||||
The program is structured into entry and return phases. The two `const volatile` variables reside in the `.rodata` section; user space writes the threshold and target TGID after `open()` but before `load()`, and the verifier treats them as compile-time constants. `bpf_session_is_return` and `bpf_session_cookie` are declared as kfunc symbols via `extern ... __ksym`, resolved by the kernel at load time.
|
||||
For slow calls, increment the `slow` counter and try to reserve space in the ring buffer. If the reservation fails (buffer full), increment `dropped` so the user knows events were lost. On success, fill in the event fields and submit.
|
||||
|
||||
At entry, the program calls `bpf_get_current_pid_tgid()` to obtain the caller's PID and TGID. If `target_tgid` is set and the call comes from a different process, the program writes 0 to the cookie to indicate this invocation should be skipped. Matching calls store the monotonic timestamp returned by `bpf_ktime_get_ns()`.
|
||||
|
||||
At return, the program first checks whether the cookie is 0. A zero cookie indicates the entry phase already filtered this call, so it returns immediately. Otherwise it computes latency as the current timestamp minus the saved entry timestamp, then increments the `calls` counter. If `ret < 0`, indicating the read operation returned an error, it increments the `errors` counter. Calls with latency below `threshold_ns` stop here, updating only aggregate counters without reporting events.
|
||||
|
||||
Calls reaching the threshold increment the `slow` counter, then attempt to reserve a fixed-size record in the ring buffer. A failed reservation increments the `dropped` counter, allowing the final statistics to expose pressure in the event path. On successful reservation, the record is filled with PID, TGID, requested bytes, return value, latency, and process name, then submitted to the ring buffer.
|
||||
|
||||
The macros at the beginning of the file provide a local compatibility bridge. The repository's `vmlinux.h` snapshot has `bpf_session_is_return` and `bpf_session_cookie` declarations that predate the `ctx` argument added in Linux 7.0. The macros rename the old declarations, include the snapshot, undef, then redeclare with the correct Linux 7.0 signatures. A freshly regenerated `vmlinux.h` from kernel 7.0 or later can be used directly without this bridge.
|
||||
Note that `count` (the requested byte count) is available directly - no need to have stored it at entry. This is the fsession advantage: function arguments persist to the return phase.
|
||||
|
||||
### User-Space Loader
|
||||
|
||||
`fsession_latency.c` parses the command line, configures BPF constants, manages the observation window, and prints results.
|
||||
`fsession_latency.c` handles command-line parsing, BPF lifecycle management, and event consumption. The key sections:
|
||||
|
||||
**Configuration via read-only data**:
|
||||
```c
|
||||
// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
|
||||
#include <errno.h>
|
||||
#include <getopt.h>
|
||||
#include <signal.h>
|
||||
#include <stdbool.h>
|
||||
#include <stdint.h>
|
||||
#include <stdio.h>
|
||||
#include <stdlib.h>
|
||||
#include <string.h>
|
||||
#include <time.h>
|
||||
#include <bpf/libbpf.h>
|
||||
#include "fsession_latency.h"
|
||||
#include "fsession_latency.skel.h"
|
||||
skel->rodata->threshold_ns = env.threshold_us * 1000;
|
||||
skel->rodata->target_tgid = env.pid;
|
||||
```
|
||||
|
||||
static volatile sig_atomic_t exiting;
|
||||
|
||||
static struct env {
|
||||
unsigned long long threshold_us;
|
||||
unsigned int duration;
|
||||
unsigned int pid;
|
||||
bool verbose;
|
||||
} env = {
|
||||
.threshold_us = 1000,
|
||||
.duration = 10,
|
||||
};
|
||||
|
||||
static unsigned long long events_printed;
|
||||
|
||||
static void handle_signal(int signal)
|
||||
{
|
||||
(void)signal;
|
||||
exiting = 1;
|
||||
}
|
||||
|
||||
static int libbpf_print_fn(enum libbpf_print_level level, const char *format,
|
||||
va_list args)
|
||||
{
|
||||
if (level == LIBBPF_DEBUG && !env.verbose)
|
||||
return 0;
|
||||
return vfprintf(stderr, format, args);
|
||||
}
|
||||
|
||||
static void usage(const char *program)
|
||||
{
|
||||
fprintf(stderr,
|
||||
"Usage: %s [--threshold-us USEC] [--duration SEC] [--pid TGID] "
|
||||
"[--verbose]\n\n"
|
||||
"Report vfs_read calls at or above a latency threshold.\n\n"
|
||||
"Options:\n"
|
||||
" -t, --threshold-us USEC slow-read threshold (default: 1000)\n"
|
||||
" -d, --duration SEC trace duration, 1-86400 (default: 10)\n"
|
||||
" -p, --pid TGID trace one process ID (default: all)\n"
|
||||
" -v, --verbose print libbpf diagnostics\n"
|
||||
" -h, --help show this help\n",
|
||||
program);
|
||||
}
|
||||
|
||||
static int parse_u64(const char *value, unsigned long long maximum,
|
||||
unsigned long long *result)
|
||||
{
|
||||
char *end = NULL;
|
||||
unsigned long long parsed;
|
||||
|
||||
errno = 0;
|
||||
parsed = strtoull(value, &end, 10);
|
||||
if (errno || end == value || *end || parsed > maximum)
|
||||
return -EINVAL;
|
||||
*result = parsed;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static int parse_args(int argc, char **argv)
|
||||
{
|
||||
static const struct option options[] = {
|
||||
{ "threshold-us", required_argument, NULL, 't' },
|
||||
{ "duration", required_argument, NULL, 'd' },
|
||||
{ "pid", required_argument, NULL, 'p' },
|
||||
{ "verbose", no_argument, NULL, 'v' },
|
||||
{ "help", no_argument, NULL, 'h' },
|
||||
{},
|
||||
};
|
||||
unsigned long long parsed;
|
||||
int option;
|
||||
|
||||
while ((option = getopt_long(argc, argv, "t:d:p:vh", options, NULL)) != -1) {
|
||||
switch (option) {
|
||||
case 't':
|
||||
if (parse_u64(optarg, UINT64_MAX / 1000, &env.threshold_us)) {
|
||||
fprintf(stderr, "invalid threshold in microseconds: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
break;
|
||||
case 'd':
|
||||
if (parse_u64(optarg, 86400, &parsed) || parsed == 0) {
|
||||
fprintf(stderr, "invalid duration in seconds: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
env.duration = parsed;
|
||||
break;
|
||||
case 'p':
|
||||
if (parse_u64(optarg, UINT32_MAX, &parsed) || parsed == 0) {
|
||||
fprintf(stderr, "invalid process ID: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
env.pid = parsed;
|
||||
break;
|
||||
case 'v':
|
||||
env.verbose = true;
|
||||
break;
|
||||
case 'h':
|
||||
usage(argv[0]);
|
||||
exit(0);
|
||||
default:
|
||||
return -EINVAL;
|
||||
}
|
||||
}
|
||||
|
||||
if (optind != argc)
|
||||
return -EINVAL;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static long long monotonic_milliseconds(void)
|
||||
{
|
||||
struct timespec timestamp;
|
||||
|
||||
if (clock_gettime(CLOCK_MONOTONIC, ×tamp))
|
||||
return -errno;
|
||||
return timestamp.tv_sec * 1000LL + timestamp.tv_nsec / 1000000;
|
||||
}
|
||||
After opening the skeleton but before loading, user space writes the threshold (converted from microseconds to nanoseconds) and target TGID to the `.rodata` section. These become constants in the BPF program.
|
||||
|
||||
**Ring buffer consumption**:
|
||||
```c
|
||||
static int handle_event(void *context, void *data, size_t size)
|
||||
{
|
||||
const struct latency_event *event = data;
|
||||
|
||||
(void)context;
|
||||
if (size < sizeof(*event))
|
||||
return 0;
|
||||
|
||||
printf("EVENT comm=%-16s tgid=%u pid=%u requested=%llu result=%lld "
|
||||
"latency_us=%llu\n",
|
||||
event->comm, event->tgid, event->pid, event->requested,
|
||||
@@ -308,124 +275,28 @@ static int handle_event(void *context, void *data, size_t size)
|
||||
events_printed++;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static int poll_until_deadline(struct ring_buffer *ring, long long deadline)
|
||||
{
|
||||
while (!exiting) {
|
||||
long long now = monotonic_milliseconds();
|
||||
int consumed;
|
||||
|
||||
if (now < 0)
|
||||
return (int)now;
|
||||
if (now >= deadline)
|
||||
break;
|
||||
|
||||
consumed = ring_buffer__poll(ring,
|
||||
deadline - now > 100 ? 100 : deadline - now);
|
||||
if (consumed == -EINTR)
|
||||
continue;
|
||||
if (consumed < 0) {
|
||||
fprintf(stderr, "ring buffer poll failed: %s\n",
|
||||
strerror(-consumed));
|
||||
return consumed;
|
||||
}
|
||||
}
|
||||
|
||||
return 0;
|
||||
}
|
||||
|
||||
int main(int argc, char **argv)
|
||||
{
|
||||
struct fsession_latency_bpf *skel = NULL;
|
||||
struct ring_buffer *ring = NULL;
|
||||
long long deadline, now;
|
||||
int err;
|
||||
|
||||
err = parse_args(argc, argv);
|
||||
if (err) {
|
||||
usage(argv[0]);
|
||||
return 1;
|
||||
}
|
||||
|
||||
libbpf_set_print(libbpf_print_fn);
|
||||
signal(SIGINT, handle_signal);
|
||||
signal(SIGTERM, handle_signal);
|
||||
|
||||
skel = fsession_latency_bpf__open();
|
||||
if (!skel) {
|
||||
fprintf(stderr, "failed to open BPF skeleton\n");
|
||||
return 1;
|
||||
}
|
||||
|
||||
skel->rodata->threshold_ns = env.threshold_us * 1000;
|
||||
skel->rodata->target_tgid = env.pid;
|
||||
|
||||
err = fsession_latency_bpf__load(skel);
|
||||
if (err) {
|
||||
fprintf(stderr,
|
||||
"failed to load fsession program: %s\n"
|
||||
"This tool requires Linux 7.0+, BTF, BPF JIT, and x86_64 "
|
||||
"fsession support.\n",
|
||||
strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
err = fsession_latency_bpf__attach(skel);
|
||||
if (err) {
|
||||
fprintf(stderr, "failed to attach to vfs_read: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
ring = ring_buffer__new(bpf_map__fd(skel->maps.events), handle_event, NULL, NULL);
|
||||
err = libbpf_get_error(ring);
|
||||
if (err) {
|
||||
ring = NULL;
|
||||
fprintf(stderr, "failed to create ring buffer: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
printf("Tracing vfs_read for %u seconds; threshold=%llu us; pid=%s\n",
|
||||
env.duration, env.threshold_us, env.pid ? "selected" : "all");
|
||||
fflush(stdout);
|
||||
|
||||
now = monotonic_milliseconds();
|
||||
if (now < 0) {
|
||||
err = now;
|
||||
goto cleanup;
|
||||
}
|
||||
deadline = now + env.duration * 1000LL;
|
||||
|
||||
err = poll_until_deadline(ring, deadline);
|
||||
if (err)
|
||||
goto cleanup;
|
||||
|
||||
fsession_latency_bpf__detach(skel);
|
||||
|
||||
err = ring_buffer__consume(ring);
|
||||
if (err < 0) {
|
||||
fprintf(stderr, "ring buffer drain failed: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
err = 0;
|
||||
|
||||
printf("SUMMARY calls=%llu slow=%llu errors=%llu dropped=%llu events=%llu\n",
|
||||
skel->bss->stats.calls, skel->bss->stats.slow,
|
||||
skel->bss->stats.errors, skel->bss->stats.dropped, events_printed);
|
||||
|
||||
cleanup:
|
||||
ring_buffer__free(ring);
|
||||
fsession_latency_bpf__destroy(skel);
|
||||
return err != 0;
|
||||
}
|
||||
```
|
||||
|
||||
The loader follows a standard flow. After parsing the command line, it opens the skeleton and writes `threshold_ns` and `target_tgid` to the read-only BPF configuration. The user-provided threshold is in microseconds; it is multiplied by 1000 to convert to nanoseconds before writing. Calling `load` completes BPF program loading, then attaches to `vfs_read`. The failure diagnostic provides both the kernel errno and a prerequisite list to help users troubleshoot.
|
||||
Each event is printed with the process name, IDs, requested bytes, return value, and latency in microseconds.
|
||||
|
||||
`ring_buffer__new` creates the ring-buffer consumer and registers the `handle_event` callback to process each event. The callback prints comm, TGID, PID, requested bytes, result, and latency in microseconds, incrementing `events_printed`.
|
||||
**Clean shutdown sequence**:
|
||||
```c
|
||||
fsession_latency_bpf__detach(skel);
|
||||
|
||||
The `poll_until_deadline` function drives the event consumption loop. It calculates a monotonic deadline and polls for up to 100 ms per iteration until the deadline or SIGINT/SIGTERM. A `-EINTR` return continues the loop; other negative values indicate errors.
|
||||
err = ring_buffer__consume(ring);
|
||||
// ... error handling ...
|
||||
|
||||
After polling ends, the loader first calls `fsession_latency_bpf__detach` to detach the fsession program, stopping changes to aggregate counters. It then calls `ring_buffer__consume` to deliver records submitted before detach but not yet consumed. This ordering is part of observation-window boundary correctness: stop new event production first, drain existing events, then read stable counters. On exit, it frees the ring buffer and destroys the skeleton.
|
||||
printf("SUMMARY calls=%llu slow=%llu errors=%llu dropped=%llu events=%llu\n",
|
||||
skel->bss->stats.calls, skel->bss->stats.slow,
|
||||
skel->bss->stats.errors, skel->bss->stats.dropped, events_printed);
|
||||
```
|
||||
|
||||
The shutdown order matters for correctness:
|
||||
1. Detach the BPF program (stops new events from being generated)
|
||||
2. Drain remaining events from the ring buffer
|
||||
3. Read the final counter values (now stable since the program is detached)
|
||||
|
||||
This ensures `events_printed` matches the events actually delivered through the ring buffer.
|
||||
|
||||
## Compilation and Execution
|
||||
|
||||
@@ -444,9 +315,9 @@ SERVICE_PID=$(pgrep -n my-service)
|
||||
sudo ./fsession_latency --pid "$SERVICE_PID" --threshold-us 10000 --duration 30
|
||||
```
|
||||
|
||||
`--pid` compares against the TGID returned by `bpf_get_current_pid_tgid()`, which is the TGID in the host (initial) PID namespace. The `pgrep` example above works for processes running directly on the host; targets inside containers or nested PID namespaces need their host-visible TGID resolved and passed in.
|
||||
**Note about PID namespaces**: The `--pid` option compares against the TGID in the host (initial) PID namespace. If your target runs in a container with its own PID namespace, you need to find its host-visible TGID. Inside the container the process might be PID 1, but from the host it could be PID 12345. Use `pgrep` on the host or inspect `/proc/<pid>/status` for the `NSpid` line.
|
||||
|
||||
Command-line arguments:
|
||||
### Command-Line Options
|
||||
|
||||
```text
|
||||
Usage: ./fsession_latency [--threshold-us USEC] [--duration SEC] [--pid TGID] [--verbose]
|
||||
@@ -459,9 +330,9 @@ Options:
|
||||
-h, --help show this help
|
||||
```
|
||||
|
||||
Defaults are 1000 microsecond threshold, 10 second duration, and all processes. `--duration` accepts 1 through 86400 seconds, `--pid` accepts 1 through 2^32-1, and `--threshold-us` accepts 0 through `UINT64_MAX / 1000` microseconds (user space converts to nanoseconds before load). Empty values and trailing characters are rejected by `parse_u64`.
|
||||
### Example Output
|
||||
|
||||
The following output was captured on x86_64 with kernel `7.0.0-rc2+`. The integration test performs 64 ordinary file reads plus one pipe read delayed by 50 ms; the pipe read exceeds the 10 ms threshold and appears in the event stream:
|
||||
The following output was captured on x86_64 with kernel `7.0.0-rc2+`. The integration test performs 64 ordinary file reads plus one pipe read delayed by 50 ms. The pipe read exceeds the 10 ms threshold and appears in the event stream:
|
||||
|
||||
```console
|
||||
Tracing vfs_read for 1 seconds; threshold=10000 us; pid=selected
|
||||
@@ -471,17 +342,26 @@ TEST-SUMMARY miss_calls=0 high_threshold_calls=66 high_threshold_slow=0 threshol
|
||||
PASS: PID filtering, threshold miss, and slow-read reporting behaved as expected
|
||||
```
|
||||
|
||||
Exact call counts, PID values, and latency numbers vary by run.
|
||||
The `SUMMARY` line shows:
|
||||
- 66 total `vfs_read` calls were observed
|
||||
- 1 was slow (met the threshold)
|
||||
- 0 returned errors
|
||||
- 0 events were dropped
|
||||
- 1 event was printed
|
||||
|
||||
Running the tests:
|
||||
### Running the Tests
|
||||
|
||||
```bash
|
||||
sudo make test
|
||||
```
|
||||
|
||||
The integration test validates four runtime paths: target TGID of `UINT32_MAX` produces zero calls and events; a 10,000,000 microsecond threshold causes ordinary reads to produce zero slow events; 64 ordinary file reads plus one 50 ms delayed pipe read under a 10,000 microsecond threshold produces a slow event; and threshold 0 verifies `slow == events + dropped`, proving every threshold-matching call is either delivered or accounted as a ring-buffer reservation failure. CLI tests cover invalid duration, empty duration, empty threshold, and empty PID.
|
||||
The integration test validates:
|
||||
- **PID filtering**: Targeting a nonexistent TGID produces zero calls
|
||||
- **Threshold filtering**: A very high threshold (10 seconds) produces zero slow events from fast reads
|
||||
- **Event reporting**: A deliberately slow pipe read (50ms) triggers an event under a 10ms threshold
|
||||
- **Accounting invariant**: With threshold=0, `slow == events + dropped` (every threshold-matching call is either delivered or counted as dropped)
|
||||
|
||||
### Environment Requirements
|
||||
## Environment Requirements
|
||||
|
||||
| Requirement | Details |
|
||||
|---|---|
|
||||
@@ -494,15 +374,28 @@ The integration test validates four runtime paths: target TGID of `UINT32_MAX` p
|
||||
|
||||
Runtime behavior was tested on x86_64 with kernel `7.0.0-rc2+`. The upstream merge commit is `f17b474e36647c23801ef8fdaf2255ab66dd2973`.
|
||||
|
||||
## Observation Scope
|
||||
## Extending This Tool
|
||||
|
||||
This tool measures time inside `vfs_read`, covering read paths that reach that function and filtering by exact host-visible TGID. A more comprehensive tracer could add cgroup, path, inode, mount, stack, or long-running metrics dimensions while keeping the same fsession correlation pattern; the existing `dropped` counter remains the event-loss signal under load.
|
||||
The fsession pattern demonstrated here applies to any kernel function where you need to correlate entry and return. Some directions for extension:
|
||||
|
||||
- **Additional functions**: Attach to `vfs_write`, `vfs_fsync`, or other VFS operations
|
||||
- **File path filtering**: Use `file->f_path` to filter by specific files or mount points
|
||||
- **Stack traces**: Add `bpf_get_stackid()` to capture kernel and/or user stack traces for slow calls
|
||||
- **Histograms**: Replace per-event reporting with latency histograms using `BPF_MAP_TYPE_ARRAY`
|
||||
- **cgroup filtering**: Add cgroup ID checks for container-aware tracing
|
||||
|
||||
The `dropped` counter remains the signal for ring buffer pressure - if it's growing, either increase the buffer size or raise the threshold to reduce event volume.
|
||||
|
||||
## Summary
|
||||
|
||||
This tutorial demonstrated how to measure kernel function latency using the fsession mechanism in Linux 7.0. Compared to the traditional approach of two fentry/fexit programs with a hash map, fsession handles both entry and return in a single program. The 8-byte per-invocation session cookie replaces the external correlation map for carrying timestamps, resulting in cleaner code, no state-leak risk, and lower performance overhead.
|
||||
This tutorial demonstrated how to measure kernel function latency using the fsession mechanism in Linux 7.0. The key advantages over the traditional fentry/fexit with hash map approach:
|
||||
|
||||
The tool's design demonstrates the core fsession pattern: use `bpf_session_is_return` to distinguish phases, use `bpf_session_cookie` to pass per-invocation state, and access function arguments and return values directly in the return phase. This pattern applies to any scenario requiring correlation between function entry and return.
|
||||
1. **Single program**: One BPF program handles both entry and return, with `bpf_session_is_return()` distinguishing the phases
|
||||
2. **Built-in correlation**: The 8-byte session cookie replaces the external hash map for passing data between phases
|
||||
3. **No state leaks**: The kernel manages cookie lifecycle - no cleanup required, no leaks possible
|
||||
4. **Arguments available at return**: Function parameters persist to the return phase without explicit storage
|
||||
|
||||
The pattern is simple: check `bpf_session_is_return()`, use `bpf_session_cookie()` for per-invocation state, and access arguments/return value directly. This applies wherever you need to correlate function entry and exit.
|
||||
|
||||
> To learn more about eBPF, check out our tutorial repository at <https://github.com/eunomia-bpf/bpf-developer-tutorial> or visit <https://eunomia.dev/tutorials/>.
|
||||
|
||||
|
||||
@@ -1,42 +1,101 @@
|
||||
# eBPF 教程：使用 fsession 追踪慢速 vfs_read 调用
|
||||
|
||||
假设一个文件服务出现了读延迟尖峰，应用层计时只能告诉你请求变慢了，却无法区分是内核读路径阻塞还是用户态逻辑耗时。有用的问题是：哪个线程发起了读操作、请求了多少字节、调用返回了什么、这一次 `vfs_read` 花了多长时间。
|
||||
当一个文件服务出现读延迟尖峰时，应用层计时只能告诉你请求变慢了，却无法区分是内核在 I/O 上阻塞还是用户态逻辑耗时。真正有用的问题是：哪个线程发起了读操作、请求了多少字节、调用返回了什么、这一次 `vfs_read` 花了多长时间？
|
||||
|
||||
本教程展示如何使用 Linux 7.0 引入的 fsession 机制测量 `vfs_read` 调用延迟。工具在函数进入时记录时间戳、返回时计算延迟，按 TGID 和阈值过滤后上报慢读事件。
|
||||
本教程展示如何使用 Linux 7.0 引入的 **fsession** 机制测量 `vfs_read` 调用延迟。fsession 是一种新的 eBPF 程序类型，它在函数进入时执行一次、返回时再执行一次，并提供内置的调用级存储来关联这两个阶段。我们构建的工具会在函数进入时记录时间戳、返回时计算延迟，按进程和阈值过滤后，通过 ring buffer 上报慢读事件。
|
||||
|
||||
> 完整源码：<https://github.com/eunomia-bpf/bpf-developer-tutorial/tree/main/src/52-fsession-latency>
|
||||
|
||||
## 为什么需要 fsession
|
||||
## 问题：如何关联函数的进入和返回
|
||||
|
||||
传统的函数延迟测量方案都有明显的局限性。
|
||||
要测量一个内核函数的执行时间，需要在它开始时记录时间戳，在它返回时计算差值。这听起来很简单，但 eBPF 中的传统方案都有各自的缺陷。
|
||||
|
||||
**独立的 fentry 和 fexit 程序**是最常见的做法。你需要编写两个 BPF 程序，一个附加到函数入口，一个附加到函数返回。两个程序之间需要通过一个按线程索引的哈希表来传递时间戳：进入时存入 `bpf_get_current_pid_tgid()` 到时间戳的映射，返回时查找并删除。这个模式有几个问题：首先需要维护额外的哈希表，每次调用都有查找和删除的开销；其次如果进入后没有正常返回（比如线程被杀死），哈希表中的条目会泄漏；最后两个程序之间没有天然的关联，状态传递完全依赖外部数据结构。
|
||||
### 传统方案：两个程序配合哈希表
|
||||
|
||||
**kprobe 和 kretprobe**同样需要两个独立的程序和外部哈希表。相比 fentry/fexit，kprobe 的开销更大，因为它通过断点机制工作，而 fentry 直接挂钩到函数序言，在 x86_64 上使用 JIT 优化的调用序列。
|
||||
最常见的做法是使用两个独立的 BPF 程序——一个附加到函数进入（fentry），一个附加到函数返回（fexit）。进入程序把时间戳存入一个以线程 ID 为键的哈希表；返回程序查找时间戳、计算延迟、删除条目：
|
||||
|
||||
**用户态采样**如 `perf record` 或 `bpftrace` 的周期性堆栈采样只能提供统计概貌，无法精确测量每次调用的延迟。对于需要捕获尾部延迟事件的场景，采样可能完全错过关键的慢调用。
|
||||
```
|
||||
进入程序： 返回程序：
|
||||
1. 获取线程 ID 1. 获取线程 ID
|
||||
2. 获取时间戳 2. 从哈希表查找时间戳
|
||||
3. 存入哈希表 3. 计算延迟
|
||||
4. 删除哈希表条目
|
||||
5. 上报事件
|
||||
```
|
||||
|
||||
**fsession 机制**从根本上解决了这个问题。Linux 7.0 引入了 fsession，它让同一个 BPF 程序在被追踪函数的进入和返回阶段各执行一次，并通过 `bpf_session_cookie(ctx)` 提供一个 8 字节的调用级暂存区。这个 cookie 从进入到返回期间持续有效，完全替代了外部哈希表。程序用 `bpf_session_is_return(ctx)` 区分两个阶段，在同一个程序内处理所有逻辑。
|
||||
这个方案能工作，但有几个问题：
|
||||
|
||||
## fsession 的工作原理
|
||||
- **哈希表开销**：每次函数调用都需要在进入时插入、在返回时查找并删除。对于像 `vfs_read` 这样的高频函数，开销会累积。
|
||||
- **状态泄漏**：如果线程在进入后、返回前被杀死（比如 `kill -9`），哈希表条目永远不会被删除，造成内存泄漏。
|
||||
- **没有内在关联**：两个程序完全独立，唯一的联系是外部哈希表——没有任何保证它们追踪的是同一次函数调用。
|
||||
|
||||
fsession 是一种特殊的 ftracing 程序类型。当你用 `SEC("fsession/vfs_read")` 声明一个程序时，内核会在 `vfs_read` 的进入和返回阶段各调用一次你的 BPF 程序。
|
||||
### kprobe/kretprobe：相同模式，更高开销
|
||||
|
||||
`bpf_session_is_return(ctx)` 返回 false 表示进入阶段，返回 true 表示返回阶段。程序可以用这个 helper 函数区分当前处于哪个阶段，执行相应的逻辑。
|
||||
kprobe 机制也是两个程序的结构，同样需要外部哈希表来关联。此外，kprobe 通过软件断点机制工作（用中断指令替换第一条指令），开销比 fentry 更大——后者使用内核的 ftrace 基础设施和 JIT 优化的调用序列。
|
||||
|
||||
`bpf_session_cookie(ctx)` 返回一个指向 8 字节暂存区的指针。这个暂存区是每次调用独立的，从进入阶段到返回阶段持续有效。你可以在进入阶段写入数据（比如时间戳），在返回阶段读取并使用它。
|
||||
### 用户态采样：统计性的，不是精确的
|
||||
|
||||
返回阶段的上下文不仅包含原始函数参数，还包含函数的返回值。对于 `vfs_read`，进入时能看到 `file`、`buf`、`count`、`pos` 四个参数，返回时还能看到 `ret` 返回值。这意味着你不需要把参数存到 map 里，返回阶段可以直接访问。
|
||||
像 `perf record` 这样的工具周期性采样堆栈，可以构建时间花在哪里的统计概貌。然而，采样无法测量单次函数调用的延迟。如果你需要捕获尾部延迟事件——偶尔出现的 100ms 读操作导致超时——统计采样可能完全错过它们。
|
||||
|
||||
`fsession_latency` 工具利用这些能力实现延迟测量。进入阶段，它检查 TGID 是否匹配目标进程，匹配的调用在 cookie 中存入 `bpf_ktime_get_ns()` 时间戳。返回阶段，它从 cookie 读取时间戳计算延迟，递增聚合计数器，超过阈值的调用通过 ring buffer 上报详细事件。
|
||||
## fsession 的解决方案
|
||||
|
||||
Linux 7.0 引入了 **fsession**，在内核层面解决了关联问题。当你用 `SEC("fsession/vfs_read")` 声明一个 BPF 程序时，内核会：
|
||||
|
||||
1. 在 `vfs_read` 进入时调用你的程序
|
||||
2. 分配一个 8 字节的暂存区（"session cookie"），绑定到这次特定的调用
|
||||
3. 在 `vfs_read` 返回时再次调用你的程序
|
||||
4. 释放 session cookie
|
||||
|
||||
关键在于 session cookie 是自动管理的，作用域精确到一次函数调用。程序用 `bpf_session_is_return(ctx)` 区分进入和返回，用 `bpf_session_cookie(ctx)` 读写 cookie。
|
||||
|
||||
### Session Cookie 替代了什么
|
||||
|
||||
在传统方案中，你需要一个这样的哈希表：
|
||||
|
||||
```c
|
||||
// 传统方案：以线程 ID 为键的哈希表
|
||||
struct {
|
||||
__uint(type, BPF_MAP_TYPE_HASH);
|
||||
__uint(max_entries, 10240);
|
||||
__type(key, u64); // pid_tgid
|
||||
__type(value, u64); // timestamp
|
||||
} start SEC(".maps");
|
||||
```
|
||||
|
||||
用了 fsession，整个哈希表都不需要了。时间戳直接存在 session cookie 里：
|
||||
|
||||
```c
|
||||
// fsession：调用级 cookie，不需要 map
|
||||
__u64 *started = bpf_session_cookie(ctx);
|
||||
*started = bpf_ktime_get_ns();
|
||||
```
|
||||
|
||||
cookie 从进入到返回一直存在，之后自动清理——不可能泄漏。
|
||||
|
||||
### 返回阶段可以访问函数参数
|
||||
|
||||
fsession 的另一个优势：返回阶段的上下文同时包含原始函数参数和返回值。在传统方案中，如果你需要在返回时访问函数参数（比如在事件中包含请求的字节数），必须在进入时把它们存到哈希表里。用 fsession，参数直接可用：
|
||||
|
||||
```c
|
||||
SEC("fsession/vfs_read")
|
||||
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
loff_t *pos, ssize_t ret)
|
||||
{
|
||||
// 返回时，'count' 和 'ret' 都可以直接访问
|
||||
// 不需要在进入时存储 'count'
|
||||
}
|
||||
```
|
||||
|
||||
## 代码实现
|
||||
|
||||
本工具由三个文件组成：共享头文件定义事件和统计结构、BPF 程序测量延迟并提交事件、用户空间加载器管理生命周期并打印结果。
|
||||
本工具由三个文件组成：
|
||||
- `fsession_latency.h`：BPF 和用户空间共享的数据结构
|
||||
- `fsession_latency.bpf.c`：测量延迟的 BPF 程序
|
||||
- `fsession_latency.c`：管理 BPF 生命周期并打印结果的用户空间加载器
|
||||
|
||||
### 共享头文件
|
||||
|
||||
`fsession_latency.h` 定义了 BPF 和用户空间共享的事件与统计结构。`latency_event` 包含 32 位 PID 和 TGID、64 位请求字节数、有符号 64 位返回值、纳秒精度延迟和进程名。`latency_stats` 包含四个计数器用于聚合统计。
|
||||
`fsession_latency.h` 定义了通过 ring buffer 发送的事件结构和聚合统计结构：
|
||||
|
||||
```c
|
||||
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
|
||||
@@ -64,11 +123,17 @@ struct latency_stats {
|
||||
#endif /* __FSESSION_LATENCY_H */
|
||||
```
|
||||
|
||||
四个计数器分别记录：`calls` 是总调用数、`slow` 是达到阈值的调用数、`errors` 是返回负值的调用数、`dropped` 是 ring buffer 预留失败的计数。`FSESSION_COMM_LEN` 设为 16，与内核 `TASK_COMM_LEN` 一致。
|
||||
四个计数器分别记录：
|
||||
- `calls`：观察到的 `vfs_read` 调用总数
|
||||
- `slow`：达到或超过延迟阈值的调用数
|
||||
- `errors`：`vfs_read` 返回负数错误码的调用数
|
||||
- `dropped`：因 ring buffer 满而无法提交的事件数
|
||||
|
||||
`FSESSION_COMM_LEN` 设为 16，与内核的 `TASK_COMM_LEN` 一致。
|
||||
|
||||
### BPF 程序
|
||||
|
||||
`fsession_latency.bpf.c` 使用 `SEC("fsession/vfs_read")` 声明为 fsession 类型。内核会在 `vfs_read` 的进入和返回阶段各调用一次这个程序。
|
||||
`fsession_latency.bpf.c` 是工具的核心。我们逐段分析。
|
||||
|
||||
```c
|
||||
// SPDX-License-Identifier: GPL-2.0
|
||||
@@ -82,7 +147,11 @@ struct latency_stats {
|
||||
#include "fsession_latency.h"
|
||||
|
||||
char LICENSE[] SEC("license") = "GPL";
|
||||
```
|
||||
|
||||
开头的宏处理是一个兼容性变通。仓库的 `vmlinux.h` 快照是在 Linux 7.0 给 `bpf_session_is_return` 和 `bpf_session_cookie` 加上 `ctx` 参数之前生成的。宏在 include 时重命名旧声明，然后我们在下面提供正确的签名。从 7.0 以上内核重新生成的 `vmlinux.h` 不需要这个处理。
|
||||
|
||||
```c
|
||||
const volatile __u64 threshold_ns;
|
||||
const volatile __u32 target_tgid;
|
||||
|
||||
@@ -92,7 +161,15 @@ struct {
|
||||
__uint(type, BPF_MAP_TYPE_RINGBUF);
|
||||
__uint(max_entries, 256 * 1024);
|
||||
} events SEC(".maps");
|
||||
```
|
||||
|
||||
BPF 程序中的 `const volatile` 变量有特殊语义。它们被放在 `.rodata` 段，用户空间可以在打开 skeleton 之后、加载之前设置。一旦加载，验证器把它们当作编译期常量，可以做死代码消除等优化（比如当 `target_tgid` 为 0 时）。
|
||||
|
||||
`stats` 是 `.bss` 段的全局变量，程序运行后用户空间可以直接读取。
|
||||
|
||||
ring buffer（`events`）大小是 256 KB——足够容纳数千个事件才会溢出。
|
||||
|
||||
```c
|
||||
/*
|
||||
* The repository vmlinux.h snapshot predates the ctx argument on these
|
||||
* kfunc prototypes. Rename those stale declarations while including the
|
||||
@@ -100,7 +177,11 @@ struct {
|
||||
*/
|
||||
extern bool bpf_session_is_return(void *ctx) __ksym;
|
||||
extern __u64 *bpf_session_cookie(void *ctx) __ksym;
|
||||
```
|
||||
|
||||
这是 **kfunc** 声明——导出给 BPF 程序调用的内核函数。`__ksym` 属性告诉验证器在加载时从运行中的内核解析这些符号，而不是期望它们在 BPF 对象中定义。
|
||||
|
||||
```c
|
||||
SEC("fsession/vfs_read")
|
||||
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
loff_t *pos, ssize_t ret)
|
||||
@@ -109,7 +190,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
__u64 *started = bpf_session_cookie(ctx);
|
||||
struct latency_event *event;
|
||||
__u64 latency;
|
||||
```
|
||||
|
||||
`SEC("fsession/vfs_read")` 告诉内核这是一个附加到 `vfs_read` 的 fsession 程序。`BPF_PROG` 宏展开后设置标准的追踪上下文；`ctx` 隐式可用，可以传给 kfunc。
|
||||
|
||||
函数签名列出 `vfs_read` 的参数，最后是返回值。进入时，`ret` 是未定义的；返回时，所有参数和返回值都有效。
|
||||
|
||||
```c
|
||||
if (!bpf_session_is_return(ctx)) {
|
||||
if (target_tgid && pid_tgid >> 32 != target_tgid) {
|
||||
*started = 0;
|
||||
@@ -118,7 +205,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
*started = bpf_ktime_get_ns();
|
||||
return 0;
|
||||
}
|
||||
```
|
||||
|
||||
**进入阶段**：首先检查是否应该过滤这次调用。如果设置了 `target_tgid`（非零）且当前进程的 TGID 不匹配，在 cookie 中写入 0 表示"跳过"，然后返回。否则，把当前单调时间戳写入 cookie。
|
||||
|
||||
TGID 在 `bpf_get_current_pid_tgid()` 返回值的高 32 位；低 32 位是线程 ID（内核术语中的 PID）。
|
||||
|
||||
```c
|
||||
if (!*started)
|
||||
return 0;
|
||||
|
||||
@@ -128,7 +221,13 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
__sync_fetch_and_add(&stats.errors, 1);
|
||||
if (latency < threshold_ns)
|
||||
return 0;
|
||||
```
|
||||
|
||||
**返回阶段**：如果 cookie 是 0，说明进入阶段已经过滤了这次调用——直接返回。否则计算延迟并更新聚合计数器。`__sync_fetch_and_add` 提供原子更新，因为多个 CPU 可能同时执行这个程序。
|
||||
|
||||
如果延迟低于阈值，到此为止——调用被计数但不产生事件。这让 ring buffer 只关注慢调用。
|
||||
|
||||
```c
|
||||
__sync_fetch_and_add(&stats.slow, 1);
|
||||
event = bpf_ringbuf_reserve(&events, sizeof(*event), 0);
|
||||
if (!event) {
|
||||
@@ -147,160 +246,28 @@ int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
|
||||
}
|
||||
```
|
||||
|
||||
程序结构分为进入阶段和返回阶段两部分。两个 `const volatile` 变量位于 `.rodata` 段，用户态在 `open()` 之后、`load()` 之前写入阈值和目标 TGID，验证器将它们视为编译期常量。`bpf_session_is_return` 和 `bpf_session_cookie` 通过 `extern ... __ksym` 声明为 kfunc 符号，内核在加载时解析。
|
||||
对于慢调用，递增 `slow` 计数器并尝试在 ring buffer 中预留空间。如果预留失败（缓冲区满），递增 `dropped` 让用户知道有事件丢失。成功后填入各字段并提交。
|
||||
|
||||
进入阶段，程序调用 `bpf_get_current_pid_tgid()` 获取调用者的 PID 和 TGID。如果设置了 `target_tgid` 且调用来自其他进程，程序在 cookie 中写入 0 表示这次调用应该被跳过。匹配的调用则存入 `bpf_ktime_get_ns()` 返回的单调时间戳。
|
||||
|
||||
返回阶段，程序首先检查 cookie 是否为 0。cookie 为 0 表示进入阶段已经过滤了这次调用，直接返回。否则计算延迟为当前时间戳减去保存的进入时间戳，然后递增 `calls` 计数器。如果 `ret < 0` 表示读操作返回错误，递增 `errors` 计数器。延迟低于 `threshold_ns` 的调用到此为止，只更新聚合计数器不上报事件。
|
||||
|
||||
达到阈值的调用递增 `slow` 计数器，然后尝试在 ring buffer 中预留固定大小的记录。预留失败时递增 `dropped` 计数器，这让最终统计能够暴露事件路径的压力。预留成功后填入 PID、TGID、请求字节数、返回值、延迟和进程名，最后提交到 ring buffer。
|
||||
|
||||
文件开头的宏处理是一个本地兼容桥接。仓库的 `vmlinux.h` 快照中 `bpf_session_is_return` 和 `bpf_session_cookie` 的声明早于 Linux 7.0 添加的 `ctx` 参数。宏先把旧声明重命名，include 之后再 undef，然后用正确的 Linux 7.0 签名重新声明。从 7.0 以上内核重新生成的 `vmlinux.h` 可以直接使用，不需要这个桥接。
|
||||
注意 `count`（请求的字节数）可以直接访问——不需要在进入时存储。这就是 fsession 的优势：函数参数在返回阶段仍然可用。
|
||||
|
||||
### 用户空间加载器
|
||||
|
||||
`fsession_latency.c` 解析命令行、配置 BPF 常量、管理观察窗口并打印结果。
|
||||
`fsession_latency.c` 处理命令行解析、BPF 生命周期管理和事件消费。关键部分：
|
||||
|
||||
**通过只读数据配置**：
|
||||
```c
|
||||
// SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
|
||||
#include <errno.h>
|
||||
#include <getopt.h>
|
||||
#include <signal.h>
|
||||
#include <stdbool.h>
|
||||
#include <stdint.h>
|
||||
#include <stdio.h>
|
||||
#include <stdlib.h>
|
||||
#include <string.h>
|
||||
#include <time.h>
|
||||
#include <bpf/libbpf.h>
|
||||
#include "fsession_latency.h"
|
||||
#include "fsession_latency.skel.h"
|
||||
skel->rodata->threshold_ns = env.threshold_us * 1000;
|
||||
skel->rodata->target_tgid = env.pid;
|
||||
```
|
||||
|
||||
static volatile sig_atomic_t exiting;
|
||||
|
||||
static struct env {
|
||||
unsigned long long threshold_us;
|
||||
unsigned int duration;
|
||||
unsigned int pid;
|
||||
bool verbose;
|
||||
} env = {
|
||||
.threshold_us = 1000,
|
||||
.duration = 10,
|
||||
};
|
||||
|
||||
static unsigned long long events_printed;
|
||||
|
||||
static void handle_signal(int signal)
|
||||
{
|
||||
(void)signal;
|
||||
exiting = 1;
|
||||
}
|
||||
|
||||
static int libbpf_print_fn(enum libbpf_print_level level, const char *format,
|
||||
va_list args)
|
||||
{
|
||||
if (level == LIBBPF_DEBUG && !env.verbose)
|
||||
return 0;
|
||||
return vfprintf(stderr, format, args);
|
||||
}
|
||||
|
||||
static void usage(const char *program)
|
||||
{
|
||||
fprintf(stderr,
|
||||
"Usage: %s [--threshold-us USEC] [--duration SEC] [--pid TGID] "
|
||||
"[--verbose]\n\n"
|
||||
"Report vfs_read calls at or above a latency threshold.\n\n"
|
||||
"Options:\n"
|
||||
" -t, --threshold-us USEC slow-read threshold (default: 1000)\n"
|
||||
" -d, --duration SEC trace duration, 1-86400 (default: 10)\n"
|
||||
" -p, --pid TGID trace one process ID (default: all)\n"
|
||||
" -v, --verbose print libbpf diagnostics\n"
|
||||
" -h, --help show this help\n",
|
||||
program);
|
||||
}
|
||||
|
||||
static int parse_u64(const char *value, unsigned long long maximum,
|
||||
unsigned long long *result)
|
||||
{
|
||||
char *end = NULL;
|
||||
unsigned long long parsed;
|
||||
|
||||
errno = 0;
|
||||
parsed = strtoull(value, &end, 10);
|
||||
if (errno || end == value || *end || parsed > maximum)
|
||||
return -EINVAL;
|
||||
*result = parsed;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static int parse_args(int argc, char **argv)
|
||||
{
|
||||
static const struct option options[] = {
|
||||
{ "threshold-us", required_argument, NULL, 't' },
|
||||
{ "duration", required_argument, NULL, 'd' },
|
||||
{ "pid", required_argument, NULL, 'p' },
|
||||
{ "verbose", no_argument, NULL, 'v' },
|
||||
{ "help", no_argument, NULL, 'h' },
|
||||
{},
|
||||
};
|
||||
unsigned long long parsed;
|
||||
int option;
|
||||
|
||||
while ((option = getopt_long(argc, argv, "t:d:p:vh", options, NULL)) != -1) {
|
||||
switch (option) {
|
||||
case 't':
|
||||
if (parse_u64(optarg, UINT64_MAX / 1000, &env.threshold_us)) {
|
||||
fprintf(stderr, "invalid threshold in microseconds: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
break;
|
||||
case 'd':
|
||||
if (parse_u64(optarg, 86400, &parsed) || parsed == 0) {
|
||||
fprintf(stderr, "invalid duration in seconds: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
env.duration = parsed;
|
||||
break;
|
||||
case 'p':
|
||||
if (parse_u64(optarg, UINT32_MAX, &parsed) || parsed == 0) {
|
||||
fprintf(stderr, "invalid process ID: %s\n", optarg);
|
||||
return -EINVAL;
|
||||
}
|
||||
env.pid = parsed;
|
||||
break;
|
||||
case 'v':
|
||||
env.verbose = true;
|
||||
break;
|
||||
case 'h':
|
||||
usage(argv[0]);
|
||||
exit(0);
|
||||
default:
|
||||
return -EINVAL;
|
||||
}
|
||||
}
|
||||
|
||||
if (optind != argc)
|
||||
return -EINVAL;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static long long monotonic_milliseconds(void)
|
||||
{
|
||||
struct timespec timestamp;
|
||||
|
||||
if (clock_gettime(CLOCK_MONOTONIC, ×tamp))
|
||||
return -errno;
|
||||
return timestamp.tv_sec * 1000LL + timestamp.tv_nsec / 1000000;
|
||||
}
|
||||
打开 skeleton 之后、加载之前，用户空间把阈值（从微秒转换为纳秒）和目标 TGID 写入 `.rodata` 段。这些在 BPF 程序中成为常量。
|
||||
|
||||
**Ring buffer 消费**：
|
||||
```c
|
||||
static int handle_event(void *context, void *data, size_t size)
|
||||
{
|
||||
const struct latency_event *event = data;
|
||||
|
||||
(void)context;
|
||||
if (size < sizeof(*event))
|
||||
return 0;
|
||||
|
||||
printf("EVENT comm=%-16s tgid=%u pid=%u requested=%llu result=%lld "
|
||||
"latency_us=%llu\n",
|
||||
event->comm, event->tgid, event->pid, event->requested,
|
||||
@@ -308,124 +275,28 @@ static int handle_event(void *context, void *data, size_t size)
|
||||
events_printed++;
|
||||
return 0;
|
||||
}
|
||||
|
||||
static int poll_until_deadline(struct ring_buffer *ring, long long deadline)
|
||||
{
|
||||
while (!exiting) {
|
||||
long long now = monotonic_milliseconds();
|
||||
int consumed;
|
||||
|
||||
if (now < 0)
|
||||
return (int)now;
|
||||
if (now >= deadline)
|
||||
break;
|
||||
|
||||
consumed = ring_buffer__poll(ring,
|
||||
deadline - now > 100 ? 100 : deadline - now);
|
||||
if (consumed == -EINTR)
|
||||
continue;
|
||||
if (consumed < 0) {
|
||||
fprintf(stderr, "ring buffer poll failed: %s\n",
|
||||
strerror(-consumed));
|
||||
return consumed;
|
||||
}
|
||||
}
|
||||
|
||||
return 0;
|
||||
}
|
||||
|
||||
int main(int argc, char **argv)
|
||||
{
|
||||
struct fsession_latency_bpf *skel = NULL;
|
||||
struct ring_buffer *ring = NULL;
|
||||
long long deadline, now;
|
||||
int err;
|
||||
|
||||
err = parse_args(argc, argv);
|
||||
if (err) {
|
||||
usage(argv[0]);
|
||||
return 1;
|
||||
}
|
||||
|
||||
libbpf_set_print(libbpf_print_fn);
|
||||
signal(SIGINT, handle_signal);
|
||||
signal(SIGTERM, handle_signal);
|
||||
|
||||
skel = fsession_latency_bpf__open();
|
||||
if (!skel) {
|
||||
fprintf(stderr, "failed to open BPF skeleton\n");
|
||||
return 1;
|
||||
}
|
||||
|
||||
skel->rodata->threshold_ns = env.threshold_us * 1000;
|
||||
skel->rodata->target_tgid = env.pid;
|
||||
|
||||
err = fsession_latency_bpf__load(skel);
|
||||
if (err) {
|
||||
fprintf(stderr,
|
||||
"failed to load fsession program: %s\n"
|
||||
"This tool requires Linux 7.0+, BTF, BPF JIT, and x86_64 "
|
||||
"fsession support.\n",
|
||||
strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
err = fsession_latency_bpf__attach(skel);
|
||||
if (err) {
|
||||
fprintf(stderr, "failed to attach to vfs_read: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
ring = ring_buffer__new(bpf_map__fd(skel->maps.events), handle_event, NULL, NULL);
|
||||
err = libbpf_get_error(ring);
|
||||
if (err) {
|
||||
ring = NULL;
|
||||
fprintf(stderr, "failed to create ring buffer: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
|
||||
printf("Tracing vfs_read for %u seconds; threshold=%llu us; pid=%s\n",
|
||||
env.duration, env.threshold_us, env.pid ? "selected" : "all");
|
||||
fflush(stdout);
|
||||
|
||||
now = monotonic_milliseconds();
|
||||
if (now < 0) {
|
||||
err = now;
|
||||
goto cleanup;
|
||||
}
|
||||
deadline = now + env.duration * 1000LL;
|
||||
|
||||
err = poll_until_deadline(ring, deadline);
|
||||
if (err)
|
||||
goto cleanup;
|
||||
|
||||
fsession_latency_bpf__detach(skel);
|
||||
|
||||
err = ring_buffer__consume(ring);
|
||||
if (err < 0) {
|
||||
fprintf(stderr, "ring buffer drain failed: %s\n", strerror(-err));
|
||||
goto cleanup;
|
||||
}
|
||||
err = 0;
|
||||
|
||||
printf("SUMMARY calls=%llu slow=%llu errors=%llu dropped=%llu events=%llu\n",
|
||||
skel->bss->stats.calls, skel->bss->stats.slow,
|
||||
skel->bss->stats.errors, skel->bss->stats.dropped, events_printed);
|
||||
|
||||
cleanup:
|
||||
ring_buffer__free(ring);
|
||||
fsession_latency_bpf__destroy(skel);
|
||||
return err != 0;
|
||||
}
|
||||
```
|
||||
|
||||
加载器的流程比较标准。解析命令行后，打开 skeleton 并把 `threshold_ns` 和 `target_tgid` 写入只读 BPF 配置。用户输入的阈值是微秒单位，乘以 1000 转换为纳秒后写入。调用 `load` 完成 BPF 程序加载，然后附加到 `vfs_read`。加载失败时的诊断同时给出内核 errno 和前置条件列表，方便用户排查问题。
|
||||
每个事件打印进程名、ID、请求字节数、返回值和延迟（微秒）。
|
||||
|
||||
`ring_buffer__new` 创建 ring buffer 消费者，注册 `handle_event` 回调处理每个事件。回调打印 comm、TGID、PID、请求字节数、结果和延迟微秒数，并递增 `events_printed` 计数。
|
||||
**干净关闭序列**：
|
||||
```c
|
||||
fsession_latency_bpf__detach(skel);
|
||||
|
||||
`poll_until_deadline` 函数驱动事件消费循环。它计算单调时间截止点，每次迭代最多轮询 100 ms 直到截止或收到 SIGINT/SIGTERM。轮询返回 `-EINTR` 时继续循环，其他负值表示错误。
|
||||
err = ring_buffer__consume(ring);
|
||||
// ... 错误处理 ...
|
||||
|
||||
轮询结束后，加载器先调用 `fsession_latency_bpf__detach` 解除 fsession 程序的附加，使聚合计数器停止变化。然后调用 `ring_buffer__consume` 投递解除附加前已提交但尚未消费的记录。这个顺序是观察窗口边界正确性的一部分：先停止新事件产生，再排空已有事件，最后读取稳定的计数器。退出时释放 ring buffer 并销毁 skeleton。
|
||||
printf("SUMMARY calls=%llu slow=%llu errors=%llu dropped=%llu events=%llu\n",
|
||||
skel->bss->stats.calls, skel->bss->stats.slow,
|
||||
skel->bss->stats.errors, skel->bss->stats.dropped, events_printed);
|
||||
```
|
||||
|
||||
关闭顺序对正确性很重要：
|
||||
1. 解除 BPF 程序的附加（停止产生新事件）
|
||||
2. 排空 ring buffer 中剩余的事件
|
||||
3. 读取最终的计数器值（现在稳定了，因为程序已解除附加）
|
||||
|
||||
这确保 `events_printed` 与实际通过 ring buffer 投递的事件数一致。
|
||||
|
||||
## 编译与运行
|
||||
|
||||
@@ -444,14 +315,14 @@ SERVICE_PID=$(pgrep -n my-service)
|
||||
sudo ./fsession_latency --pid "$SERVICE_PID" --threshold-us 10000 --duration 30
|
||||
```
|
||||
|
||||
`--pid` 比较的是 `bpf_get_current_pid_tgid()` 返回的 TGID，即宿主机（初始）PID 命名空间中的 TGID。上面的 `pgrep` 适用于直接在宿主机上运行的进程，容器或嵌套 PID 命名空间内的目标需要解析并传入其宿主机可见的 TGID。
|
||||
**关于 PID 命名空间**：`--pid` 选项比较的是宿主机（初始）PID 命名空间中的 TGID。如果目标运行在有自己 PID 命名空间的容器中，你需要找到它在宿主机可见的 TGID。在容器内进程可能是 PID 1，但从宿主机看可能是 PID 12345。在宿主机上使用 `pgrep` 或检查 `/proc/<pid>/status` 中的 `NSpid` 行。
|
||||
|
||||
命令行参数：
|
||||
### 命令行选项
|
||||
|
||||
```text
|
||||
Usage: ./fsession_latency [--threshold-us USEC] [--duration SEC] [--pid TGID] [--verbose]
|
||||
|
||||
Options:
|
||||
选项：
|
||||
-t, --threshold-us USEC 慢读阈值（默认：1000 微秒）
|
||||
-d, --duration SEC 追踪时长，1-86400（默认：10 秒）
|
||||
-p, --pid TGID 追踪指定进程 ID（默认：所有进程）
|
||||
@@ -459,9 +330,9 @@ Options:
|
||||
-h, --help 显示帮助
|
||||
```
|
||||
|
||||
默认阈值 1000 微秒、持续 10 秒、追踪所有进程。`--duration` 接受 1 到 86400 秒，`--pid` 接受 1 到 2^32-1，`--threshold-us` 接受 0 到 `UINT64_MAX / 1000` 微秒（用户空间在加载前转换为纳秒）。空值和尾随字符都会被 `parse_u64` 拒绝。
|
||||
### 输出示例
|
||||
|
||||
以下输出在运行内核 `7.0.0-rc2+` 的 x86_64 环境中采集。集成测试执行 64 次普通文件读取加一次延迟 50 ms 的管道读取，管道读超过 10 ms 阈值后出现在事件流中：
|
||||
以下输出在运行内核 `7.0.0-rc2+` 的 x86_64 环境中采集。集成测试执行 64 次普通文件读取加一次延迟 50 ms 的管道读取。管道读超过 10 ms 阈值后出现在事件流中：
|
||||
|
||||
```console
|
||||
Tracing vfs_read for 1 seconds; threshold=10000 us; pid=selected
|
||||
@@ -471,22 +342,31 @@ TEST-SUMMARY miss_calls=0 high_threshold_calls=66 high_threshold_slow=0 threshol
|
||||
PASS: PID filtering, threshold miss, and slow-read reporting behaved as expected
|
||||
```
|
||||
|
||||
具体调用次数、PID 值和延迟数值因运行环境而异。
|
||||
`SUMMARY` 行显示：
|
||||
- 观察到 66 次 `vfs_read` 调用
|
||||
- 1 次是慢的（达到阈值）
|
||||
- 0 次返回错误
|
||||
- 0 个事件被丢弃
|
||||
- 1 个事件被打印
|
||||
|
||||
运行测试：
|
||||
### 运行测试
|
||||
|
||||
```bash
|
||||
sudo make test
|
||||
```
|
||||
|
||||
集成测试验证四个运行时路径：目标 TGID 为 `UINT32_MAX` 产生零调用和事件、10,000,000 微秒阈值使普通读产生零慢事件、64 次普通文件读加一次延迟 50 ms 的管道读在 10,000 微秒阈值下产生慢事件、阈值为 0 时 `slow == events + dropped` 证明每个阈值匹配调用要么被投递要么被计入 ring buffer 预留失败。CLI 测试覆盖无效 duration、空 duration、空 threshold 和空 PID。
|
||||
集成测试验证：
|
||||
- **PID 过滤**：针对不存在的 TGID 产生零调用
|
||||
- **阈值过滤**：很高的阈值（10 秒）使快速读取产生零慢事件
|
||||
- **事件上报**：故意延迟的管道读取（50ms）在 10ms 阈值下触发事件
|
||||
- **计数不变式**：阈值为 0 时，`slow == events + dropped`（每个达到阈值的调用要么被投递要么被计入丢弃）
|
||||
|
||||
### 环境要求
|
||||
## 环境要求
|
||||
|
||||
| 要求 | 详情 |
|
||||
|---|---|
|
||||
| 内核版本 | Linux 7.0+（fsession 首次引入） |
|
||||
| BTF | 必须启用 (`CONFIG_DEBUG_INFO_BTF=y`) |
|
||||
| BTF | 必须启用（`CONFIG_DEBUG_INFO_BTF=y`） |
|
||||
| 内核配置 | `CONFIG_BPF=y`, `CONFIG_BPF_SYSCALL=y`, `CONFIG_BPF_JIT=y`, `CONFIG_BPF_EVENTS=y`, `CONFIG_DEBUG_INFO_BTF=y`, `CONFIG_DYNAMIC_FTRACE_WITH_DIRECT_CALLS=y` |
|
||||
| BPF JIT | 运行时必须启用 |
|
||||
| 架构 | 已在 x86_64 上测试 |
|
||||
@@ -494,15 +374,28 @@ sudo make test
|
||||
|
||||
运行时行为在 x86_64 内核 `7.0.0-rc2+` 上测试。上游合并提交为 `f17b474e36647c23801ef8fdaf2255ab66dd2973`。
|
||||
|
||||
## 观察范围
|
||||
## 扩展方向
|
||||
|
||||
本工具测量 `vfs_read` 内部的时间，覆盖到达该函数的读路径并按精确的宿主机可见 TGID 筛选。更完整的追踪器可以在保持相同 fsession 关联模式的基础上加入 cgroup、路径、inode、挂载点、栈或长时运行指标维度，现有的 `dropped` 计数器在负载下仍是事件丢失信号。
|
||||
这里展示的 fsession 模式适用于任何需要关联进入和返回的内核函数。一些扩展方向：
|
||||
|
||||
- **其他函数**：附加到 `vfs_write`、`vfs_fsync` 或其他 VFS 操作
|
||||
- **文件路径过滤**：使用 `file->f_path` 按特定文件或挂载点过滤
|
||||
- **堆栈追踪**：添加 `bpf_get_stackid()` 捕获慢调用的内核和/或用户态堆栈
|
||||
- **直方图**：用 `BPF_MAP_TYPE_ARRAY` 的延迟直方图替代逐事件上报
|
||||
- **cgroup 过滤**：添加 cgroup ID 检查实现容器感知的追踪
|
||||
|
||||
`dropped` 计数器仍然是 ring buffer 压力的信号——如果它在增长，要么增大缓冲区大小，要么提高阈值减少事件量。
|
||||
|
||||
## 总结
|
||||
|
||||
本教程展示了如何使用 Linux 7.0 的 fsession 机制测量内核函数延迟。相比传统的 fentry/fexit 两程序配合哈希表的方案，fsession 用一个程序同时处理进入和返回，8 字节的调用级 session cookie 替代外部关联 map 携带时间戳，代码更简洁、无状态泄漏风险、性能开销更低。
|
||||
本教程展示了如何使用 Linux 7.0 的 fsession 机制测量内核函数延迟。相比传统的 fentry/fexit 配合哈希表的方案，主要优势：
|
||||
|
||||
工具的设计演示了 fsession 的核心模式：用 `bpf_session_is_return` 区分阶段，用 `bpf_session_cookie` 传递调用级状态，返回阶段直接访问函数参数和返回值。这个模式适用于任何需要关联函数进入和返回的场景。
|
||||
1. **单个程序**：一个 BPF 程序处理进入和返回，用 `bpf_session_is_return()` 区分阶段
|
||||
2. **内置关联**：8 字节的 session cookie 替代外部哈希表在两个阶段间传递数据
|
||||
3. **无状态泄漏**：内核管理 cookie 生命周期——不需要清理，不可能泄漏
|
||||
4. **返回时可访问参数**：函数参数在返回阶段仍然可用，无需显式存储
|
||||
|
||||
模式很简单：检查 `bpf_session_is_return()`，用 `bpf_session_cookie()` 管理调用级状态，直接访问参数和返回值。这个模式适用于任何需要关联函数进入和退出的场景。
|
||||
|
||||
> 如果你想深入了解 eBPF，请查看我们的教程代码仓库 <https://github.com/eunomia-bpf/bpf-developer-tutorial> 或访问我们的网站 <https://eunomia.dev/tutorials/>。
|
||||
|
||||
|
||||
Reference in New Issue
Block a user