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

时间 2020-03-16

标签一次文件句柄消耗过多排查过程栏目 OS基础繁體版

原文原文链接

背景：java

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

现象：linux

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

同时，运维查看监控，能够看到文件句柄使用量在短期内剧增，以下图：docker

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

ulimit -n  # 查看当前用户可用最大句柄

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

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

运维侧的快速解决方法：vim

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都有问题）：bash

lsof > /tmp/lsof # 得出的文件差很少2GB大小 (这个过程比较漫长，可能须要5-10分钟）服务器

[root@k8s-worker-node-13 ~]# cat /tmp/lsof | grep -c javaapp

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关闭动做，致使文件句柄不释放。

运维侧的优化方案：

一、增长相关的监控（node_exporter便可）
监控表达式： node_filefd_allocated/ node_filefd_maximum * 100 > 70  就触发告警，提示文件句柄占用超过70%，须要运维介入查看分析

二、对docker image里面的内核参数作限制（还没测试这招是否有效，待实战验证）
理由：docker镜像里面也是个精简版的linux，咱们发现生产环境的image里它的默认的fs.file-max 和 ulimt -n设置的很是大，咱们能够考虑将ulimit -n 调低到 65535 ， 将 fs.file-max 调低到 655350。
这样即使这个pod出问题后，只能影响到它本身，而不会连累到宿主机的上运行的其余pod。