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

時間 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。

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。