一次文件句柄消耗过多的排查过程
- 2020 年 3 月 17 日
- 筆記
背景：
随着业务迭代，部分项目用nodejs重构后，部署到k8s环境下运行。为了便于分析，上了一版代码，增加输出日志的功能。
现象：
上线半天后，发现研发反馈有收到报错提示 too many open files 这种 打开文件过多的告警， 部分pod crash掉了，影响到用户体验。
同时，运维查看监控，可以看到文件句柄使用量在短时间内剧增，如下图：
运维查看问题k8s节点的文件句柄使用情况
ulimit -n # 查看当前用户可用最大句柄 sysctl -a | grep fs.file-max # 查看内核级的文件句柄最大限制值 cat /proc/sys/fs/file-nr # 查看当前已用的文件句柄数量 和 内核级的文件句柄限制的最大值 可以看到的是问题k8s节点的 cat /proc/sys/fs/file-nr 的已用文件句柄数量基本用满了。
运维侧的快速解决方法：
vim /etc/sysctl.conf 增加一行配置 fs.file-max = 13129438 # 调大这个值（这个值如果不人工指定的话，linux是会根据每台服务器的硬件配置自动设置的，可以看到64G和128G内存的主机，这个值是不同的） sysctl -p 使上面调整文件句柄的操作立即生效 然后，将这个节点从k8s集群摘除掉（并将pod赶到其它正常节点上）。无法释放的文件句柄，我们只能通过重启服务器来释放出来。 并猜测可能是最近新上的nodejs项目打日志的姿势不对造成的。
下面是在 k8s worker-node13 节点抓取的lsof信息（只要跑有这个异常的pod的k8s-worker-node的就可以去执行下lsof看下，毕竟如果有句柄未关闭，肯定这个系列的全部pod都有问题）：
lsof > /tmp/lsof # 得出的文件差不多2GB大小 (这个过程比较漫长，可能需要5-10分钟）
[root@k8s-worker-node-13 ~]# cat /tmp/lsof | grep -c java
3422
[root@k8s-worker-node-13 ~]#cat /tmp/lsof | egrep -c 'bnodeb'
14621626
[root@k8s-worker-node-13 ~]# cat /tmp/lsof | egrep 'bnodeb' | less 查看过滤出来的日志文件
TID列为空 COMMAND PID TID USER FD TYPE DEVICE SIZE/OFF NODE NAME node 16966 root 458w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 459w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 460w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 461w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 462w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 463w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 464w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 465w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 466w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 467w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 468w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 469w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 470w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 471w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 472w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json node 16966 root 473w REG 253,1 671641730 1572898 /usr/src/app/log/test-app/test-app-2020-03-11.json 。。。。。 省略部分内容 。。。。。 node 20927 20955 root mem REG 253,16 6823953 /usr/lib/libgcc_s.so.1 (stat: No such file or directory) node 20927 20955 root mem REG 253,16 6823955 /usr/lib/libstdc++.so.6.0.22 (stat: No such file or directory) node 20927 20955 root mem REG 253,16 6030733 /lib/ld-musl-x86_64.so.1 (stat: No such file or directory) node 20927 20955 root mem REG 253,16 6030679 /etc/localtime (path dev=253,1, inode=788097) node 20927 20955 root 23w REG 0,460 717345 9178728 /tmp/access-20200311.log node 20927 20955 root 27w REG 0,460 209117 9178762 /tmp/tracing-20200311.log node 20927 20955 root 29w REG 0,460 209117 9178762 /tmp/tracing-20200311.log node 20927 20956 root txt REG 0,460 40885256 7079234 /usr/local/bin/node node 20927 20956 root mem REG 253,16 7079234 /usr/local/bin/node (stat: No such file or directory) node 20927 20956 root mem REG 253,16 6823953 /usr/lib/libgcc_s.so.1 (stat: No such file or directory) node 20927 20956 root mem REG 253,16 6823955 /usr/lib/libstdc++.so.6.0.22 (stat: No such file or directory) node 20927 20956 root mem REG 253,16 6030733 /lib/ld-musl-x86_64.so.1 (stat: No such file or directory) node 20927 20956 root mem REG 253,16 6030679 /etc/localtime (path dev=253,1, inode=788097) node 20927 20957 root txt REG 0,460 40885256 7079234 /usr/local/bin/node node 20927 20957 root mem REG 253,16 7079234 /usr/local/bin/node (stat: No such file or directory) node 20927 20957 root mem REG 253,16 6823953 /usr/lib/libgcc_s.so.1 (stat: No such file or directory) node 20927 20957 root mem REG 253,16 6823955 /usr/lib/libstdc++.so.6.0.22 (stat: No such file or directory) node 20927 20957 root mem REG 253,16 6030733 /lib/ld-musl-x86_64.so.1 (stat: No such file or directory) node 20927 20957 root mem REG 253,16 6030679 /etc/localtime (path dev=253,1, inode=788097) node 20927 20957 root 23w REG 0,460 717345 9178728 /tmp/access-20200311.log node 20927 20957 root 27w REG 0,460 209117 9178762 /tmp/tracing-20200311.log node 20927 20957 root 29w REG 0,460 209117 9178762 /tmp/tracing-20200311.log node:Log 20927 21094 root txt REG 0,460 40885256 7079234 /usr/local/bin/node node:Log 20927 21094 root mem REG 253,16 7079234 /usr/local/bin/node (stat: No such file or directory) node:Log 20927 21094 root mem REG 253,16 6823953 /usr/lib/libgcc_s.so.1 (stat: No such file or directory) node:Log 20927 21094 root mem REG 253,16 6823955 /usr/lib/libstdc++.so.6.0.22 (stat: No such file or directory) node:Log 20927 21094 root mem REG 253,16 6030733 /lib/ld-musl-x86_64.so.1 (stat: No such file or directory)
开发侧的解决方法：
回退服务，并排查代码里面打日志的地方是否有问题。 后续，第二天后，开发反馈，他们之前的打日志写的有问题，都是持续打开文件，没有做close关闭动作，导致文件句柄不释放。
运维侧的优化方案：
1、增加相关的监控（node_exporter即可） 监控表达式： node_filefd_allocated/ node_filefd_maximum * 100 > 70 就触发告警，提示文件句柄占用超过70%，需要运维介入查看分析 2、对docker image里面的内核参数做限制（还没测试这招是否有效，待实战验证） 理由：docker镜像里面也是个精简版的linux，我们发现生产环境的image里它的默认的fs.file-max 和 ulimt -n设置的非常大，我们可以考虑将ulimit -n 调低到 65535 ， 将 fs.file-max 调低到 655350。 这样即便这个pod出问题后，只能影响到它自己，而不会连累到宿主机的上运行的其他pod。
