# 案例三：模式 2 Debug 版（-O0）perf stat 深度解读

> 本文档的核心转折点。前面 [案例一](/concepts/tools/perf-case-studies/01-mode1-o0-baseline.md) 建立了理想对照组，[案例二](/concepts/tools/perf-case-studies/02-mode1-o2-comparison.md) 展示了 O2 优化效果。本节将揭示：**同样的 `-O0` 构建、同样的 3 秒采样，模式 2 的 `:u` 数据竟然和模式 1 O2 一模一样**——这就是 `:u` 陷阱的起点。读完本节后，[案例四](/concepts/tools/perf-case-studies/04-mode2-o2-u-trap.md) 用实测验证预测，[案例五](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 用 `:u`+`:k` 完整视角揭开真相。

前两节都盯着"模式 1(纯 user 计算)"看。本节切到"模式 2(疯狂 syscall)"——表面看 perf 数字非常反常:**和模式 1 O2 几乎一模一样**。但反常背后是一个**所有 syscall-heavy 程序的必修知识点**——`perf` 的 `:u` 后缀只统计 user 模式,内核的真实成本被完全藏起来了。

## 3.1 场景:模式 2 跑的是什么

`demos/cpu-demo/main.cpp` 选了选项 `2` 之后,后台线程会进入 `busy_kernel_cpu()`:

```cpp
// 场景 2:内核态高 CPU(频繁系统调用,消耗 stime)
void busy_kernel_cpu() {
    std::string tmp_file = "/tmp/test_kernel_io.tmp";
    while (true) {
        // 频繁打开关闭文件,触发 open/write/close 系统调用
        std::ofstream f(tmp_file, std::ios::app);
        f.write("hello\n", 6);
        f.close();
    }
}
```

特征关键词:
- **每次循环 3 个 syscall**:`open()`(可能伴随 `stat` / `fstat`) + `write()` + `close()` → **用户态几乎无事可做,内核态疯狂**;
- **追加写模式**:`O_APPEND` 让 `write()` 在内核里做"读 offset → 加 len → 写回 offset → 拷数据"四步;
- **标准库包装**:`std::ofstream` 的实现是 libstdc++ 编译期 `-O2`,但**用户代码本身的 `f.write/f.close` 包装逻辑仍由 `-O0` 编译**;
- **永不阻塞**:`/tmp` 一般是 tmpfs(内存文件系统),`write()` 同步进 page cache 就返回,**不会触发 IO 等待**,所以 0 context-switches 是合理的。

## 3.2 原始 perf stat 输出

```text
[czhuo@shrdlab31 perf]$ perf stat -p 10589 -- sleep 3
 Performance counter stats for process id '10589':
     2,971.42 msec task-clock:u          #    0.990 CPUs utilized
             0      context-switches:u    #    0.000 K/sec
             0      cpu-migrations:u      #    0.000 K/sec
             0      page-faults:u         #    0.000 K/sec
   2,520,068,314      cycles:u           #    0.848 GHz
    4,248,326,349      instructions:u     #    1.69  insn per cycle
      944,800,535      branches:u         #  317.963 M/sec
        266,143      branch-misses:u       #    0.03% of all branches
       3.002539028 seconds time elapsed
```

## 3.3 第一个反直觉点:它跟模式 1 O2 几乎一模一样

把三组数据并列:

| 指标 | 模式 1 (-O0) | 模式 1 (-O2) | **模式 2 (-O0)** |
|------|---------------|----------------|--------------------|
| task-clock (ms) | 3,024.12 | 2,997.61 | 2,971.42 |
| CPUs utilized | 1.004 | 0.990 | 0.990 |
| context-switches | 0 | 0 | 0 |
| cpu-migrations | 0 | 0 | 0 |
| page-faults | 0 | 0 | 0 |
| **cycles** | 12,047,315,514 | 2,546,077,721 | **2,520,068,314** |
| **CPU 频率** | 3.984 GHz | 0.849 GHz | **0.848 GHz** |
| **instructions** | 7,340,204,487 | 4,272,852,608 | 4,248,326,349 |
| **IPC** | 0.61 | 1.68 | **1.69** |
| **branches** | 2,446,709,897 | 953,529,848 | 944,800,535 |
| branch-misses | 4,455 | 21,772 | **266,143** |
| branch-misses % | 0.00018% | 0.00228% | **0.02817%** |

**模式 2 O0 vs 模式 1 O2:几乎 100% 雷同**。cycles / instructions / IPC / branches / CPU 频率全部相差不到 2%。

这合理吗?**不合理**——模式 2 在做"每秒几千次 open/write/close 系统调用",按理说它应该比模式 1 O2(纯计算空转)耗 CPU 得多。**真正的解释:perf 的 `:u` 后缀把所有内核态 cycles / instructions 全部屏蔽了。**

## 3.4 关键解读:`:u` 后缀的真相

`perf stat` 默认输出的所有数字都带 `:u` 后缀,这意味着**只统计 user 模式(Ring 3)的事件**,kernel 模式(Ring 0)的事件**不计入**。

| 指标 | `:u` 含义 | 模式 2 实际发生了什么 |
|------|------------|-----------------------|
| `cycles:u` | 仅 Ring 3 的 CPU 周期 | 用户态只跑了"设置 syscall 参数 + `syscall` 指令 + 处理返回值",**真实周期数被漏算** |
| `instructions:u` | 仅 Ring 3 退役指令 | 同上,只数到 ofstream 包装函数的指令 |
| `branches:u` | 仅 Ring 3 分支 | 同上,内核里 VFS 的 `if (IS_ERR(inode))` 等等分支**完全没记** |
| `task-clock:u` | 仅 Ring 3 计时 | 这是 `:u` 唯一仍能反映"进程被调度时间"的指标,所以 2,971 ms / 3.0 s = 0.99 CPUs 还算真实 |

> **类比**:你拿温度计量湖水表面温度,测出 5°C 就断言"湖水很冷"——但湖底可能有 90°C 的热泉。**`:u` 是湖面温度计,要测内核的真实消耗必须加 `:k` 或去掉后缀。**

## 3.5 重新采集:同时看 user + kernel 的真实画面

去掉 `:u`,或者并列看 `:u` + `:k`:

```bash
# 命令 1:同时统计 user 和 kernel 模式
perf stat -e cycles:u,cycles:k,instructions:u,instructions:k \
          -p 46147 -- sleep 3
# 命令 2:完全不区分模式(看总 cycles)
perf stat -e cycles,instructions,branches \
          -p 46147 -- sleep 3
# 命令 3:用 tracepoint 专门看 syscall 次数
sudo perf stat -e syscalls:sys_enter_openat,syscalls:sys_enter_write,syscalls:sys_enter_close \
               -p 46147 -- sleep 3
```

**实际数据**(PID 46147,3 秒采样窗口):

**命令 2 实测输出**(无 `:u`/`:k` 过滤,perf 默认对硬件 PMU 事件带 `:u`):

```text
[czhuo@shrdlab31 ~]$ perf stat -e cycles,instructions,branches -p 46147 -- sleep 3
 Performance counter stats for process id '46147':
     2,804,912,054      cycles:u
     4,164,607,998      instructions:u     #    1.48  insn per cycle
       926,182,901      branches:u
       3.028519909 seconds time elapsed
```

**命令 3 实测输出**(syscall tracepoint 计数,需 sudo):

```text
[czhuo@shrdlab31 ~]$ sudo perf stat -e syscalls:sys_enter_openat,syscalls:sys_enter_write,syscalls:sys_enter_close -p 46147 -- sleep 3
 Performance counter stats for process id '46147':
                  0      syscalls:sys_enter_openat
            816,314      syscalls:sys_enter_write
            816,309      syscalls:sys_enter_close
       3.001754696 seconds time elapsed
```

### 数据解读

| 指标 | 命令 2 显示 | 命令 3 真实数 | 与 §3.2 PID 10589 对比 |
|------|-----------|--------------|------------------------|
| cycles:u | 2.80 G | — | 略高于 2.52 G(机器负载波动) |
| instructions:u | 4.16 G | — | 略低于 4.25 G(基本一致) |
| branches:u | 926 M | — | 略低于 944 M(基本一致) |
| IPC | 1.48 | — | 略低于 1.69(本次运行略低) |
| `openat` | (隐藏) | **0** | **意外!按代码逻辑应为 ~81.6 万次** |
| `write` | (隐藏) | **816,314** | 与 §3.2 推测的 ~1M 接近 |
| `close` | (隐藏) | **816,309** | 与 write 几乎一一对应 |

**意外发现 ①:0 次 `openat`,但代码每次循环都构造 ofstream 并 open**

理论上 `std::ofstream f(tmp_file, std::ios::app)` 每次都应触发 `sys_openat`,但 tracepoint 记录 0 次。三个可能:

1. **glibc 缓存优化**:glibc 的 `fopen()` 在反复打开同一路径时,**复用底层 file descriptor**——只做 dup 而不是真正的 openat syscall。这是较新 glibc 版本(2.31+)的优化行为,可以通过 `strace -e openat -p <pid>` 验证。
2. **libstdc++ 的 ofstream 缓存**:某些 libstdc++ 版本对相同 path + flag 的 open 做内部 cache,只对第一次的 `fopen()` 真正发 syscall。
3. **tracepoint 未安装**:`syscalls:sys_enter_openat` 在某些内核/配置下需要单独 enable——`sudo perf trace --event syscalls:sys_enter_openat` 验证。

无论哪种情况,**`write` 和 `close` 的 tracepoint 都正常记录,说明 tracepoint 机制本身工作**。进一步分析见 [案例五 §5.5](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 的 `strace -c` 实测。

**意外发现 ②:`write` 与 `close` 几乎一一对应(816,314 vs 816,309)**

每写 1 次就关 1 次文件——完全符合 `f.write(); f.close();` 的代码逻辑。差 5 次属于 tracepoint 采样边界误差,可忽略。**这说明模式 2 的真实内核工作量集中在 write/close 这两次 syscall 上**,而不是 §3.1 推测的"open + write + close"三次。

### 推算 kernel 真实成本

按 write/close 每次 5,000 ~ 15,000 cycles 估算:

```bash
每秒 272,105 次 write + 272,103 次 close ≈ 544,208 次 syscall/秒
× 10,000 cycles/syscall(中位数)
= 5.44 G cycles/秒(内核侧)
× 3 秒
= 16.3 G kernel cycles
```

**估算的 kernel cycles ~16 G,是 user 态 2.8 G 的 5 ~ 6 倍**——这部分是 perf `:u` 完全看不到的"被隐藏成本"。完整定量验证见 [案例五](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 的 `cycles:k` 实测。

### 下一步:运行命令 1 拿到 cycles:k 硬数据

当前 :u + tracepoint 只能看到"用户态干 2.8G cycles、写 81.6 万次 write/close"——**还缺关键的 cycles:k 数字**。要看到 kernel 真实成本,必须运行命令 1:

```bash
perf stat -e cycles:u,cycles:k,instructions:u,instructions:k -p 46147 -- sleep 3
```

完整 `:u` + `:k` 数据将在 [案例五](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 中给出。

## 3.6 模式 2 四个"看似 0 但其实隐藏"的事件

### 3.6.1 context-switches:u = 0(对,模式 2 真的没切换)

| 现象 | 解释 |
|------|------|
| 频繁 syscall 不等于 context-switch | `open/write/close` 在 tmpfs / page cache 上是**非阻塞**的,内核处理完直接 `sysret` 回到用户态,**不换进程** |
| task-clock 仍是 2,971 ms | 因为 `task-clock:u` 还是把"用户在 CPU 上跑的总时间"算上了,syscall 进入内核那段时间算 user 还是 kernel 有歧义,但 perf 通常**整段时间算 user** |
| 与模式 1 O0 对比 | 模式 1 O0 也是 0 context-switches,两者机制相同——单任务 + 不阻塞 |

### 3.6.2 page-faults:u = 0(也对,写 tmpfs 不触发 user fault)

| 现象 | 解释 |
|------|------|
| 写 `/tmp` 不触发 user fault | tmpfs 用 page cache,内核分配 page 给 page cache 是**内核内部 kmalloc**,不映射到 user 虚地址空间,user 看不到 page fault |
| 0 page-faults 跟 syscall 数量无关 | 即使每秒 1M 次 `write`,只要 `write` 的 buffer 是已映射的栈/堆,就不 fault |
| 怎么才会 non-zero | 让 `f.write(buf, sz)` 中的 `buf` 指向尚未映射的 mmap 区域,或 `read` 一个未缓存的大文件 |

### 3.6.3 branch-misses = 0.03%(模式 2 唯一一个"高"一点的指标)

| 项 | 模式 1 O0 | 模式 1 O2 | **模式 2 O0** |
|----|-----------|-----------|---------------|
| 绝对 miss 数 | 4,455 | 21,772 | **266,143** |
| miss 率 % | 0.00018% | 0.00228% | **0.02817%** |

**0.03% 看着很低,但比模式 1 高了 12 ~ 150 倍**。原因:

1. **syscall 返回路径有条件分支**:`if (ret < 0) { errno = -ret; throw; }`,`close()` 返回值有 `if (ret == -EINTR)` 等检查;
2. **glibc syscall 包装函数的间接跳转**:`syscall(SYS_openat, ...)` 内部通过 `syscall` 指令,再回到 `__openat` 走 `__openat_2` 路径,**函数指针调用**是预测器较难猜的;
3. **std::ofstream 析构里有 if 分支**:`~ofstream()` 调用 `close()`,里面有"是否已 close 过"的判断,预测器要学着这个状态机。

> 即便如此,0.03% 离"分支预测瓶颈"还差两个数量级。模式 2 的真实瓶颈**不在 branch prediction**,而在 syscall 本身的 kernel 路径开销。

### 3.6.4 CPU 频率 = 0.85 GHz(为啥 syscall 风暴下还能降频?)

直觉:每秒上千次 syscall,CPU 一定全速跑。
实际:**用户态角度确实"很闲"**。每次 syscall 之间的用户态代码只有几十条指令,内核态忙完 sysret 回来,用户态很快又触发下一次 `syscall`。**从 CPU 的 P-state governor 视角看,"用户态执行时间"很短,所以它把频率降到 0.85 GHz;但每次降频的窗口很短,syscall 风暴的吞吐靠"快速进内核-快速出内核"维持,不需要高频**。

## 3.7 PlantUML:模式 2 一次循环的 user↔kernel 切换

```plantuml
@startuml
skinparam shadowing false
skinparam sequence {
  ArrowColor #1976D2
  LifeLineBorderColor #1976D2
}
participant "用户态\n(ofstream 代码, -O0)" as U #E3F2FD
participant "libstdc++\n(预编译 -O2)" as L #FFF3E0
participant "内核 Ring 0\nVFS / page cache" as K #FFEBEE
participant "perf counter\n:u 只看这里" as P #E8F5E9
U -> U : while(true) {\n构造 ofstream f
U -> L : f.open("/tmp/.../tmp", O_APPEND)
L -> K : syscall(SYS_openat, ...)
K -> K : link_path_walk\ninode lookup\nfile struct alloc
K --> L : 返回 fd
L --> U : f 持有 fd
U -> L : f.write("hello\\n", 6)
L -> K : syscall(SYS_write, fd, buf, 6)
K -> K : tmpfs 写 page cache\n更新 inode->i_size
K --> L : 返回 6
L --> U : write 完毕
U -> L : f.close()
L -> K : syscall(SYS_close, fd)
K -> K : filp_close\n释放 file struct
K --> L : 返回 0
L --> U : close 完毕
U -> P : 在 user 态消耗的\ncycles / instructions\n**全部在这里** → 被记录
note right of P
  :u 后缀只数 user 态
  kernel 态的 cycles / instructions
  完全漏掉
  → 必须用 cycles:k 或
    取消后缀才能看到真实成本
end note
@enduml
```

## 3.8 模式 2 真实瓶颈:为什么它"很慢"perf 却看不出

| 维度 | `:u` 显示 | 实际发生了什么 |
|------|-----------|----------------|
| **用户态 IPC** | 1.69(很高效) | 用户态代码确实高效,只有"包装+触发 syscall"的轻量活 |
| **用户态 cycles** | 2.5 G(很少) | 同样的原因——用户态无事可做 |
| **内核态 cycles** | (隐藏) | **这里是真正的瓶颈**:`do_sys_open → do_filp_open → path_openat → ...` 一条 syscall 在内核跑 ~ 5,000 ~15,000 周期 |
| **每秒 syscall 数** | (隐藏) | **真实吞吐指标**,应该用 `perf stat -e syscalls:sys_enter_*` 看 |
| **CPU 频率** | 0.85 GHz | 反映 user 闲,kernel 忙但 P-state 看不到 |

**核心 takeaway**:**模式 2 的真实成本是"内核里跑的 VFS / page cache 路径",而不是"用户态循环"**。要分析这种程序:
- **必须用 tracepoint**:`syscalls:sys_enter_openat`、`syscalls:sys_enter_write` 等
- **必须看 :k 模式**:`cycles:k`、`instructions:k` 才是真实工作量
- **必须配 `perf record -g` + `caller`**:用 call graph 看到 `__open64 → do_sys_open → ...` 整条内核调用链
- **考虑 `strace -c -p <pid>`** 一次性看每个 syscall 的次数、平均耗时、错误率

## 3.9 实操:把"模式 2"这个反例变成教学样本

按以下顺序操作,把"`:u` 陷阱"刻进肌肉记忆:

```bash
# 1) 起进程:make && ./cpu_demo,选 2
./cpu_demo   # 输入 2,记下 PID,比如 10589
# 2) 看 :u 视角(本次实验数据)
perf stat -p 10589 -- sleep 3
# → 数字看着很正常,IPC 1.69,cycles 2.5G
# → 容易误以为"程序很高效"
# 3) 看完整视角
perf stat -e cycles:u,cycles:k,instructions:u,instructions:k \
          -p 10589 -- sleep 3
# → cycles:k 比 cycles:u 大 2~5 倍 → 真相暴露
# 4) 看 syscall 次数
perf stat -e syscalls:sys_enter_openat,syscalls:sys_enter_write,syscalls:sys_enter_close \
          -p 10589 -- sleep 3
# → 看到每秒几千次 open/write/close
# 5) 用 strace 看每个 syscall 耗时分布
strace -c -p 10589   # Ctrl+C 退出
# → 看到 open/write/close 各调了多少次,平均多少微秒
# 6) 用 perf record 看内核调用链
perf record -g -p 10589 -- sleep 3
perf report --sort=dso,symbol
# → 大头在 [kernel.kallsyms] 里的 do_sys_open / vfs_write / filp_close
```

## 3.10 与模式 1 的横向对比(本节核心 takeaway 表)

> **本节结论依赖 [案例一](/concepts/tools/perf-case-studies/01-mode1-o0-baseline.md) 和 [案例二](/concepts/tools/perf-case-studies/02-mode1-o2-comparison.md) 的对照组数据**，下表中的模式 2 O2 预期将在 [案例四](/concepts/tools/perf-case-studies/04-mode2-o2-u-trap.md) 中用实测验证，完整视角（`:u`+`:k`）将在 [案例五](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 中揭开真相。

| 维度 | 模式 1 O0 | 模式 1 O2 | **模式 2 O0** | 模式 2 O2(预期) |
|------|-----------|-----------|---------------|------------------|
| 真实工作在哪 | user 循环体 | user 循环体(更少) | **kernel VFS 路径** | kernel VFS 路径(同样) |
| 优化主要收益方 | n/a | **编译器** DCE / 寄存器化 | **标准库 + 内核** cache命中 | 同 |
| perf `:u` 数据 | 12G cycles / IPC 0.61 | 2.5G cycles / IPC 1.68 | 2.5G cycles / IPC 1.69 | 类似 模式 2 O0 |
| perf `:k` 数据 | 几乎为 0(纯 user) | 几乎为 0 | **>10G cycles** | 类似 |
| 真实总 cycles | ~12G | ~2.5G | **~12G** | ~12G |
| 看真实成本的方法 | 直接看 cycles:u | 直接看 cycles:u | **必须看 cycles:k + syscall tracepoint** | 同 |
| CPU 频率 | 3.98 GHz(跑满) | 0.85 GHz(降频) | 0.85 GHz(user 闲) | 类似 |

## 3.11 一句话总结

> **模式 2 看似跟模式 1 O2 perf 数字一模一样(cycles 2.5G、IPC 1.69、CPU 0.85 GHz),但这是 `:u` 后缀造成的"假象"——它屏蔽了 syscall 在内核里跑的 ~10G 真实 cycles;模式 2 的真实瓶颈在 `do_sys_open / vfs_write / filp_close` 这条内核 VFS 路径,必须用 `cycles:k`、`syscalls:sys_enter_*` tracepoint 或 `strace -c` 才能看到;这次实验最重要的教训是:**永远不要用 `cycles:u` 评估 syscall-heavy 程序的性能,那只是湖面温度计**。**

> **后续阅读**：本节结论仍为理论推断。下一节 [案例四](/concepts/tools/perf-case-studies/04-mode2-o2-u-trap.md) 将用实测数据验证"模式 2 O2 也会是这个样子"的预测，而 [案例五](/concepts/tools/perf-case-studies/05-mode2-o0-full-view.md) 和 [案例六](/concepts/tools/perf-case-studies/06-mode2-o2-full-view.md) 将用 `:u`+`:k` 完整视角给出定量验证。