这篇文章主要介绍了在将capnp-rpc从Lwt移植到Eio的过程中遇到的网络性能问题，并使用多种工具进行调查和分析，最终找到并解决了问题。主要内容如下：

• 问题描述：将capnp-rpc从Lwt移植到Eio后，运行基准测试发现新的Eio版本速度非常慢，Lwt版本使用 CPU 的时间为 98%，而Eio版本大部分时间在睡眠。

• 使用的工具及介绍：

  • time：可以显示程序在用户模式、内核模式和总挂钟时间上的花费，为问题提供了初步线索。
  • eio-trace：用于查看Eio程序的行为，可运行命令并在窗口中显示跟踪，或保存跟踪以供以后检查。
  • strace：用于跟踪应用程序与 Linux 内核之间的交互，-tt -T显示每个调用的开始时间和持续时间，-f可跟踪所有派生的线程。
  • bpftrace：一种类似于awk的脚本语言，可实时修补运行中的 Linux 内核，用于跟踪io_uring操作。
  • tcpdump：用于捕获网络数据包，可在控制台或wireshark中显示。
  • ss：显示套接字统计信息，ss -tin显示所有 TCP 套接字的内部信息。
  • offwaketime：记录程序停止使用 CPU 的原因和导致其恢复的原因。
  • magic-trace：允许捕获 CPU 在某些事件发生之前所做的一切的短跟踪，使用 Intel Processor Trace 将所有控制流更改记录到环形缓冲区中。

• 具体调查过程及结果：

  • 通过eio-trace跟踪发现每次测试循环迭代有 40ms 延迟，程序在第一次延迟中间会短暂唤醒然后继续睡眠，通过配置日志库可获取更多上下文信息，发现未缓冲输出导致两次单独写入而不是合并，这可能导致 40ms 延迟。
  • 使用strace跟踪发现Eio默认使用io_uring机制提交工作到内核，超时后会唤醒futexes并等待，切换到posix后端后问题仍然存在，还发现Eio在处理getaddrinfo时会创建新的系统线程。
  • 使用bpftrace跟踪io_uring操作，发现io_uring_complete事件的时间和结果，确认了 40ms 延迟。
  • 使用tcpdump捕获网络数据包，看到应用程序两次写入之间 TCP 等待发送第二次数据，这是由于 Nagle 算法导致的延迟 ACK。
  • 使用ss显示套接字统计信息，看到客户端套接字有 176 字节的队列等待确认。
  • 使用offwaketime记录程序暂停和恢复的堆栈跟踪，发现 Eio 被网络接收的 TCP 数据唤醒，还发现 OCaml 的 tick 线程每 50ms 唤醒一次。
  • 使用magic-trace获取更详细的函数级跟踪，看到Eio_posix.Flow.single_read在读取时遇到EAGAIN并切换到下一个纤维，以及tcp_write_xmit中的 Nagle 算法。
• 总结脚本及分析：编写summary-posix.bt脚本总结各种事件，包括应用程序的日志消息、套接字的读写和内核函数的调用，确认了问题的原因。
• 解决方案及效果：添加缓冲到Eio版本解决了问题，不仅消除了长延迟，还使 CPU 操作更快，新的Eio版本速度从 511.963565 提升到 59653.451934 RPC 请求每秒。
• 结论：有很多工具可帮助理解程序运行缓慢的原因，每个工具都有其特点和用途，bpftrace非常有用，magic-trace对于获取详细的函数级跟踪很有帮助，但很难直接指出 Nagle 算法与延迟 ACK 导致的问题。下一篇文章将调查 CPU 密集型问题。