如何使用 perf 分析 splice 中 pipe 的容量变化
这个文章为了填上一篇文章的坑的，跟踪内核函数本来是准备使用 ebpf 的，但是涉及到了低内核版本，只能使用 kprobe 了。
恰好，在搜索东西的时候又看到了 perf，可以使用 perf probe 来完成对内核函数的跟踪，使用相对写内核模块简单很多，对于排查问题如何能解决就应该尽量挑简单的方案，所以就它了。
提到 perf 那么 Brendan Gregg 是绕不过去的，这里对 perf 只记一些本文使用到的一些东西。
perf 的一些东西
需要先添加探测点，探测点可以通过 /proc/kallsyms 进行查询，以 splice_to_pipe 为例
perf probe --add 'splice_to_pipe'
# 如何系统内有 kernel-debuginfo 那么就可以直接检测变量的值
perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages'
在添加探测点后，进行记录。可以指定对应的 pid 和记录的时间 30s（等待的过程可以中断，并且不影响结果）
perf record -e 'probe:splice_to_pipe' -p $(pidof a.out) -gR sleep 30
# 也可以记录多个事件
perf record -e 'probe:tcp_splice_data_recv,probe:kill_fasync,probe:pipe_wait,probe:sock_spd_release,probe:splice_to_pipe' -p $(pidof a.out) -gR sleep 30
在完成记录后，将结果展示在命令行中
perf report --stdio
其它的可能用到的
# 查询已经添加过的探测点
perf probe --list
probe:splice_to_pipe (on splice_to_pipe@fs/splice.c with nrbufs buffers nr_pages)
probe:tcp_splice_data_recv (on tcp_splice_data_recv@net/ipv4/tcp.c with count len)
probe:tcp_splice_data_recv__return (on tcp_splice_data_recv%return@net/ipv4/tcp.c with arg1)
# 删除已添加的探测点，从 perf probe --list 中获取
perf probe --del probe:splice_to_pipe
# 查看准确的探测点（颜色区分）
perf probe -L splice_to_pipe
探测点要捕获变量，需要安装 kernel-debuginfo，Centos7.9 可以直接从阿里云下载，速度非常快（有的镜像源没有debuginfo，官方的速度太慢）
- https://mirrors.aliyun.com/centos-debuginfo/7/x86_64/kernel-debuginfo-$(uname -r).rpm
- https://mirrors.aliyun.com/centos-debuginfo/7/x86_64/kernel-debuginfo-common-x86_64-$(uname -r).rpm
问题背景
在数据在 24k 字节左右时，低版本内核 3.10.0 调用 splice 会被阻塞，但是在高版本内核 6.1 可以直接返回。
这个问题只需要对 3.10.0版本内核的 splice_to_pipe 做分析（6.1 不会被阻塞），确认 24k 字节数据下 skbuff 的 PAGE 数量
以及引出来的一个问题，调用 splice 只做 fd -> pipe 而不做 pipe -> fd，这个情况都会发生阻塞，但是阻塞触发的大小不相同
- 3.10.0 大概在 24k 字节就发生阻塞
- 6.1.0 大概 200k 字节才发生阻塞，远大于 65536
这个问题聚焦点在
- 3.10.0 下和上面那个问题相同，判断 PAGE 数量，是否大于了 pipe size
- 6.1.0 需要判断阻塞之前的两个点
- splice 入口的 wait_for_space 是否满足
- splice_to_pipe 判断 PAGE 数量，观察挂载了几个页的数据
分析
问题在 3.10.0 的内核上体现明显，先对 3.10.0 进行分析。
本机环境
- 宿主机 Debian12 (6.1.0-10-amd64), CPU i7-12700
- 虚拟机 CentOS7.9 (3.10.0-1160.62.1.el7.x86_64)
- QEMU 7.2.4 virt-io
分析 splice 3.10.0内核上阻塞的情况
先对 3.10.0内核入手，大概分析一下 splice_to_pipe 的源码
// fs/splice.c splice_to_pipe
186 ssize_t splice_to_pipe(struct pipe_inode_info *pipe,
187 struct splice_pipe_desc *spd)
188 {
198 for (;;) {
206 if (pipe->nrbufs < pipe->buffers) {
218 pipe->nrbufs++;
219 page_nr++;
220 ret += buf->len;
221
222 if (pipe->files)
223 do_wakeup = 1;
224
225 if (!--spd->nr_pages)
226 break;
227 if (pipe->nrbufs < pipe->buffers)
228 continue;
229
230 break;
231 }
232
233 if (spd->flags & SPLICE_F_NONBLOCK) {
234 if (!ret)
235 ret = -EAGAIN;
236 break;
237 }
244
245 if (do_wakeup) {
246 smp_mb();
247 if (waitqueue_active(&pipe->wait))
248 wake_up_interruptible_sync(&pipe->wait);
249 kill_fasync(&pipe->fasync_readers, SIGIO, POLL_IN);
250 do_wakeup = 0;
251 }
252
253 pipe->waiting_writers++;
254 pipe_wait(pipe);
255 pipe->waiting_writers--;
256 }
257
260 if (do_wakeup)
261 wakeup_pipe_readers(pipe);
262
263 while (page_nr < spd_pages)
264 spd->spd_release(spd, page_nr++);
265
266 return ret;
267 }
之前是怀疑 if (pipe->nrbufs < pipe->buffers) 不满足而又不满足 if (spd->flags & SPLICE_F_NONBLOCK)，在 pipe_wait(pipe) 中被阻塞。
所以要看的就是
- pipe->nrbufs, pipe 中已使用的 buffer 数量
- pipe->buffers, pipe 中总的 buffer 数量
- spd->nr_pages, socket 中读取出来数据页的数量
perf 追踪单次 splice 24k 字节数据的调用情况
调整测试数据的大小，生成 24k 字节的数据
$ dd if=/dev/zero of=/tmp/1.txt bs=1k count=24
$ ncat -nv 192.168.32.245 10022 < /tmp/1.txt
开始 perf 记录
[root@localhost ~]# perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages'
Added new event:
probe:splice_to_pipe (on splice_to_pipe with nrbufs=pipe->nrbufs buffers=pipe->buffers nr_pages=spd->nr_pages)
[root@localhost ~]# perf record -e 'probe:splice_to_pipe' -p $(pidof a.out) -gR sleep 30
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.017 MB perf.data (1 samples) ]
[root@localhost ~]# perf report --stdio
# Samples: 2 of event 'probe:splice_to_pipe'
# Event count (approx.): 2
# Children Self Trace output
# ........ ........ ......................................................
50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=17
...
50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2
通过 perf 观察到 splice_to_pipe 调用了两次，从 nrbufs 看第一次调用后 pipe 就没有空间了，再看一次代码，第一次调用在在 fs/splice.c L230 返回，没有执行后续的逻辑。
// fs/splice.c splice_to_pipe
227 if (pipe->nrbufs < pipe->buffers)
228 continue;
229
230 break;
并且在 fs/splice.c L263 这里 while (page_nr < spd_pages) 这个条件是满足的，我们完整的追踪一下这个调用的链路，主要跟踪可能出现循环的逻辑，包括 tcp_read_sock, tcp_splice_data_recv, sock_spd_release 以及阻塞的逻辑 pull_wait
---splice
system_call_fastpath
sys_splice
do_splice_to
sock_splice_read
tcp_splice_read
tcp_read_sock
tcp_splice_data_recv
skb_splice_bits
skb_socket_splice
splice_to_pipe
kill_fasync
通过增加观测点来进行验证，
perf probe --add 'tcp_read_sock desc->count'
perf probe --add 'tcp_read_sock%return $retval'
perf probe --add 'tcp_splice_data_recv rd_desc->count len offset'
perf probe --add 'tcp_splice_data_recv%return $retval'
perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages pipe->files pipe->waiting_writers pipe->readers'
perf probe --add 'splice_to_pipe%return $retval'
perf probe --add 'pipe_wait pipe->nrbufs pipe->buffers pipe->files pipe->waiting_writers pipe->readers'
perf probe --add 'sock_spd_release spd->nr_pages i'
perf record -e "$(perf probe --list | awk '{print $1}' | sed ':a;N;$!ba;s/\n/,/g')" -p $(pidof a.out) -gR sleep 30
输出结果为:
# Samples: 1 of event 'probe:pipe_wait'
# Children Self Trace output
# ........ ........ .....................................................................................
100.00% 100.00% (ffffffffa9a57760) nrbufs=0x10 buffers=0x10 files=0x2 waiting_writers=0x1 readers=0x1
# Samples: 1 of event 'probe:sock_spd_release'
# Children Self Trace output
# ........ ........ ....................................
100.00% 100.00% (ffffffffa9e418a0) nr_pages=1 i=0x10
# Samples: 2 of event 'probe:splice_to_pipe'
# Children Self Trace output
# ........ ........ ................................................................................................
50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=17 files=0x2 waiting_writers=0x0 readers=0x1
50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2 files=0x2 waiting_writers=0x0 readers=0x1
# Samples: 1 of event 'probe:tcp_read_sock'
# Children Self Trace output
# ........ ........ .................................
100.00% 100.00% (ffffffffa9eb2e50) count=0x100000
# Samples: 2 of event 'probe:tcp_splice_data_recv'
# Children Self Trace output
# ........ ........ ........................................................
50.00% 50.00% (ffffffffa9eb2a10) count=0x100000 len=0x6000 offset=0x0
50.00% 50.00% (ffffffffa9eb2a10) count=0xfa770 len=0x770 offset=0x5890
# Samples: 1 of event 'probe:splice_to_pipe__return'
# Children Self Trace output
# ........ ........ ..................................................
100.00% 100.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x5890
# Samples: 0 of event 'probe:tcp_read_sock__return'
# Children Self Trace output
# ........ ........ ............
# Samples: 1 of event 'probe:tcp_splice_data_recv__return'
# Children Self Trace output
# ........ ........ ..................................................
100.00% 100.00% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x5890
通过测试结果分析代码
splice_to_pipe
splice_to_pipe 被调用两次，返回（splice_to_pipe__return）一次，poll_wait 调用一次，sock_spd_release 调用一次
-
第一次调用的时候在 fs/splice.c L230 返回，没有进入 poll_wait 逻辑，但是由于数据没有全部写入 pipe 中，fs/splice.c L263 while (page_nr < spd_pages) 被调用，观察 nr_pages=1 i=0x10 到写入了 16 页，剩余 1 页。观察 tcp_splice_data_recv__return 写入 pipe 的数据为 0x5890.
-
然后出现了第二次调用，由于没有空间（观察 nrbufs=0x10 buffers=0x10）再进行写入 fs/splice.c 206 if (pipe->nrbufs < pipe->buffers) 条件不满足，直接进入了阻塞逻辑 pull_wait.
-
第二次调用是第一次剩余的页数，重试导致阻塞，观察代码发现只要写入数据至 pipe 中，就会跳出循环不进入阻塞中
225 if (!--spd->nr_pages) 226 break; 227 if (pipe->nrbufs < pipe->buffers) 228 continue; 230 break;
tcp_splice_data_recv
tcp_splice_data_recv 出现在 tcp_read_sock 的循环中，我们对其调用参数进行分析。
// net/ipv4/tcp.c tcp_splice_data_recv
634 static int tcp_splice_data_recv(read_descriptor_t *rd_desc, struct sk_buff *skb,
635 unsigned int offset, size_t len)
636 {
637 struct tcp_splice_state *tss = rd_desc->arg.data;
638 int ret;
639
640 ret = skb_splice_bits(skb, offset, tss->pipe, min(rd_desc->count, len),
641 tss->flags);
642 if (ret > 0)
643 rd_desc->count -= ret;
644 return ret;
645 }
// net/ipv4/tcp.c tcp_read_sock
1458 int tcp_read_sock(struct sock *sk, read_descriptor_t *desc,
1459 sk_read_actor_t recv_actor)
1460 {
1469 while ((skb = tcp_recv_skb(sk, seq, &offset)) != NULL) {
1470 if (offset < skb->len) {
1471 int used;
1472 size_t len;
1473
1474 len = skb->len - offset;
1475 /* Stop reading if we hit a patch of urgent data */
1476 if (tp->urg_data) {
1477 u32 urg_offset = tp->urg_seq - seq;
1478 if (urg_offset < len)
1479 len = urg_offset;
1480 if (!len)
1481 break;
1482 }
1483 used = recv_actor(desc, skb, offset, len);
1484 if (used <= 0) {
1485 if (!copied)
1486 copied = used;
1487 break;
1488 } else if (used <= len) {
1489 seq += used;
1490 copied += used;
1491 offset += used;
1492 }
// 50.00% 50.00% (ffffffffa9eb2a10) count=0x100000 len=0x6000 offset=0x0
// 50.00% 50.00% (ffffffffa9eb2a10) count=0xfa770 len=0x770 offset=0x5890
第一次调用为 count 为 0x100000，是 splice 的 max 参数，从套接字读出来的字节为 0x6000，一次性从套接字把数据读完了，写入 pipe 的长度为 0x5890，剩余 0x770。
看起来第二次调用 splice 的情况下，0x770 的数据占用了两个 PAGE（nr_pages=2）
看起来是 tcp_recv_skb 从套接字读取的数据没有把每个 PAGE 占满，24576 字节的数据占用 PAGE 数量为 18，直接写入 pipe 就发生了阻塞。
perf 追踪多次 splice 4k 字节数据的调用情况
这种情况的阻塞是正常的，是为了观测 splice 持续可以写多少数据至 pipe 中
测试数据量保持不变，修改 splice 最大的长度为 4096，并且不再从 pipe 消费数据。得到的结果如下
ssize_t n = splice(fd, NULL, pipefd, NULL, 1<<20, 0);
调整为 ->
ssize_t n = splice(fd, NULL, pipefd, NULL, 1<<12, 0);
ssize_t n = splice_pump(pipefd[0], dstfd, in_pipe);
if (n > 0) {
remain -= n;
written += n;
}
调整为 ->
// ssize_t n = splice_pump(pipefd[0], dstfd, in_pipe);
// if (n > 0) {
// remain -= n;
// written += n;
// }
使用 perf 跟踪得到的结果如下：
[root@localhost ~]# perf report --stdio
# Samples: 1 of event 'probe:pipe_wait'
# Children Self Trace output
# ........ ........ .....................................................................................
100.00% 100.00% (ffffffffa9a57760) nrbufs=0x10 buffers=0x10 files=0x2 waiting_writers=0x1 readers=0x1
# Samples: 2 of event 'probe:sock_spd_release'
# Children Self Trace output
# ........ ........ ...................................
50.00% 50.00% (ffffffffa9e418a0) nr_pages=2 i=0x2
50.00% 50.00% (ffffffffa9e418a0) nr_pages=2 i=0x3
# Samples: 6 of event 'probe:splice_to_pipe'
# Children Self Trace output
# ........ ........ ................................................................................................
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=3 files=0x2 waiting_writers=0x0 readers=0x1
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2 files=0x2 waiting_writers=0x0 readers=0x1
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x3 buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x7 buffers=0x10 nr_pages=3 files=0x2 waiting_writers=0x0 readers=0x1
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0xa buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
16.67% 16.67% (ffffffffa9a811e0) nrbufs=0xe buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
# Samples: 5 of event 'probe:tcp_read_sock'
# Children Self Trace output
# ........ ........ ...............................
100.00% 100.00% (ffffffffa9eb2e50) count=0x1000
# Samples: 10 of event 'probe:tcp_splice_data_recv'
# Children Self Trace output
# ........ ........ ........................................................
10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x2000 offset=0x4000
10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x3000 offset=0x3000
10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x4000 offset=0x2000
10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x5000 offset=0x1000
10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x2000 offset=0x4000
10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x3000 offset=0x3000
10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x4000 offset=0x2000
10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x5000 offset=0x1000
10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x6000 offset=0x0
10.00% 10.00% (ffffffffa9eb2a10) count=0x868 len=0x1868 offset=0x4798
# Samples: 5 of event 'probe:splice_to_pipe__return'
# Children Self Trace output
# ........ ........ ..................................................
80.00% 80.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x1000
20.00% 20.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x798
# Samples: 4 of event 'probe:tcp_read_sock__return'
# Children Self Trace output
# ........ ........ ..................................................
100.00% 100.00% (ffffffffa9eb2e50 <- ffffffffa9eb3128) arg1=0x1000
# Samples: 9 of event 'probe:tcp_splice_data_recv__return'
# Children Self Trace output
# ........ ........ ..................................................
44.44% 44.44% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x0
44.44% 44.44% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x1000
11.11% 11.11% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x798
总共 24k 的数据，splice 被调用了5次，4次返回，阻塞了1次。观察 pipe 的变化，同样是最后 nrbufs=0x10 buffers=0x10 nr_pages=2 pipe 已满导致被阻塞，PAGE 数量也是 18.
自顶向下分析的话，每次调用 splice 会调用一次 tcp_read_sock，然后调用两次 tcp_splice_data_recv（观察 probe:tcp_splice_data_recv__return 和 probe:tcp_splice_data_recv 里面 count 的变化），最后一次在 net/ipv4/tcp.c L1487 之前就被阻塞了。
// net/ipv4/tcp.c tcp_read_sock
1484 if (used <= 0) {
1485 if (!copied)
1486 copied = used;
1487 break;
结论
3.10.0 在数据远小于 65536 的情况下被阻塞的原因就是 tcp_read_sock 用于读取数据的页没有写满 4096 字节，导致占用的页数大于 pipe 的容量（16）。
TODO
由于 debian12 没有找到对应的 debuginfo（ubuntu 的 dbgsyms），这里再挖个坑，后面准备用 fedora39 再跟踪一波
参考
- https://www.brendangregg.com/perf.html, perf Examples
- https://mirrors.aliyun.com/centos-debuginfo, 阿里云开源镜像站
- https://www.cnblogs.com/shuqin/p/18031269, 记一次 splice 导致 io.Copy 阻塞的排查过程