一次文件句柄消耗过多的排查过程

2020-03-16 23:54:43 浏览数 (1)

背景:

随着业务迭代,部分项目用nodejs重构后,部署到k8s环境下运行。为了便于分析,上了一版代码,增加输出日志的功能。

现象:

上线半天后,发现研发反馈有收到报错提示 too many open files 这种 打开文件过多的告警, 部分pod crash掉了,影响到用户体验。 

同时,运维查看监控,可以看到文件句柄使用量在短时间内剧增,如下图:

运维查看问题k8s节点的文件句柄使用情况

代码语言:javascript复制
ulimit -n  # 查看当前用户可用最大句柄

sysctl -a | grep fs.file-max  # 查看内核级的文件句柄最大限制值

cat /proc/sys/fs/file-nr      # 查看当前已用的文件句柄数量 和 内核级的文件句柄限制的最大值
可以看到的是问题k8s节点的  cat /proc/sys/fs/file-nr      的已用文件句柄数量基本用满了。

运维侧的快速解决方法:

代码语言:javascript复制
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   查看过滤出来的日志文件

代码语言:javascript复制
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)

开发侧的解决方法:

代码语言:javascript复制
回退服务,并排查代码里面打日志的地方是否有问题。 
后续,第二天后,开发反馈,他们之前的打日志写的有问题,都是持续打开文件,没有做close关闭动作,导致文件句柄不释放。

运维侧的优化方案:

代码语言:javascript复制
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。

0 人点赞