Ubuntu 20.04下eBPF上下文切换追踪时间戳跳变问题咨询

问题背景 #

在裸机Ubuntu 20.04服务器上使用eBPF追踪上下文切换时，出现追踪时间戳跳变现象。该问题在多台服务器、多次运行中均复现：重启服务器后首次运行程序时时间戳表现正常，但首次运行后异常会持续；跳变需一段时间才会发生，且每次跳变都会缩小内核时间戳与Python性能计数器的差值，跳变恢复后仅存在小幅波动。

现有追踪代码 #

#!/usr/bin/python
#
# trace context switch
import time
start_time = time.time()
from bcc import BPF

print("imports: " + str(time.time() - start_time))

# load BPF program
b = BPF(text="""
TRACEPOINT_PROBE(sched, sched_switch) {
    // cat /sys/kernel/debug/tracing/events/sched/sched_switch/format
    bpf_trace_printk("%d\\n", args->prev_prio);
    return 0;
}
""")

print("BPF program set: " + str(time.time() - start_time))

# data structures
unique_pid_counts = {}
timeline = []
value_errors = 0
time_diffs = []

"""
Collects data from the context switch trace and stores it in the data structures unique_task_counts and timeline
"""

print("Started tracing: " + str(time.time() - start_time))

while True:
    try:
        # get current time
        current_time = time.perf_counter()
        # capture data from trace
        data = b.trace_fields() # (task, pid, cpu, flags, ts, msg)
        # add task to timeline
        timeline.append(data)
        # output
        # if counter % 2000 == 0:
        time_diffs.append((data, current_time - data[4]))
    except ValueError:
        value_errors += 1
        continue
    except KeyboardInterrupt:
        # feedback to the user
        print("Finished tracing: " + str(time.time() - start_time) + " seconds")
        if value_errors:
            print("value errors: " + str(value_errors))
        # write the differences to a file
        with open("Data/time_diffs.txt", "w") as fl:
            fl.write("\n".join(str(x) for x in time_diffs))
        # process the data
        from data_process import tracing_data_process
        tracing_data_process(timeline)
        # finished tracing
        print("Finished processing timeline, total run: " + str(round(time.time() - start_time, 3)) + " seconds")
        exit()

异常时间戳记录 #

以下为存储的追踪数据片段，格式为((任务名,进程ID,CPU编号,标志,时间戳,消息), Python性能计数器-时间戳)，其中跳变的两条记录已加粗：

((b'kworker/u32:0', 62419, 13, b'd...', 5032.112517, b'120'), 344.77145957000084)
((b'<idle>', 0, 13, b'd...', 5032.112689, b'120'), 344.77129126600084)
((b'kworker/u32:0', 62419, 13, b'd...', 5032.112701, b'120'), 344.77128291699955)
((b'<idle>', 0, 13, b'd...', 5032.114244, b'120'), 344.7697435989994)
((b'kworker/u32:0', 62419, 13, b'd...', 5032.114271, b'120'), 344.7697202419995)
((b'<idle>', 0, 1, b'd...', 5032.114313, b'120'), 344.76968189200034)

((b'sshd', 45772, 1, b'd...', 5032.114459, b'120'), 344.7695395889996)

((b'', 0, 14, b'd...', 5377.338941, b'120'), -0.45493316400006734)

((b'kworker/u32:4', 21613, 14, b'd...', 5377.338969, b'120'), -0.4549573809999856)
((b'<idle>', 0, 1, b'd...', 5377.33901, b'120'), -0.4549946520000958)
((b'sshd', 45772, 1, b'd...', 5377.339155, b'120'), -0.455133453999224)
((b'<idle>', 0, 5, b'd...', 5377.346264, b'120'), -0.4622384320000492)
((b'rcu_sched', 11, 5, b'd...', 5377.346278, b'120'), -0.462244209000346)
((b'<idle>', 0, 14, b'd...', 5377.346296, b'120'), -0.4622557519996917)
((b'kworker/u32:4', 21613, 14, b'd...', 5377.346316, b'120'), -0.4622718830005397)
((b'<idle>', 0, 14, b'd...', 5377.346673, b'120'), -0.46262520700020104)

问题分析 #

1. trace_printk共享缓冲区溢出：bpf_trace_printk使用内核共享的trace buffer，当追踪事件量较大时，旧数据可能未被及时清理，后续读取时会获取到历史数据，导致时间戳跳变。这符合“首次运行正常、之后异常持续”的现象——首次运行缓冲区为空，后续残留的旧数据被重复读取。
2. 时间基准不匹配：b.trace_fields()返回的ts是内核启动后的时间偏移（ktime_get_boottime），而time.perf_counter()是当前进程启动后的时间，两者基准不同。若系统发生时间调整（如NTP同步、硬件时钟校准），会加剧两者的差值波动。
3. trace_fields的ts字段可靠性问题：bcc的trace_fields返回的时间戳可能存在缓冲区复用或基准重置的情况，尤其是在长时间追踪后。

修复建议 #

方案1：改用BPF_PERF_OUTPUT替代trace_printk #

这是最可靠的方案，避免共享缓冲区的溢出问题，同时可以自定义输出字段，包括更精确的时间戳。修改后的代码示例：

#!/usr/bin/python
import time
from bcc import BPF

# 定义输出数据结构
class EventData(BPF.get_table_struct(b"""
struct event {
    u32 prev_pid;
    u64 timestamp;
    char prev_comm[TASK_COMM_LEN];
    u32 cpu;
};
""")):
    pass

# 加载BPF程序
b = BPF(text="""
#include <uapi/linux/ptrace.h>
#include <linux/sched.h>

struct event {
    u32 prev_pid;
    u64 timestamp;
    char prev_comm[TASK_COMM_LEN];
    u32 cpu;
};

BPF_PERF_OUTPUT(events);

TRACEPOINT_PROBE(sched, sched_switch) {
    struct event e = {};
    e.prev_pid = args->prev_pid;
    e.timestamp = bpf_ktime_get_ns(); // 获取纳秒级内核时间戳
    bpf_get_current_comm(&e.prev_comm, sizeof(e.prev_comm));
    e.cpu = bpf_get_smp_processor_id();
    events.perf_submit(args, &e, sizeof(e));
    return 0;
}
""")

timeline = []
time_diffs = []
value_errors = 0

# 定义事件回调
def handle_event(cpu, data, size):
    event = EventData(data)
    # 转换内核时间戳为秒
    kernel_ts = event.timestamp / 1e9
    current_time = time.time()
    # 计算系统启动时间，统一基准
    boot_time = current_time - time.monotonic()
    # 内核ts是启动后的偏移，转换为wall time
    kernel_wall_time = boot_time + kernel_ts
    timeline.append((event.prev_comm.decode(), event.prev_pid, cpu, kernel_wall_time, event.prev_pid))
    time_diffs.append((kernel_wall_time, current_time - kernel_wall_time))

# 挂载回调
b["events"].open_perf_buffer(handle_event)

print("Started tracing...")
try:
    while True:
        b.perf_buffer_poll()
except KeyboardInterrupt:
    print("Finished tracing")
    # 保存数据
    with open("Data/time_diffs.txt", "w") as fl:
        fl.write("\n".join(str(x) for x in time_diffs))
    from data_process import tracing_data_process
    tracing_data_process(timeline)
    print("Processing done")
    exit()

方案2：验证并统一时间基准 #

如果坚持使用trace_printk，需要统一内核时间戳与用户空间时间的基准：

• 计算系统启动时间：boot_time = time.time() - time.monotonic()
• 内核返回的ts是启动后的秒数，转换为wall time：kernel_wall_time = boot_time + data[4]
• 对比用户空间time.time()与转换后的时间，避免使用perf_counter的进程基准时间。

方案3：清理trace buffer #

在程序启动时清理内核trace buffer，避免读取旧数据：

# 在加载BPF程序后添加
with open("/sys/kernel/debug/tracing/trace", "w") as f:
    f.write("")

补充说明 #

• 方案1是推荐的生产级方案，性能更稳定，数据更可靠，适合长时间追踪。
• 方案3为临时 workaround，仅能解决首次运行后的残留数据问题，无法彻底避免缓冲区溢出。

内容的提问来源于stack exchange，提问作者Jawand S.