kernel/bpf-developer-tutorial
1
0
Fork 0
mirror of https://github.com/eunomia-bpf/bpf-developer-tutorial.git synced 2026-10-29 11:45:17 +08:00
Code Issues Packages Projects Releases Wiki Activity

Add advanced eBPF tutorials 51–54 and tutorial agent skills (#220)

Browse Source 
* Add targeted TCP connection quarantine tool

* Document TCP quarantine workflow

* Refresh package indexes before CI install

* Document TCP quarantine namespace scope

* Require BPF events for TCP iterator

* Add production fsession latency tracer

* Document fsession latency workflow

* Reject empty fsession CLI values

* Preserve successful fsession exit status

* Document fsession deadline regression test

* Drain fsession events before summary

* Document fsession PID and shutdown semantics

* Simplify fsession polling control flow

* Add bounded BPF egress pacer tutorial

* Test queued packet cleanup on signal

* Document the BPF egress pacer

* Polish and review the BPF egress pacer

* Refactor egress pacer option parsing

* Add executable image inspector lesson

* Build the exec image inspector in CI

* Document executable image inspection

* Handle re-exec chains in the image inspector

* Polish exec image inspector guidance

* Reduce exec inspector wait complexity

* Rewrite the egress pacer tutorial

* Rewrite the exec image inspector tutorial

* Polish the exec image inspector tutorial

* Correct the egress pacer tutorial

* Make the exec tutorial Chinese natural

* Fix egress tutorial prose checks

* Finish the exec tutorial style pass

* Clarify exec tutorial runtime evidence

* Polish exec tutorial scope wording

* Rewrite the egress pacer tutorial for readers

* Regenerate tutorial indexes

* Teach the egress pacer component by component

* Use standard Markdown in the egress tutorial

* Strengthen the egress pacer tutorial narrative

* jiji

* Use positive framing in the egress tutorial

* Rewrite the exec image inspector tutorial

* Rewrite the TCP quarantine tutorial

* Add the egress pacer lifecycle diagram

* Refresh TCP tutorial indexes

* Add the exec image inspection flow diagram

* Use one source directory link

* Rewrite the fsession latency tutorial

* Add fsession feature background

* Add BPF qdisc feature background

* Add TCP iterator feature background

* Add exec inspection feature background

* Require feature background in tutorial openings

* Polish fsession background prose

* Simplify repository tutorial skills

* Update exec inspector tooling revisions

* Restructure tutorials 51-54 following advanced guideline

- Update SKILL.md with strict section ordering and "why" requirements
- Rewrite README.zh.md for tutorials 51-54:
  - Add background sections explaining why traditional approaches fail
  - Move compilation/execution sections after code analysis
  - Add high-level mechanism explanation before code
  - Use paragraph style instead of bullet lists

* Consolidate skill guidelines and remove duplicates

- Update write-bpf-production-tutorial skill to reference 47, 48, 49
- Add structure requirements section with "Why" section emphasis
- Remove duplicate advanced-tutorial-guidelines.md (use scripts/guideline_advance.md instead)

* Rewrite English READMEs 51-54 to match Chinese structure

Restructure all four English tutorials to match their Chinese counterparts:
- Add "Why this approach is needed" sections explaining traditional limitations
- Add high-level mechanism sections before code
- Move compilation/execution sections after code analysis
- Add environment requirements tables
- Use consistent section ordering across all tutorials

* Regenerate TOC after tutorial title changes

Run generate_toc.py to sync SUMMARY and README files with
updated tutorial titles from the restructuring.

* Regenerate compatibility tables after title changes

---------

Co-authored-by: LinuxDev9002 <i@littlefisher.me>
This commit is contained in:
云微
2026-07-19 19:34:09 -07:00
committed by GitHub
parent d055a0833f
commit ca1267d82a
57 changed files with 9014 additions and 385 deletions
Download Patch File Download Diff File Expand all files Collapse all files

10
src/52-fsession-latency/.config Normal file
View File

@@ -0,0 +1,10 @@
level=Depth
type=Tracing
kernel_min=7.0
kernel_min_basis=documented
architectures=x86_64
btf=required
kernel_config=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
hardware=none
root=required
test_status=ci-build

15
src/52-fsession-latency/.gitignore vendored Normal file
View File

@@ -0,0 +1,15 @@
# Build artifacts
.output/
*.o
*.skel.h
# Generated binary
fsession_latency
# Python cache
__pycache__/
# Editor files
*.swp
*~
.vscode/

92
src/52-fsession-latency/Makefile Normal file
View File

@@ -0,0 +1,92 @@
# SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause)
OUTPUT := .output
CLANG ?= clang
LIBBPF_SRC := $(abspath ../third_party/libbpf/src)
BPFTOOL_SRC := $(abspath ../third_party/bpftool/src)
LIBBPF_OBJ := $(abspath $(OUTPUT)/libbpf.a)
BPFTOOL_OUTPUT ?= $(abspath $(OUTPUT)/bpftool)
BPFTOOL ?= $(BPFTOOL_OUTPUT)/bootstrap/bpftool
ARCH ?= $(shell uname -m | sed 's/x86_64/x86/' \
| sed 's/arm.*/arm/' \
| sed 's/aarch64/arm64/' \
| sed 's/ppc64le/powerpc/' \
| sed 's/mips.*/mips/' \
| sed 's/riscv64/riscv/' \
| sed 's/loongarch64/loongarch/')
VMLINUX := ../third_party/vmlinux/$(ARCH)/vmlinux.h
INCLUDES := -I$(OUTPUT) -I../third_party/libbpf/include/uapi -I$(dir $(VMLINUX)) -I.
CFLAGS := -g -Wall -Wextra
ALL_LDFLAGS := $(LDFLAGS) $(EXTRA_LDFLAGS)
APPS = fsession_latency
CLANG_BPF_SYS_INCLUDES ?= $(shell $(CLANG) -v -E - </dev/null 2>&1 \
| sed -n '/<...> search starts here:/,/End of search list./{ s| \(/.*\)|-idirafter \1|p }')
ifeq ($(V),1)
Q =
msg =
else
Q = @
msg = @printf ' %-8s %s%s\n' "$(1)" \
"$(patsubst $(abspath $(OUTPUT))/%,%,$(2))" \
"$(if $(3), $(3))";
MAKEFLAGS += --no-print-directory
endif
define allow-override
$(if $(or $(findstring environment,$(origin $(1))),\
$(findstring command line,$(origin $(1)))),,\
$(eval $(1) = $(2)))
endef
$(call allow-override,CC,$(CROSS_COMPILE)cc)
$(call allow-override,LD,$(CROSS_COMPILE)ld)
.PHONY: all clean test
all: $(APPS)
clean:
$(call msg,CLEAN)
$(Q)rm -rf $(OUTPUT) $(APPS)
test: all
python3 tests/test_fsession_latency.py ./fsession_latency
$(OUTPUT) $(OUTPUT)/libbpf $(BPFTOOL_OUTPUT):
$(call msg,MKDIR,$@)
$(Q)mkdir -p $@
$(LIBBPF_OBJ): $(wildcard $(LIBBPF_SRC)/*.[ch] $(LIBBPF_SRC)/Makefile) | $(OUTPUT)/libbpf
$(call msg,LIB,$@)
$(Q)$(MAKE) -C $(LIBBPF_SRC) BUILD_STATIC_ONLY=1 \
OBJDIR=$(dir $@)/libbpf DESTDIR=$(dir $@) \
INCLUDEDIR= LIBDIR= UAPIDIR= install
$(BPFTOOL): | $(BPFTOOL_OUTPUT)
$(call msg,BPFTOOL,$@)
$(Q)$(MAKE) ARCH= CROSS_COMPILE= OUTPUT=$(BPFTOOL_OUTPUT)/ -C $(BPFTOOL_SRC) bootstrap
$(OUTPUT)/%.bpf.o: %.bpf.c $(LIBBPF_OBJ) $(wildcard %.h) $(VMLINUX) | $(OUTPUT) $(BPFTOOL)
$(call msg,BPF,$@)
$(Q)$(CLANG) -g -O2 -target bpf -D__TARGET_ARCH_$(ARCH) \
$(INCLUDES) $(CLANG_BPF_SYS_INCLUDES) \
-c $(filter %.c,$^) -o $(patsubst %.bpf.o,%.tmp.bpf.o,$@)
$(Q)$(BPFTOOL) gen object $@ $(patsubst %.bpf.o,%.tmp.bpf.o,$@)
$(OUTPUT)/%.skel.h: $(OUTPUT)/%.bpf.o | $(OUTPUT) $(BPFTOOL)
$(call msg,GEN-SKEL,$@)
$(Q)$(BPFTOOL) gen skeleton $< > $@
$(patsubst %,$(OUTPUT)/%.o,$(APPS)): %.o: %.skel.h
$(OUTPUT)/%.o: %.c $(wildcard %.h) | $(OUTPUT)
$(call msg,CC,$@)
$(Q)$(CC) $(CFLAGS) $(INCLUDES) -c $(filter %.c,$^) -o $@
$(APPS): %: $(OUTPUT)/%.o $(LIBBPF_OBJ) | $(OUTPUT)
$(call msg,BINARY,$@)
$(Q)$(CC) $(CFLAGS) $^ $(ALL_LDFLAGS) -lelf -lz -o $@
.DELETE_ON_ERROR:
.SECONDARY:

515
src/52-fsession-latency/README.md Normal file
View File

@@ -0,0 +1,515 @@
# 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?
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.
> Complete source: <https://github.com/eunomia-bpf/bpf-developer-tutorial/tree/main/src/52-fsession-latency>
## Why fsession Is Needed
Traditional approaches to measuring function latency all have notable limitations.
**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.
**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.
**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.
**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.
## How fsession Works
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.
`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.
`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.
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.
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.
## 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.
### 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.
```c
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
#ifndef __FSESSION_LATENCY_H
#define __FSESSION_LATENCY_H
#define FSESSION_COMM_LEN 16
struct latency_event {
unsigned int pid;
unsigned int tgid;
unsigned long long requested;
long long result;
unsigned long long latency_ns;
char comm[FSESSION_COMM_LEN];
};
struct latency_stats {
unsigned long long calls;
unsigned long long slow;
unsigned long long errors;
unsigned long long dropped;
};
#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`.
### 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.
```c
// SPDX-License-Identifier: GPL-2.0
#define bpf_session_is_return bpf_session_is_return_vmlinux_snapshot
#define bpf_session_cookie bpf_session_cookie_vmlinux_snapshot
#include "vmlinux.h"
#undef bpf_session_is_return
#undef bpf_session_cookie
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
#include "fsession_latency.h"
char LICENSE[] SEC("license") = "GPL";
const volatile __u64 threshold_ns;
const volatile __u32 target_tgid;
struct latency_stats stats;
struct {
__uint(type, BPF_MAP_TYPE_RINGBUF);
__uint(max_entries, 256 * 1024);
} events SEC(".maps");
/*
* The repository vmlinux.h snapshot predates the ctx argument on these
* kfunc prototypes. Rename those stale declarations while including the
* snapshot, then provide the Linux 7.0 signatures below.
*/
extern bool bpf_session_is_return(void *ctx) __ksym;
extern __u64 *bpf_session_cookie(void *ctx) __ksym;
SEC("fsession/vfs_read")
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
loff_t *pos, ssize_t ret)
{
__u64 pid_tgid = bpf_get_current_pid_tgid();
__u64 *started = bpf_session_cookie(ctx);
struct latency_event *event;
__u64 latency;
if (!bpf_session_is_return(ctx)) {
if (target_tgid && pid_tgid >> 32 != target_tgid) {
*started = 0;
return 0;
}
*started = bpf_ktime_get_ns();
return 0;
}
if (!*started)
return 0;
latency = bpf_ktime_get_ns() - *started;
__sync_fetch_and_add(&stats.calls, 1);
if (ret < 0)
__sync_fetch_and_add(&stats.errors, 1);
if (latency < threshold_ns)
return 0;
__sync_fetch_and_add(&stats.slow, 1);
event = bpf_ringbuf_reserve(&events, sizeof(*event), 0);
if (!event) {
__sync_fetch_and_add(&stats.dropped, 1);
return 0;
}
event->pid = (__u32)pid_tgid;
event->tgid = pid_tgid >> 32;
event->requested = count;
event->result = ret;
event->latency_ns = latency;
bpf_get_current_comm(event->comm, sizeof(event->comm));
bpf_ringbuf_submit(event, 0);
return 0;
}
```
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.
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.
### User-Space Loader
`fsession_latency.c` parses the command line, configures BPF constants, manages the observation window, and prints results.
```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"
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, &timestamp))
return -errno;
return timestamp.tv_sec * 1000LL + timestamp.tv_nsec / 1000000;
}
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,
event->result, event->latency_ns / 1000);
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.
`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`.
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.
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.
## Compilation and Execution
Build from source (the repository vendors libbpf 1.7.0 and bpftool v7.7.0):
```bash
cd src/52-fsession-latency
make clean
make -j2
```
Trace a specific service process for 30 seconds, reporting reads of 10 ms or longer:
```bash
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.
Command-line arguments:
```text
Usage: ./fsession_latency [--threshold-us USEC] [--duration SEC] [--pid TGID] [--verbose]
Options:
-t, --threshold-us USEC slow-read threshold (default: 1000 microseconds)
-d, --duration SEC trace duration, 1-86400 (default: 10 seconds)
-p, --pid TGID trace a specific process ID (default: all processes)
-v, --verbose print libbpf diagnostics
-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`.
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
EVENT comm=python3 tgid=1257 pid=1257 requested=1 result=1 latency_us=50160
SUMMARY calls=66 slow=1 errors=0 dropped=0 events=1
TEST-SUMMARY miss_calls=0 high_threshold_calls=66 high_threshold_slow=0 threshold_calls=66 threshold_slow=1 events=1 dropped=0
PASS: PID filtering, threshold miss, and slow-read reporting behaved as expected
```
Exact call counts, PID values, and latency numbers vary by run.
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.
### Environment Requirements
| Requirement | Details |
|---|---|
| Kernel version | Linux 7.0+ (fsession first introduced) |
| BTF | Must be enabled (`CONFIG_DEBUG_INFO_BTF=y`) |
| Kernel config | `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 | Must be enabled at runtime |
| Architecture | Tested on x86_64 |
| Privilege | root |
Runtime behavior was tested on x86_64 with kernel `7.0.0-rc2+`. The upstream merge commit is `f17b474e36647c23801ef8fdaf2255ab66dd2973`.
## Observation Scope
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.
## 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.
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.
> 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/>.
## References
- [Linux fsession merge commit](https://github.com/torvalds/linux/commit/f17b474e36647c23801ef8fdaf2255ab66dd2973)
- [Upstream fsession program selftest](https://github.com/torvalds/linux/blob/v7.1/tools/testing/selftests/bpf/progs/fsession_test.c)
- [Upstream fsession runner selftest](https://github.com/torvalds/linux/blob/v7.1/tools/testing/selftests/bpf/prog_tests/fsession_test.c)
- [libbpf 1.7.0](https://github.com/libbpf/libbpf/releases/tag/v1.7.0)
- [bpftool v7.7.0](https://github.com/libbpf/bpftool/releases/tag/v7.7.0)

515
src/52-fsession-latency/README.zh.md Normal file
View File

@@ -0,0 +1,515 @@
# eBPF 教程：使用 fsession 追踪慢速 vfs_read 调用
假设一个文件服务出现了读延迟尖峰，应用层计时只能告诉你请求变慢了，却无法区分是内核读路径阻塞还是用户态逻辑耗时。有用的问题是：哪个线程发起了读操作、请求了多少字节、调用返回了什么、这一次 `vfs_read` 花了多长时间。
本教程展示如何使用 Linux 7.0 引入的 fsession 机制测量 `vfs_read` 调用延迟。工具在函数进入时记录时间戳、返回时计算延迟，按 TGID 和阈值过滤后上报慢读事件。
> 完整源码：<https://github.com/eunomia-bpf/bpf-developer-tutorial/tree/main/src/52-fsession-latency>
## 为什么需要 fsession
传统的函数延迟测量方案都有明显的局限性。
**独立的 fentry 和 fexit 程序**是最常见的做法。你需要编写两个 BPF 程序，一个附加到函数入口，一个附加到函数返回。两个程序之间需要通过一个按线程索引的哈希表来传递时间戳：进入时存入 `bpf_get_current_pid_tgid()` 到时间戳的映射，返回时查找并删除。这个模式有几个问题：首先需要维护额外的哈希表，每次调用都有查找和删除的开销；其次如果进入后没有正常返回（比如线程被杀死），哈希表中的条目会泄漏；最后两个程序之间没有天然的关联，状态传递完全依赖外部数据结构。
**kprobe 和 kretprobe**同样需要两个独立的程序和外部哈希表。相比 fentry/fexit，kprobe 的开销更大，因为它通过断点机制工作，而 fentry 直接挂钩到函数序言，在 x86_64 上使用 JIT 优化的调用序列。
**用户态采样**如 `perf record` 或 `bpftrace` 的周期性堆栈采样只能提供统计概貌，无法精确测量每次调用的延迟。对于需要捕获尾部延迟事件的场景，采样可能完全错过关键的慢调用。
**fsession 机制**从根本上解决了这个问题。Linux 7.0 引入了 fsession，它让同一个 BPF 程序在被追踪函数的进入和返回阶段各执行一次，并通过 `bpf_session_cookie(ctx)` 提供一个 8 字节的调用级暂存区。这个 cookie 从进入到返回期间持续有效，完全替代了外部哈希表。程序用 `bpf_session_is_return(ctx)` 区分两个阶段，在同一个程序内处理所有逻辑。
## fsession 的工作原理
fsession 是一种特殊的 ftracing 程序类型。当你用 `SEC("fsession/vfs_read")` 声明一个程序时，内核会在 `vfs_read` 的进入和返回阶段各调用一次你的 BPF 程序。
`bpf_session_is_return(ctx)` 返回 false 表示进入阶段，返回 true 表示返回阶段。程序可以用这个 helper 函数区分当前处于哪个阶段，执行相应的逻辑。
`bpf_session_cookie(ctx)` 返回一个指向 8 字节暂存区的指针。这个暂存区是每次调用独立的，从进入阶段到返回阶段持续有效。你可以在进入阶段写入数据（比如时间戳），在返回阶段读取并使用它。
返回阶段的上下文不仅包含原始函数参数，还包含函数的返回值。对于 `vfs_read`，进入时能看到 `file`、`buf`、`count`、`pos` 四个参数，返回时还能看到 `ret` 返回值。这意味着你不需要把参数存到 map 里，返回阶段可以直接访问。
`fsession_latency` 工具利用这些能力实现延迟测量。进入阶段，它检查 TGID 是否匹配目标进程，匹配的调用在 cookie 中存入 `bpf_ktime_get_ns()` 时间戳。返回阶段，它从 cookie 读取时间戳计算延迟，递增聚合计数器，超过阈值的调用通过 ring buffer 上报详细事件。
## 代码实现
本工具由三个文件组成：共享头文件定义事件和统计结构、BPF 程序测量延迟并提交事件、用户空间加载器管理生命周期并打印结果。
### 共享头文件
`fsession_latency.h` 定义了 BPF 和用户空间共享的事件与统计结构。`latency_event` 包含 32 位 PID 和 TGID、64 位请求字节数、有符号 64 位返回值、纳秒精度延迟和进程名。`latency_stats` 包含四个计数器用于聚合统计。
```c
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
#ifndef __FSESSION_LATENCY_H
#define __FSESSION_LATENCY_H
#define FSESSION_COMM_LEN 16
struct latency_event {
unsigned int pid;
unsigned int tgid;
unsigned long long requested;
long long result;
unsigned long long latency_ns;
char comm[FSESSION_COMM_LEN];
};
struct latency_stats {
unsigned long long calls;
unsigned long long slow;
unsigned long long errors;
unsigned long long dropped;
};
#endif /* __FSESSION_LATENCY_H */
```
四个计数器分别记录：`calls` 是总调用数、`slow` 是达到阈值的调用数、`errors` 是返回负值的调用数、`dropped` 是 ring buffer 预留失败的计数。`FSESSION_COMM_LEN` 设为 16，与内核 `TASK_COMM_LEN` 一致。
### BPF 程序
`fsession_latency.bpf.c` 使用 `SEC("fsession/vfs_read")` 声明为 fsession 类型。内核会在 `vfs_read` 的进入和返回阶段各调用一次这个程序。
```c
// SPDX-License-Identifier: GPL-2.0
#define bpf_session_is_return bpf_session_is_return_vmlinux_snapshot
#define bpf_session_cookie bpf_session_cookie_vmlinux_snapshot
#include "vmlinux.h"
#undef bpf_session_is_return
#undef bpf_session_cookie
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
#include "fsession_latency.h"
char LICENSE[] SEC("license") = "GPL";
const volatile __u64 threshold_ns;
const volatile __u32 target_tgid;
struct latency_stats stats;
struct {
__uint(type, BPF_MAP_TYPE_RINGBUF);
__uint(max_entries, 256 * 1024);
} events SEC(".maps");
/*
* The repository vmlinux.h snapshot predates the ctx argument on these
* kfunc prototypes. Rename those stale declarations while including the
* snapshot, then provide the Linux 7.0 signatures below.
*/
extern bool bpf_session_is_return(void *ctx) __ksym;
extern __u64 *bpf_session_cookie(void *ctx) __ksym;
SEC("fsession/vfs_read")
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
loff_t *pos, ssize_t ret)
{
__u64 pid_tgid = bpf_get_current_pid_tgid();
__u64 *started = bpf_session_cookie(ctx);
struct latency_event *event;
__u64 latency;
if (!bpf_session_is_return(ctx)) {
if (target_tgid && pid_tgid >> 32 != target_tgid) {
*started = 0;
return 0;
}
*started = bpf_ktime_get_ns();
return 0;
}
if (!*started)
return 0;
latency = bpf_ktime_get_ns() - *started;
__sync_fetch_and_add(&stats.calls, 1);
if (ret < 0)
__sync_fetch_and_add(&stats.errors, 1);
if (latency < threshold_ns)
return 0;
__sync_fetch_and_add(&stats.slow, 1);
event = bpf_ringbuf_reserve(&events, sizeof(*event), 0);
if (!event) {
__sync_fetch_and_add(&stats.dropped, 1);
return 0;
}
event->pid = (__u32)pid_tgid;
event->tgid = pid_tgid >> 32;
event->requested = count;
event->result = ret;
event->latency_ns = latency;
bpf_get_current_comm(event->comm, sizeof(event->comm));
bpf_ringbuf_submit(event, 0);
return 0;
}
```
程序结构分为进入阶段和返回阶段两部分。两个 `const volatile` 变量位于 `.rodata` 段，用户态在 `open()` 之后、`load()` 之前写入阈值和目标 TGID，验证器将它们视为编译期常量。`bpf_session_is_return` 和 `bpf_session_cookie` 通过 `extern ... __ksym` 声明为 kfunc 符号，内核在加载时解析。
进入阶段，程序调用 `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` 可以直接使用，不需要这个桥接。
### 用户空间加载器
`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"
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, &timestamp))
return -errno;
return timestamp.tv_sec * 1000LL + timestamp.tv_nsec / 1000000;
}
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,
event->result, event->latency_ns / 1000);
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 和前置条件列表，方便用户排查问题。
`ring_buffer__new` 创建 ring buffer 消费者，注册 `handle_event` 回调处理每个事件。回调打印 comm、TGID、PID、请求字节数、结果和延迟微秒数，并递增 `events_printed` 计数。
`poll_until_deadline` 函数驱动事件消费循环。它计算单调时间截止点，每次迭代最多轮询 100 ms 直到截止或收到 SIGINT/SIGTERM。轮询返回 `-EINTR` 时继续循环，其他负值表示错误。
轮询结束后，加载器先调用 `fsession_latency_bpf__detach` 解除 fsession 程序的附加，使聚合计数器停止变化。然后调用 `ring_buffer__consume` 投递解除附加前已提交但尚未消费的记录。这个顺序是观察窗口边界正确性的一部分：先停止新事件产生，再排空已有事件，最后读取稳定的计数器。退出时释放 ring buffer 并销毁 skeleton。
## 编译与运行
从源码构建（仓库内置 libbpf 1.7.0 和 bpftool v7.7.0）：
```bash
cd src/52-fsession-latency
make clean
make -j2
```
追踪指定服务进程 30 秒，上报 10 ms 及以上的读操作：
```bash
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。
命令行参数：
```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（默认：所有进程）
-v, --verbose 打印 libbpf 诊断信息
-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 阈值后出现在事件流中：
```console
Tracing vfs_read for 1 seconds; threshold=10000 us; pid=selected
EVENT comm=python3 tgid=1257 pid=1257 requested=1 result=1 latency_us=50160
SUMMARY calls=66 slow=1 errors=0 dropped=0 events=1
TEST-SUMMARY miss_calls=0 high_threshold_calls=66 high_threshold_slow=0 threshold_calls=66 threshold_slow=1 events=1 dropped=0
PASS: PID filtering, threshold miss, and slow-read reporting behaved as expected
```
具体调用次数、PID 值和延迟数值因运行环境而异。
运行测试：
```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。
### 环境要求
| 要求 | 详情 |
|---|---|
| 内核版本 | Linux 7.0+（fsession 首次引入） |
| 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 上测试 |
| 权限 | root |
运行时行为在 x86_64 内核 `7.0.0-rc2+` 上测试。上游合并提交为 `f17b474e36647c23801ef8fdaf2255ab66dd2973`。
## 观察范围
本工具测量 `vfs_read` 内部的时间，覆盖到达该函数的读路径并按精确的宿主机可见 TGID 筛选。更完整的追踪器可以在保持相同 fsession 关联模式的基础上加入 cgroup、路径、inode、挂载点、栈或长时运行指标维度，现有的 `dropped` 计数器在负载下仍是事件丢失信号。
## 总结
本教程展示了如何使用 Linux 7.0 的 fsession 机制测量内核函数延迟。相比传统的 fentry/fexit 两程序配合哈希表的方案，fsession 用一个程序同时处理进入和返回，8 字节的调用级 session cookie 替代外部关联 map 携带时间戳，代码更简洁、无状态泄漏风险、性能开销更低。
工具的设计演示了 fsession 的核心模式：用 `bpf_session_is_return` 区分阶段，用 `bpf_session_cookie` 传递调用级状态，返回阶段直接访问函数参数和返回值。这个模式适用于任何需要关联函数进入和返回的场景。
> 如果你想深入了解 eBPF，请查看我们的教程代码仓库 <https://github.com/eunomia-bpf/bpf-developer-tutorial> 或访问我们的网站 <https://eunomia.dev/tutorials/>。
## 参考资料
- [Linux fsession 合并提交](https://github.com/torvalds/linux/commit/f17b474e36647c23801ef8fdaf2255ab66dd2973)
- [上游 fsession 程序自测试](https://github.com/torvalds/linux/blob/v7.1/tools/testing/selftests/bpf/progs/fsession_test.c)
- [上游 fsession 运行器自测试](https://github.com/torvalds/linux/blob/v7.1/tools/testing/selftests/bpf/prog_tests/fsession_test.c)
- [libbpf 1.7.0](https://github.com/libbpf/libbpf/releases/tag/v1.7.0)
- [bpftool v7.7.0](https://github.com/libbpf/bpftool/releases/tag/v7.7.0)

74
src/52-fsession-latency/fsession_latency.bpf.c Normal file
View File

@@ -0,0 +1,74 @@
// SPDX-License-Identifier: GPL-2.0
#define bpf_session_is_return bpf_session_is_return_vmlinux_snapshot
#define bpf_session_cookie bpf_session_cookie_vmlinux_snapshot
#include "vmlinux.h"
#undef bpf_session_is_return
#undef bpf_session_cookie
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>
#include "fsession_latency.h"
char LICENSE[] SEC("license") = "GPL";
const volatile __u64 threshold_ns;
const volatile __u32 target_tgid;
struct latency_stats stats;
struct {
__uint(type, BPF_MAP_TYPE_RINGBUF);
__uint(max_entries, 256 * 1024);
} events SEC(".maps");
/*
* The repository vmlinux.h snapshot predates the ctx argument on these
* kfunc prototypes. Rename those stale declarations while including the
* snapshot, then provide the Linux 7.0 signatures below.
*/
extern bool bpf_session_is_return(void *ctx) __ksym;
extern __u64 *bpf_session_cookie(void *ctx) __ksym;
SEC("fsession/vfs_read")
int BPF_PROG(measure_vfs_read, struct file *file, char *buf, size_t count,
loff_t *pos, ssize_t ret)
{
__u64 pid_tgid = bpf_get_current_pid_tgid();
__u64 *started = bpf_session_cookie(ctx);
struct latency_event *event;
__u64 latency;
if (!bpf_session_is_return(ctx)) {
if (target_tgid && pid_tgid >> 32 != target_tgid) {
*started = 0;
return 0;
}
*started = bpf_ktime_get_ns();
return 0;
}
if (!*started)
return 0;
latency = bpf_ktime_get_ns() - *started;
__sync_fetch_and_add(&stats.calls, 1);
if (ret < 0)
__sync_fetch_and_add(&stats.errors, 1);
if (latency < threshold_ns)
return 0;
__sync_fetch_and_add(&stats.slow, 1);
event = bpf_ringbuf_reserve(&events, sizeof(*event), 0);
if (!event) {
__sync_fetch_and_add(&stats.dropped, 1);
return 0;
}
event->pid = (__u32)pid_tgid;
event->tgid = pid_tgid >> 32;
event->requested = count;
event->result = ret;
event->latency_ns = latency;
bpf_get_current_comm(event->comm, sizeof(event->comm));
bpf_ringbuf_submit(event, 0);
return 0;
}

255
src/52-fsession-latency/fsession_latency.c Normal file
View File

@@ -0,0 +1,255 @@
// 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"
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, &timestamp))
return -errno;
return timestamp.tv_sec * 1000LL + timestamp.tv_nsec / 1000000;
}
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,
event->result, event->latency_ns / 1000);
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;
}

23
src/52-fsession-latency/fsession_latency.h Normal file
View File

@@ -0,0 +1,23 @@
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
#ifndef __FSESSION_LATENCY_H
#define __FSESSION_LATENCY_H
#define FSESSION_COMM_LEN 16
struct latency_event {
unsigned int pid;
unsigned int tgid;
unsigned long long requested;
long long result;
unsigned long long latency_ns;
char comm[FSESSION_COMM_LEN];
};
struct latency_stats {
unsigned long long calls;
unsigned long long slow;
unsigned long long errors;
unsigned long long dropped;
};
#endif /* __FSESSION_LATENCY_H */

217
src/52-fsession-latency/tests/test_fsession_latency.py Normal file
View File

@@ -0,0 +1,217 @@
#!/usr/bin/env python3
"""Deterministic runtime checks for the fsession latency tool."""
from __future__ import annotations
import os
import pathlib
import re
import select
import subprocess
import sys
import threading
import time
SUMMARY = re.compile(
r"SUMMARY calls=(\d+) slow=(\d+) errors=(\d+) dropped=(\d+) events=(\d+)"
)
EVENT = re.compile(
r"^EVENT comm=.{16} tgid=(\d+) pid=(\d+) requested=(\d+) "
r"result=(-?\d+) latency_us=(\d+)$",
re.MULTILINE,
)
def wait_until_attached(process: subprocess.Popen[str]) -> list[str]:
lines: list[str] = []
deadline = time.monotonic() + 8
assert process.stdout is not None
while time.monotonic() < deadline:
readable, _, _ = select.select([process.stdout], [], [], 0.25)
if readable:
line = process.stdout.readline()
if line:
lines.append(line)
if line.startswith("Tracing vfs_read"):
return lines
if process.poll() is not None:
break
process.kill()
remainder, _ = process.communicate()
raise AssertionError("tool did not attach:\n" + "".join(lines) + remainder)
def generate_reads() -> None:
path = pathlib.Path(__file__)
descriptor = os.open(path, os.O_RDONLY)
try:
for _ in range(64):
os.lseek(descriptor, 0, os.SEEK_SET)
os.read(descriptor, 256)
finally:
os.close(descriptor)
read_fd, write_fd = os.pipe()
def delayed_write() -> None:
time.sleep(0.05)
os.write(write_fd, b"x")
os.close(write_fd)
writer = threading.Thread(target=delayed_write)
writer.start()
try:
assert os.read(read_fd, 1) == b"x"
finally:
os.close(read_fd)
writer.join()
def run_trace(
binary: str,
*arguments: str,
workload: bool,
continuous: bool = False,
) -> tuple[dict[str, int], str]:
process = subprocess.Popen(
[binary, *arguments],
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
text=True,
bufsize=1,
)
lines = wait_until_attached(process)
stop_workload = threading.Event()
producer: threading.Thread | None = None
if continuous:
path = pathlib.Path(__file__)
def generate_continuous_reads() -> None:
descriptor = os.open(path, os.O_RDONLY)
try:
while not stop_workload.is_set():
os.lseek(descriptor, 0, os.SEEK_SET)
os.read(descriptor, 1)
time.sleep(0.001)
finally:
os.close(descriptor)
producer = threading.Thread(target=generate_continuous_reads)
producer.start()
elif workload:
generate_reads()
try:
remainder, _ = process.communicate(timeout=8)
finally:
stop_workload.set()
if producer is not None:
producer.join()
output = "".join(lines) + remainder
if process.returncode != 0:
raise AssertionError(f"tool failed with {process.returncode}:\n{output}")
match = SUMMARY.search(output)
if not match:
raise AssertionError("missing summary:\n" + output)
values = dict(zip(("calls", "slow", "errors", "dropped", "events"), map(int, match.groups())))
return values, output
def main() -> int:
binary = sys.argv[1] if len(sys.argv) > 1 else "./fsession_latency"
invalid = subprocess.run(
[binary, "--duration", "invalid"],
text=True,
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
check=False,
)
assert invalid.returncode != 0
assert "invalid duration" in invalid.stdout
empty_threshold = subprocess.run(
[binary, "--threshold-us", ""],
text=True,
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
check=False,
)
assert empty_threshold.returncode != 0
assert "invalid threshold" in empty_threshold.stdout
pid = str(os.getpid())
missed, _ = run_trace(
binary,
"--duration", "1",
"--threshold-us", "0",
"--pid", str(2**32 - 1),
workload=True,
)
assert missed == {"calls": 0, "slow": 0, "errors": 0, "dropped": 0, "events": 0}, missed
below_threshold, _ = run_trace(
binary,
"--duration", "1",
"--threshold-us", "10000000",
"--pid", pid,
workload=True,
)
assert below_threshold["calls"] >= 64, below_threshold
assert below_threshold["slow"] == 0, below_threshold
assert below_threshold["events"] == 0, below_threshold
slow, slow_output = run_trace(
binary,
"--duration", "1",
"--threshold-us", "10000",
"--pid", pid,
workload=True,
)
assert slow["calls"] >= 65, slow
assert 1 <= slow["slow"] < slow["calls"], slow
assert slow["events"] > 0, slow
event_records = [tuple(map(int, match.groups())) for match in EVENT.finditer(slow_output)]
assert any(
tgid == os.getpid()
and thread_pid == os.getpid()
and requested == 1
and result == 1
and latency_us >= 10000
for tgid, thread_pid, requested, result, latency_us in event_records
), slow_output
deadline, _ = run_trace(
binary,
"--duration", "1",
"--threshold-us", "0",
"--pid", pid,
workload=False,
continuous=True,
)
assert deadline["calls"] > 0, deadline
assert deadline["events"] > 0, deadline
assert deadline["slow"] == deadline["events"] + deadline["dropped"], deadline
tracing_line = next(line for line in slow_output.splitlines() if line.startswith("Tracing "))
first_event = next(line for line in slow_output.splitlines() if line.startswith("EVENT "))
tool_summary = next(line for line in slow_output.splitlines() if line.startswith("SUMMARY "))
print(tracing_line)
print(first_event)
print(tool_summary)
print(
"TEST-SUMMARY miss_calls=0 "
f"high_threshold_calls={below_threshold['calls']} high_threshold_slow=0 "
f"threshold_calls={slow['calls']} threshold_slow={slow['slow']} "
f"events={slow['events']} dropped={slow['dropped']}"
)
print("PASS: PID filtering, threshold miss, and slow-read reporting behaved as expected")
return 0
if __name__ == "__main__":
raise SystemExit(main())