经验首页 前端设计 程序设计 Java相关 移动开发 数据库/运维 软件/图像 大数据/云计算 其他经验
当前位置:技术经验 » 数据库/运维 » Kubernetes » 查看文章
如何使用 perf 分析 splice 中 pipe 的容量变化
来源:cnblogs  作者:小胖西瓜  时间:2024/3/1 8:42:47  对本文有异议

如何使用 perf 分析 splice 中 pipe 的容量变化

这个文章为了填上一篇文章的坑的,跟踪内核函数本来是准备使用 ebpf 的,但是涉及到了低内核版本,只能使用 kprobe 了。

恰好,在搜索东西的时候又看到了 perf,可以使用 perf probe 来完成对内核函数的跟踪,使用相对写内核模块简单很多,对于排查问题如何能解决就应该尽量挑简单的方案,所以就它了。

提到 perf 那么 Brendan Gregg 是绕不过去的,这里对 perf 只记一些本文使用到的一些东西。

perf 的一些东西

需要先添加探测点,探测点可以通过 /proc/kallsyms 进行查询,以 splice_to_pipe 为例

  1. perf probe --add 'splice_to_pipe'
  2. # 如何系统内有 kernel-debuginfo 那么就可以直接检测变量的值
  3. perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages'

在添加探测点后,进行记录。可以指定对应的 pid 和记录的时间 30s(等待的过程可以中断,并且不影响结果)

  1. perf record -e 'probe:splice_to_pipe' -p $(pidof a.out) -gR sleep 30
  2. # 也可以记录多个事件
  3. 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

在完成记录后,将结果展示在命令行中

  1. perf report --stdio

其它的可能用到的

  1. # 查询已经添加过的探测点
  2. perf probe --list
  3. probe:splice_to_pipe (on splice_to_pipe@fs/splice.c with nrbufs buffers nr_pages)
  4. probe:tcp_splice_data_recv (on tcp_splice_data_recv@net/ipv4/tcp.c with count len)
  5. probe:tcp_splice_data_recv__return (on tcp_splice_data_recv%return@net/ipv4/tcp.c with arg1)
  6. # 删除已添加的探测点,从 perf probe --list 中获取
  7. perf probe --del probe:splice_to_pipe
  8. # 查看准确的探测点(颜色区分)
  9. perf probe -L splice_to_pipe

探测点要捕获变量,需要安装 kernel-debuginfo,Centos7.9 可以直接从阿里云下载,速度非常快(有的镜像源没有debuginfo,官方的速度太慢)

问题背景

在数据在 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 的源码

  1. // fs/splice.c splice_to_pipe
  2. 186 ssize_t splice_to_pipe(struct pipe_inode_info *pipe,
  3. 187 struct splice_pipe_desc *spd)
  4. 188 {
  5. 198 for (;;) {
  6. 206 if (pipe->nrbufs < pipe->buffers) {
  7. 218 pipe->nrbufs++;
  8. 219 page_nr++;
  9. 220 ret += buf->len;
  10. 221
  11. 222 if (pipe->files)
  12. 223 do_wakeup = 1;
  13. 224
  14. 225 if (!--spd->nr_pages)
  15. 226 break;
  16. 227 if (pipe->nrbufs < pipe->buffers)
  17. 228 continue;
  18. 229
  19. 230 break;
  20. 231 }
  21. 232
  22. 233 if (spd->flags & SPLICE_F_NONBLOCK) {
  23. 234 if (!ret)
  24. 235 ret = -EAGAIN;
  25. 236 break;
  26. 237 }
  27. 244
  28. 245 if (do_wakeup) {
  29. 246 smp_mb();
  30. 247 if (waitqueue_active(&pipe->wait))
  31. 248 wake_up_interruptible_sync(&pipe->wait);
  32. 249 kill_fasync(&pipe->fasync_readers, SIGIO, POLL_IN);
  33. 250 do_wakeup = 0;
  34. 251 }
  35. 252
  36. 253 pipe->waiting_writers++;
  37. 254 pipe_wait(pipe);
  38. 255 pipe->waiting_writers--;
  39. 256 }
  40. 257
  41. 260 if (do_wakeup)
  42. 261 wakeup_pipe_readers(pipe);
  43. 262
  44. 263 while (page_nr < spd_pages)
  45. 264 spd->spd_release(spd, page_nr++);
  46. 265
  47. 266 return ret;
  48. 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 字节的数据

  1. $ dd if=/dev/zero of=/tmp/1.txt bs=1k count=24
  2. $ ncat -nv 192.168.32.245 10022 < /tmp/1.txt

开始 perf 记录

  1. [root@localhost ~]# perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages'
  2. Added new event:
  3. probe:splice_to_pipe (on splice_to_pipe with nrbufs=pipe->nrbufs buffers=pipe->buffers nr_pages=spd->nr_pages)
  4. [root@localhost ~]# perf record -e 'probe:splice_to_pipe' -p $(pidof a.out) -gR sleep 30
  5. [ perf record: Woken up 1 times to write data ]
  6. [ perf record: Captured and wrote 0.017 MB perf.data (1 samples) ]
  7. [root@localhost ~]# perf report --stdio
  8. # Samples: 2 of event 'probe:splice_to_pipe'
  9. # Event count (approx.): 2
  10. # Children Self Trace output
  11. # ........ ........ ......................................................
  12. 50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=17
  13. ...
  14. 50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2

通过 perf 观察到 splice_to_pipe 调用了两次,从 nrbufs 看第一次调用后 pipe 就没有空间了,再看一次代码,第一次调用在在 L230 返回,没有执行后续的逻辑。

  1. // fs/splice.c splice_to_pipe
  2. 227 if (pipe->nrbufs < pipe->buffers)
  3. 228 continue;
  4. 229
  5. 230 break;

并且在 L263 while (page_nr < spd_pages) 这个条件是满足的,我们完整的追踪一下这个调用的链路,主要跟踪可能出现循环的逻辑,包括 tcp_read_sock, tcp_splice_data_recv, sock_spd_release 以及阻塞的逻辑 pull_wait

  1. ---splice
  2. system_call_fastpath
  3. sys_splice
  4. do_splice_to
  5. sock_splice_read
  6. tcp_splice_read
  7. tcp_read_sock
  8. tcp_splice_data_recv
  9. skb_splice_bits
  10. skb_socket_splice
  11. splice_to_pipe
  12. kill_fasync

通过增加观测点来进行验证,

  1. perf probe --add 'tcp_read_sock desc->count'
  2. perf probe --add 'tcp_read_sock%return $retval'
  3. perf probe --add 'tcp_splice_data_recv rd_desc->count len offset'
  4. perf probe --add 'tcp_splice_data_recv%return $retval'
  5. perf probe --add 'splice_to_pipe pipe->nrbufs pipe->buffers spd->nr_pages pipe->files pipe->waiting_writers pipe->readers'
  6. perf probe --add 'splice_to_pipe%return $retval'
  7. perf probe --add 'pipe_wait pipe->nrbufs pipe->buffers pipe->files pipe->waiting_writers pipe->readers'
  8. perf probe --add 'sock_spd_release spd->nr_pages i'
  9. perf record -e "$(perf probe --list | awk '{print $1}' | sed ':a;N;$!ba;s/\n/,/g')" -p $(pidof a.out) -gR sleep 30

输出结果为:

  1. # Samples: 1 of event 'probe:pipe_wait'
  2. # Children Self Trace output
  3. # ........ ........ .....................................................................................
  4. 100.00% 100.00% (ffffffffa9a57760) nrbufs=0x10 buffers=0x10 files=0x2 waiting_writers=0x1 readers=0x1
  5. # Samples: 1 of event 'probe:sock_spd_release'
  6. # Children Self Trace output
  7. # ........ ........ ....................................
  8. 100.00% 100.00% (ffffffffa9e418a0) nr_pages=1 i=0x10
  9. # Samples: 2 of event 'probe:splice_to_pipe'
  10. # Children Self Trace output
  11. # ........ ........ ................................................................................................
  12. 50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=17 files=0x2 waiting_writers=0x0 readers=0x1
  13. 50.00% 50.00% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2 files=0x2 waiting_writers=0x0 readers=0x1
  14. # Samples: 1 of event 'probe:tcp_read_sock'
  15. # Children Self Trace output
  16. # ........ ........ .................................
  17. 100.00% 100.00% (ffffffffa9eb2e50) count=0x100000
  18. # Samples: 2 of event 'probe:tcp_splice_data_recv'
  19. # Children Self Trace output
  20. # ........ ........ ........................................................
  21. 50.00% 50.00% (ffffffffa9eb2a10) count=0x100000 len=0x6000 offset=0x0
  22. 50.00% 50.00% (ffffffffa9eb2a10) count=0xfa770 len=0x770 offset=0x5890
  23. # Samples: 1 of event 'probe:splice_to_pipe__return'
  24. # Children Self Trace output
  25. # ........ ........ ..................................................
  26. 100.00% 100.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x5890
  27. # Samples: 0 of event 'probe:tcp_read_sock__return'
  28. # Children Self Trace output
  29. # ........ ........ ............
  30. # Samples: 1 of event 'probe:tcp_splice_data_recv__return'
  31. # Children Self Trace output
  32. # ........ ........ ..................................................
  33. 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 break 返回,没有进入 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 中,就会跳出循环不进入阻塞中

    1. 225 if (!--spd->nr_pages)
    2. 226 break;
    3. 227 if (pipe->nrbufs < pipe->buffers)
    4. 228 continue;
    5. 230 break;
tcp_splice_data_recv

tcp_splice_data_recv 出现在 tcp_read_sock 的循环中,我们对其调用参数进行分析。

  1. // net/ipv4/tcp.c tcp_splice_data_recv
  2. 634 static int tcp_splice_data_recv(read_descriptor_t *rd_desc, struct sk_buff *skb,
  3. 635 unsigned int offset, size_t len)
  4. 636 {
  5. 637 struct tcp_splice_state *tss = rd_desc->arg.data;
  6. 638 int ret;
  7. 639
  8. 640 ret = skb_splice_bits(skb, offset, tss->pipe, min(rd_desc->count, len),
  9. 641 tss->flags);
  10. 642 if (ret > 0)
  11. 643 rd_desc->count -= ret;
  12. 644 return ret;
  13. 645 }
  14. // net/ipv4/tcp.c tcp_read_sock
  15. 1458 int tcp_read_sock(struct sock *sk, read_descriptor_t *desc,
  16. 1459 sk_read_actor_t recv_actor)
  17. 1460 {
  18. 1469 while ((skb = tcp_recv_skb(sk, seq, &offset)) != NULL) {
  19. 1470 if (offset < skb->len) {
  20. 1471 int used;
  21. 1472 size_t len;
  22. 1473
  23. 1474 len = skb->len - offset;
  24. 1475 /* Stop reading if we hit a patch of urgent data */
  25. 1476 if (tp->urg_data) {
  26. 1477 u32 urg_offset = tp->urg_seq - seq;
  27. 1478 if (urg_offset < len)
  28. 1479 len = urg_offset;
  29. 1480 if (!len)
  30. 1481 break;
  31. 1482 }
  32. 1483 used = recv_actor(desc, skb, offset, len);
  33. 1484 if (used <= 0) {
  34. 1485 if (!copied)
  35. 1486 copied = used;
  36. 1487 break;
  37. 1488 } else if (used <= len) {
  38. 1489 seq += used;
  39. 1490 copied += used;
  40. 1491 offset += used;
  41. 1492 }
  42. // 50.00% 50.00% (ffffffffa9eb2a10) count=0x100000 len=0x6000 offset=0x0
  43. // 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 消费数据。得到的结果如下

  1. ssize_t n = splice(fd, NULL, pipefd, NULL, 1<<20, 0);
  2. 调整为 ->
  3. ssize_t n = splice(fd, NULL, pipefd, NULL, 1<<12, 0);
  4. ssize_t n = splice_pump(pipefd[0], dstfd, in_pipe);
  5. if (n > 0) {
  6. remain -= n;
  7. written += n;
  8. }
  9. 调整为 ->
  10. // ssize_t n = splice_pump(pipefd[0], dstfd, in_pipe);
  11. // if (n > 0) {
  12. // remain -= n;
  13. // written += n;
  14. // }

使用 perf 跟踪得到的结果如下:

  1. [root@localhost ~]# perf report --stdio
  2. # Samples: 1 of event 'probe:pipe_wait'
  3. # Children Self Trace output
  4. # ........ ........ .....................................................................................
  5. 100.00% 100.00% (ffffffffa9a57760) nrbufs=0x10 buffers=0x10 files=0x2 waiting_writers=0x1 readers=0x1
  6. # Samples: 2 of event 'probe:sock_spd_release'
  7. # Children Self Trace output
  8. # ........ ........ ...................................
  9. 50.00% 50.00% (ffffffffa9e418a0) nr_pages=2 i=0x2
  10. 50.00% 50.00% (ffffffffa9e418a0) nr_pages=2 i=0x3
  11. # Samples: 6 of event 'probe:splice_to_pipe'
  12. # Children Self Trace output
  13. # ........ ........ ................................................................................................
  14. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x0 buffers=0x10 nr_pages=3 files=0x2 waiting_writers=0x0 readers=0x1
  15. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x10 buffers=0x10 nr_pages=2 files=0x2 waiting_writers=0x0 readers=0x1
  16. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x3 buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
  17. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0x7 buffers=0x10 nr_pages=3 files=0x2 waiting_writers=0x0 readers=0x1
  18. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0xa buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
  19. 16.67% 16.67% (ffffffffa9a811e0) nrbufs=0xe buffers=0x10 nr_pages=4 files=0x2 waiting_writers=0x0 readers=0x1
  20. # Samples: 5 of event 'probe:tcp_read_sock'
  21. # Children Self Trace output
  22. # ........ ........ ...............................
  23. 100.00% 100.00% (ffffffffa9eb2e50) count=0x1000
  24. # Samples: 10 of event 'probe:tcp_splice_data_recv'
  25. # Children Self Trace output
  26. # ........ ........ ........................................................
  27. 10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x2000 offset=0x4000
  28. 10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x3000 offset=0x3000
  29. 10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x4000 offset=0x2000
  30. 10.00% 10.00% (ffffffffa9eb2a10) count=0x0 len=0x5000 offset=0x1000
  31. 10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x2000 offset=0x4000
  32. 10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x3000 offset=0x3000
  33. 10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x4000 offset=0x2000
  34. 10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x5000 offset=0x1000
  35. 10.00% 10.00% (ffffffffa9eb2a10) count=0x1000 len=0x6000 offset=0x0
  36. 10.00% 10.00% (ffffffffa9eb2a10) count=0x868 len=0x1868 offset=0x4798
  37. # Samples: 5 of event 'probe:splice_to_pipe__return'
  38. # Children Self Trace output
  39. # ........ ........ ..................................................
  40. 80.00% 80.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x1000
  41. 20.00% 20.00% (ffffffffa9a811e0 <- ffffffffa9e481b7) arg1=0x798
  42. # Samples: 4 of event 'probe:tcp_read_sock__return'
  43. # Children Self Trace output
  44. # ........ ........ ..................................................
  45. 100.00% 100.00% (ffffffffa9eb2e50 <- ffffffffa9eb3128) arg1=0x1000
  46. # Samples: 9 of event 'probe:tcp_splice_data_recv__return'
  47. # Children Self Trace output
  48. # ........ ........ ..................................................
  49. 44.44% 44.44% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x0
  50. 44.44% 44.44% (ffffffffa9eb2a10 <- ffffffffa9eb2efb) arg1=0x1000
  51. 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__returnprobe:tcp_splice_data_recv 里面 count 的变化),最后一次在 L1487 之前就被阻塞了。

  1. // net/ipv4/tcp.c tcp_read_sock
  2. 1484 if (used <= 0) {
  3. 1485 if (!copied)
  4. 1486 copied = used;
  5. 1487 break;

结论

3.10.0 在数据远小于 65536 的情况下被阻塞的原因就是 tcp_read_sock 用于读取数据的页没有写满 4096 字节,导致占用的页数大于 pipe 的容量(16)

TODO

由于 debian12 没有找到对应的 debuginfo(ubuntu 的 dbgsyms),这里再挖个坑,后面准备用 fedora39 再跟踪一波

参考

原文链接:https://www.cnblogs.com/shuqin/p/18034331

 友情链接:直通硅谷  点职佳  北美留学生论坛

本站QQ群:前端 618073944 | Java 606181507 | Python 626812652 | C/C++ 612253063 | 微信 634508462 | 苹果 692586424 | C#/.net 182808419 | PHP 305140648 | 运维 608723728

W3xue 的所有内容仅供测试,对任何法律问题及风险不承担任何责任。通过使用本站内容随之而来的风险与本站无关。
关于我们  |  意见建议  |  捐助我们  |  报错有奖  |  广告合作、友情链接(目前9元/月)请联系QQ:27243702 沸活量
皖ICP备17017327号-2 皖公网安备34020702000426号