背景:
随着业务迭代,部分项目用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 '\bnode\b'
14621626
[root@k8s-worker-node-13 ~]# cat /tmp/lsof | egrep '\bnode\b' | 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。
20200407补充:
下面是我在生产环境的 ingress-controller deployment的yaml里看到的方法,通过initContainers方式控制内核参数,建议大家有需求的也使用这种方式来处理。