阿里云ECS的CPU100%排查

一、背景和現(xiàn)象

初創(chuàng)公司，架構(gòu)lanmp，web前端和后端分開服務(wù)器，業(yè)務(wù)驅(qū)動主要是nginx和apache，nginx主要是處理靜態(tài)文件和反向代理，前后端、搜索引擎、緩存、隊列等附加的服務(wù)都是用docker容器部署。因為比較初級，上傳文件和采集文件都是直接寫在硬盤上，涉及到的目錄共享，就在其中一臺服務(wù)器存儲并且nfs共享。我們暫且分為ECS1（apache1）、ECS2（apache2）、ECS3（nginx）。某天網(wǎng)站業(yè)務(wù)中斷，但是沒有報錯。一直在等待響應(yīng)，默認(rèn)響應(yīng)超時是一分鐘，所以很基礎(chǔ)高可用沒有起到作用。中斷10分鐘左右，重啟服務(wù)，提示“open too many files”，但是lsof統(tǒng)計沒幾個。因為初級處理不了，所以直接重啟服務(wù)器，一段時間后一切恢復(fù)正常，可是第二天又來一次這種情況。

二、第一次出現(xiàn)后的排查思路

本來第一次發(fā)現(xiàn)這種問題的時候就要追查原因了，看了一下zabbix監(jiān)控圖像其中斷了十分鐘，包括網(wǎng)絡(luò)、內(nèi)存、CPU、硬盤、IO等監(jiān)控數(shù)據(jù)。首先想到的是網(wǎng)絡(luò)問題，結(jié)論是zabbix-servert獲取不到了zabbix-agent采集的數(shù)據(jù)，估計就是網(wǎng)絡(luò)不通了。

但是，這個結(jié)論站不住腳，因為我本身通過ssh登錄服務(wù)器，并且命令輸入無卡頓，不至于頭文件都傳不過來。后來一看阿里云的云監(jiān)控，上面有數(shù)據(jù)，似乎也可以佐證網(wǎng)絡(luò)這個說法，因為云監(jiān)控是阿里云內(nèi)部的監(jiān)控，可以內(nèi)網(wǎng)獲取到監(jiān)控數(shù)據(jù)。直到看CPU的使用率這項，發(fā)現(xiàn)有一段時間的CPU使用率100%。并且我重啟的時候CPU恢復(fù)正常，不能說網(wǎng)絡(luò)一定沒問題，但系統(tǒng)肯定有問題。也可以解釋因為CPU使用已經(jīng)是100%，zabbix-agent和根本不能正常運行，所以沒有監(jiān)控數(shù)據(jù)。因為這個公司全部都是云服務(wù)器，沒有使用IDC所以我們也沒有安裝smokeping來監(jiān)控，接著我們就不把重心在網(wǎng)絡(luò)上了。

目前掌握的信息就是:在毫無征兆的情況下，CPU暴漲到100%，重啟之前一直保留，重啟之后恢復(fù)原樣。匆忙之中又看了一下系統(tǒng)各日志，因為太匆忙，沒有總結(jié)，沒有找到什么有價值的東西?，F(xiàn)在有下面幾種猜想：第一，程序的bug或者部署不當(dāng)，觸發(fā)之后耗盡資源。第二、docker容器的bug。第三、網(wǎng)絡(luò)攻擊。第四、病毒入侵。第五、阿里云方系統(tǒng)不穩(wěn)定。

小總結(jié)了一下，現(xiàn)在問題還沒有找出來。下次還有這個問題的可能，所以先盡量防范，但是又不能重啟一刀切。所以在zabbix上面設(shè)置了自動化，當(dāng)檢測到ECS1獲取不到數(shù)據(jù)的時候馬上操作ECS3標(biāo)記后端為ECS1的apache為down。保留異?，F(xiàn)場。（請求停止的時候，CPU100%還在）

三、現(xiàn)場排查

1、相應(yīng)的排查計劃（想到這些信息需要獲取的，實際上沒有嚴(yán)格按照這樣的步驟）

1）用htop和top命令監(jiān)控CPU、內(nèi)存使用大的進程。先看看哪個進程消耗資源較多,用戶態(tài)、內(nèi)核態(tài)、內(nèi)存、IO……同時sar-b查io的歷史定時抽樣。

2）統(tǒng)計tcp連接數(shù)，看看有沒有DDOS攻擊。netstat-anp|grep tcp|wc-l。用iftop-i eth1看看通訊。同時用tail-n 1200/var/log/messages查看內(nèi)核日志。

3）用pstree查看打開進程，ps aux|wc-l看看有沒有特別多的進程。雖然zabbix監(jiān)控上說沒有，但是我們要檢查一下看看有沒有異常的進程名字。

4）查看全部容器的資源使用docker stats$(docker ps-a-q)，看看能不能從容器上排查。

5）有了“too many open files”的啟發(fā)，計算打開文件數(shù)目lsof|wc-l，根據(jù)進程看看ll/proc/PID/fd文件描述符有沒有可疑的打開文件、文件描述符。

6）關(guān)于用lsof打開文件數(shù)找到的線索，排序打開文件找出進程號lsof-n|awk'{print$2}'|sort|uniq-c|sort-nr|more

7）關(guān)于用lsof打開文件數(shù)找到的線索，用lsof-p PID查看進程打開的句柄。直接查看打開的文件。

8）啟動容器的時候又總是“open too many files"。那就是打開文件數(shù)的問題，因為CPU的使用率是CPU的使用時間和空閑時間比，有可能因為打開文件數(shù)阻塞而導(dǎo)致CPU都在等待。針對連接數(shù)的問題，大不了最后一步試試echo 6553500>/proc/sys/fs/file-max測試打開文件對CPU的影響。

9）玩意測出來了消耗CPU的進程，可以使用strace最終程序。用戶態(tài)的函數(shù)調(diào)用跟蹤用「ltrace」，所以這里我們應(yīng)該用「strace」-p PID

10）從程序里面看到調(diào)用系統(tǒng)底層的函數(shù)可以跟蹤。跟蹤操作strace-T-e*-p PID，主要看看代碼調(diào)用的函數(shù)有沒有問題。

2、現(xiàn)場排查

第二天同樣時間，ECS果然暴漲了CPU。這是時候zabbix的工作如希望進行保留了一臺故障的ECS1給我。

1）用htop看到資源使用最大是，搜索引擎下我寫的一個判斷腳本xunsearch.sh。腳本里面很簡單，判斷索引和搜索服務(wù)缺一個就全部重啟。就當(dāng)是我的容器有問題我直接關(guān)掉搜索引擎容器。httpd頂上，我又關(guān)掉apache容器。rabbitmq相關(guān)進程又頂上。這時候我沒心情周旋了，肯定不也是這個原因。sar-b查看的歷史io也沒有異常。

2）統(tǒng)計tcp連接，幾百。先不用著重考慮攻擊了。用tail-n 1200/var/log/messages查看內(nèi)核日志，是TCP TIME WAIT的錯誤。可以理解為CPU使用100%，程序無響應(yīng)外面的tcp請求超時。這是結(jié)果，還是沒有找到根本原因。

接著往下看系統(tǒng)內(nèi)核日志，發(fā)現(xiàn)了和“open too many files”呼應(yīng)的錯誤，“file-max limit 65535 reached”意思是，已到達了文件限制瓶頸。這里保持懷疑，繼續(xù)收集其他信息。

3）查看進程數(shù)量，數(shù)量幾百。列出來也看到都是熟悉的進程，可以先排除異常進程。

4）監(jiān)控容器的資源使用，里面很不穩(wěn)定，首先是xunsearch容器使用80%的CPU，關(guān)掉xunsearch，又變成了其他容器使用CPU最高。很大程度上可以排查容器的問題和執(zhí)行程序的問題。

5）查看了最大連接數(shù)cat/proc/sys/fs/file-max是65535但是用lsof查到的連接數(shù)是10000多，完全沒有達到連接數(shù)。

6）各項參數(shù)都正常，現(xiàn)在聚焦在打開的文件數(shù)這個問題上面。也可以用另外同一種方式查看一下內(nèi)核統(tǒng)計文件/proc/sys/fs/file-nr，比較一下差異，看看能不能找出問題。cat了一下，打開文件數(shù)是66080，果然超了！內(nèi)核日志就以這個為標(biāo)準(zhǔn)。

但是看lsof怎么統(tǒng)計不出來，ll/proc/PID/fd也沒幾個。這個問題放在后面，先按照步驟echo 6553500>/proc/sys/fs/file-max給連接數(shù)提高到100倍，CPU果然降了下來。原因確認(rèn)了，但是必須找到根源，為什么忽然有這么大的打開文件數(shù)。關(guān)掉全部docker容器和docker引擎，打開文件數(shù)是少了一點，但是仍然在65535差不多。我就先排除一下業(yè)務(wù)的影響，把ECS3的nginx直接指向視頻ECS2的apache，就等同于在ECS2上實現(xiàn)了ECS1的場景。查看一下ECS2的句柄數(shù)，才4000多，排除了業(yè)務(wù)相關(guān)應(yīng)用對服務(wù)器的影響。那就能下個小結(jié)論，ECS1被神秘程序打開了6萬多句柄數(shù)，打開業(yè)務(wù)就多了2000多的句柄數(shù)，然后就崩潰了。不過這個現(xiàn)象有點奇怪，ECS2和ECS1在一樣的機房一樣的配置一樣的網(wǎng)絡(luò)環(huán)境，一樣的操作系統(tǒng)，一樣的服務(wù)，一樣的容器，為什么一個有問題，一個沒問題呢？不同的只是有一臺是共享nfs。難道是靜態(tài)文件共享了，其他人讀了，也算是本服務(wù)器打開的？

7）現(xiàn)在程序找不到，沒法繼續(xù)lsof-p了。排查之前的猜想。帶著排查得到對的結(jié)論往下想。

程序的bug和部署不當(dāng)，那是不可能的，因為主要問題來自于打開句柄數(shù)，當(dāng)部署到ECS2那里，一切正常。docker容器的bug，那也不可能的，每個都是我親自寫腳本，親自編譯，親自構(gòu)建的，關(guān)鍵是我關(guān)掉了docker容器和引擎都沒有很大改善。網(wǎng)絡(luò)攻擊也排除，因為網(wǎng)絡(luò)連接數(shù)沒幾個，流量也不變。那就只剩下病毒入侵也不是，沒有異常進程?？紤]到ECS的穩(wěn)定性問題了。這方面就協(xié)助阿里云工程師去排查。

8）阿里云工程師用的排查手段和我差不多，最終也是沒能看到什么。也只是給了我一些治標(biāo)不治本的建議。后來上升到專家排查，專家直接在阿里云后端抓取了coredump文件分析打開的文件是圖片，程序是nfsd。

好像印證了我剛才后面的猜想，應(yīng)該就是ECS1使用了nfs共享其他服務(wù)器打開了然后算在ECS1頭上。那問題又來了，我們的業(yè)務(wù)已經(jīng)到達了可以影響服務(wù)器的程度嗎？

9）既然問題解決到這一步，先不管程序有沒有關(guān)閉打開的文件和nfs的配置。我們架構(gòu)上面的圖片應(yīng)該是歸nginx讀取，難道是linux的內(nèi)存機制讓它緩存了。帶著緩存的問題，首先去ECS3上釋放內(nèi)存echo 3>/proc/sys/vm/drop_caches，釋放之后，發(fā)現(xiàn)沒什么改善，有點失落。總是覺得還有一臺后端是PHP主導(dǎo)，但是邏輯上是寫入，沒有打開文件之說。后來從程序員中了解到，PHP也有打開圖片。我猛然去ECS2釋放一下內(nèi)存，果然，句柄數(shù)降下來。（這里大家一定有個疑問，為什么我直接想到內(nèi)存緩存而不是目前打開的文件呢。其一，這是生產(chǎn)環(huán)境，web前端只有一個，不能亂來停服務(wù)。其二，第一次遇到問題的時候，重啟之后沒有問題，過了一天之后積累到一定的程度才爆發(fā)，這里已經(jīng)引導(dǎo)了我的思路是積累的問題，那就是緩存不斷積累了）

10）因為ECS2的調(diào)用ECS1的nfs共享文件，所以lsof也有讀不到那么多句柄數(shù)的理由。如果說是nfs的服務(wù)本身就有緩存，導(dǎo)致問題的話，我查看了配置文件，還是默認(rèn)值允許緩存，30S過期，根本不會因為nfs的緩存造成打開文件過多。如果我們的后端程序打開之后沒好好處理的話，那倒有可能。然后嘗試排除：我改了ECS3的配置，使程序只讀ECS1后端，從ECS1上面卻看不到有什么異常表現(xiàn)，說明PHP程序已經(jīng)好好處理了打開的文件。也不是docker掛載了nfs的共享的問題，因為nginx也有掛載。排查到這里也很大程度上解決問題，而且緩存了nfs的全部共享文件，句柄并沒有增加，也算合理，所以就增加了打開文件數(shù)的限制。

11）現(xiàn)在排查的結(jié)果是跟后端和nfs共享有關(guān)。就是說，后端掛載了nfs的網(wǎng)絡(luò)共享，被程序讀取。而程序釋放之后，在正常背景的硬盤文件是沒有緩存的。但是在nfs掛載的環(huán)境下，緩存并沒有得到釋放。

12）總結(jié)：很多問題的排查和我們的猜想結(jié)果一樣，但是有些例外的情況。比如這次我想到的原因都一一排除，但是問題也是在一步步排查中，逐步被發(fā)現(xiàn)的。