一次文件句柄消耗過多的排查過程
- 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。
