linux命令从日志里抓取流水,流水账-使用strace调试解决Pistache中Too Many Open Files

Too Many Open Files这个问题一般是由于fd未关闭导致的，当项目足够庞大且依赖大量第三方库的时候，依靠gdb调试的手段几乎不可能找的到未关闭的fd。我们实验室的某个存储项目在开发的时候就出现了这个故障：

E0421 02:43:45.960949164 31575 ev_epollex_linux.cc:1450] pollset_set_add_pollset:

{"created":"@1587408225.960932685","description":"Too many open files","errno":24,"file":

"XXXXXXXXXX/third-party/grpc/src/core/lib/iomgr/ev_epollex_linux.cc","file_line":560,

"os_error":"Too many open files","syscall":"epoll_create1"}

其中涉及fd的创建的有如下组件：

grpc: RPC框架

pistache: REST框架

libCouchBase: 数据库连接客户端

libuv: 事件驱动框架

项目本身调用的open以及opendir等

可能存在的其他依赖组件

从代码角度去人工找出未调用close(fd)的部分几乎不可能，因为close(fd)本身已经经过多层复杂的封装以及复杂的多线程调用关系(例如往ASIO框架中塞lambda函数的方式)，并且fd过多，难以追踪每一个fd涉及的代码。在解决复杂项目的file descriptor leaking问题上，gdb帮助很小，而需要strace等工具。

使用strace抓取系统调用记录

strace的教程网上有很多，成熟的linux使用者也基本都掌握了自己看man page的能力，man strace告诉我们如果想要调试一个

正在运行的进程的: -p pid Attach to the process with the process ID pid and begin tracing.

所有子线程的: -f Trace child processes as they are created by currently traced processes as a result of the fork(2), vfork(2) and clone(2) system calls.

关于fd的系统调用: -e trace=%desc Trace all file descriptor related system calls.

最好能够像gdb一样打印call stack: -k Print the execution stack trace of the traced processes after each system call (experimental).

出错的fd很可能和网络有关: -yy Print protocol specific information associated with socket file descriptors. -y Print paths associated with file descriptor arguments.

所以了解自己的需求然后带着需求去看man page的能力真的很重要，CSDN或者简书根本不会告诉你这么多。最终组合起来的命令就是：

strace -k -y -yy -e trace=%desc -o gc.strace.log -fp [The Running Process's PID]

分析系统调用记录

fd相关的系统调用记录以及记录到了gc.strace.log中，使用less或者vscode进行肉眼分析。分析过程比较朴素：

找出所有的close调用，可以很清楚的知道哪些fd被关闭了，哪些没有。

例如

close(19127.0.0.1:7090]> = 0

close(22127.0.0.1:7090]> = 0

...

可以很清楚的发现fd=20与fd=21并没有关闭

找出未关闭的fd相关的创建的系统调用。

例如可以找到fd=20是由epoll_create(128) = 20 创建的；fd=21是由eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK) = 21创建的。

找到系统调用对应的代码位置：

由于我在strace中使用-k打印了调用栈，因此可以很清楚地找到系统调用的调用代码位置

> /lib/x86_64-linux-gnu/libc-2.27.so(epoll_create+0x7) [0x1221e7]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Polling::Epoll::Epoll(unsigned long)::{lambda()#1

}::operator()() const+0x38) [0x2ea616]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Polling::Epoll::Epoll(unsigned long)+0x33) [0x2ea

7df]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Aio::SyncImpl::SyncImpl(Pistache::Aio::Reactor*)+

0x7a) [0x2eff52]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Aio::AsyncImpl::Worker::Worker(Pistache::Aio::Rea

ctor*)+0x53) [0x2f1a31]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Aio::AsyncImpl::AsyncImpl(Pistache::Aio::Reactor*

, unsigned long)+0x8d) [0x2f10c9]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Aio::AsyncContext::makeImpl(Pistache::Aio::Reacto

r*) const+0x37) [0x2ef84d]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Aio::Reactor::init(Pistache::Aio::ExecutionContex

t const&)+0x37) [0x2ef33d]

> XXXXXX/lib/libpistache.so.0.0(Pistache::Http::Client::init(Pistache::Http::Client::Option

s const&)+0x74) [0x35e520]

bug已经很明显了，Pistache这个第三方库的HTTP Client在使用完epoll之后没有关闭epoll的fd。因此如果在某个函数中不断创建与销毁新的Pistache的Http Client(栈对象)，就会导致leaking epoll fd耗完所有fd。因此只需要在Pistache::Polling::Epoll::~Epoll()中加入对epoll fd的close逻辑即可。

eventfd的处理方式同理。

回过头来检查

在代码修改完成后需要检查Too Many Open Files的问题是否解决，使用watch /proc/[Running Proc's PID]/fd即可看到进程占用的fd的实时变化情况，果然没有无限增长了，问题解决。