一段mongodb伺服器讀取資料逾時的故事

標籤：

北京時間 2016年9月25日  22:58:30 PM

近期線上生產環境mongodb的總是發現讀取資料逾時的問題，今天下午坐下來細細的研究了一番，大致過程如下：

業務背景　　　　　　　　　　　　　　　　　　　　　　　　　　　　

線上有一對mongodb主從的伺服器，只是簡單做了mongodb的主從，master - slave。

開始以為做了主從就能確保資料不丟的問題了，確實，資料沒有發生丟失的問題，但是近期發現好多使用者在點擊某些操作要讀取mongo裡面的資料內容的時候，要等待很長的時間，這樣的等待是叫人無法忍受的。

最開始的時候，以為做了主從，然後在Tomcat的mong設定檔中設定好讀寫分離的步驟就能做到讀寫分離了，可是不然，並沒有想象的那麼好，實際的結果是不管讀還是寫都被無情的把任務分發到了主的上面，這樣一來主的壓力就恨到了，導致了使用者讀取資料的時候，需要花費很長的時間來進行等待，沿著這個問題，我們就有了下文

問題排查：　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　　

問題排查之：網卡流量君

先使用sar命令查看了伺服器的網卡流量資訊，發現正常：

sar -n DEV 1  #1秒鐘重新整理一次網卡流量資訊

23時05分26秒     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s23時05分27秒        lo      0.00      0.00      0.00      0.00      0.00      0.00      0.0023時05分27秒      eth1    909.18    818.37     64.31    148.47      0.00      0.00      0.00

問題排查之：伺服器CPU君

查看了cpu之後發現並沒有什麼異常，8核的cpu使用率不到1%

top 時時顯示伺服器資源資訊

Cpu0  : 57.4%us,  2.6%sy,  0.0%ni, 32.3%id,  0.0%wa,  2.6%hi,  5.2%si,  0.0%stCpu1  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu2  :  0.6%us,  0.0%sy,  0.0%ni, 99.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu3  :  0.6%us,  0.0%sy,  0.0%ni, 99.4%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu4  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu5  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu6  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stCpu7  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st

問題排查之：伺服器記憶體君

查看了記憶體使用量情況，可用記憶體還很多，16GB的記憶體，可用記憶體還有5GB之多

free -m 顯示記憶體資訊

             total       used       free     shared    buffers     cachedMem:         15950      10338       5612          0        105       8925-/+ buffers/cache:       1307      14642 Swap:         1023        682        341 

問題排查之：外來進程君

ps -ef 顯示系統進程

這裡不方便把伺服器開啟了那些進程羅列到此處，還請見諒；最後的分析結果就是，並無異常進程

這就奇怪了，到底是哪的問題呢？

此時io這個詞，在我頭腦中轉悠，我想會不會硬碟io堵塞，導致讀取資料超級慢呢？來，繼續

問題排查之：系統io君

iostart -x 1 每一秒鐘查看一下系統下所有磁碟的io使用狀況

avg-cpu:  %user   %nice %system %iowait  %steal   %idle          11.64    0.00    1.13    0.00    0.00   7.23Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %utilsda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00sdb               0.00     7.00    0.00    5.00     0.00   104.00    20.80     0.00    0.20   0.20   99.10dm-0              0.00     0.00    0.00   12.00     0.00   104.00     8.67     0.01    0.67   0.08   0.10

找到了一個可疑的元兇，磁碟io的等待很高，磁碟超負荷運轉。

沿著這個思路，順藤摸瓜，找到了研發同事問了下對mongodb做了什麼，他們淡定的說，就是簡單的增加、查詢之操作；好吧，那我就看看到底mongo的使用狀態吧

順藤蘑菇啊之：mongo系統使用狀況

insert  query update delete getmore command flushes mapped  vsize    res faults  locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn repl       time     *0     *0     *0     *0       0     2|0       0    31g  62.7g   999m      0 young:0.0%          0       0|0     0|0   120b     3k    18  SLV   23:19:57     *0     *0     *0     *0       0     1|0       0    31g  62.7g   999m      0 young:0.0%          0       0|0     0|0    62b     3k    18  SLV   23:19:58     *0     *0     *0     *0       0     8|0       0    31g  62.7g   999m      0 local:0.0%          0       0|0     0|0   468b     5k    18  SLV   23:19:59     *0     *0     *0     *0       0     5|0       0    31g  62.7g   999m      0 young:0.0%          0       0|0     0|0   294b     4k    18  SLV   23:20:00     *1     *0     *0     *0       0     6|0       0    31g  62.7g   999m      0     .:0.1%          0       0|0     0|0   352b     4k    18  SLV   23:20:01     *0     *0     *0     *0       0     2|0       0    31g  62.7g   999m      0 young:0.0%          0       0|0     0|0   120b     3k    18  SLV   23:20:02

 

 

的

 

一段mongodb伺服器讀取資料逾時的故事