早上突然收到配置中心服務告警,Http check出現問題,趕緊訪問下服務看看是否Cabot監控系統的誤報,發現服務時而正常,時而出現500內部服務器錯誤,趕緊排查問題。
1、問題定位
首先看看當前配置中心的總體上報statsd請求量是否出現飆升:
確實負載上來了,先看看應用服務器有沒有報錯,再確定是應用服務問題,還是數據庫的問題:
tail -f logs/log.log
應用服務器出現了一堆"no reachable servers"的報錯,那么說明要么是數據庫掛掉了,要么是出於各種原因無響應。
那就登錄到幾台數據庫服務器上面,看看Mongodb進程,發現進程都還在的,那么再看看master上面的數據庫日志:
ps -ef | grep mongo
發現日志里面出現了一堆的too many open connections: 819這樣的錯誤。
Mongodb默認的最大連接數是819,當連接數到達819后,就無法增加,那么新的請求就無法再連接上去了。
OK,感覺問題很清晰了,時而正常時而出現500錯誤的原因,是因為請求量上來以后,舊的數據庫連接還沒有釋放,新的又創建了,導致觸碰到Mongodb的最大連接數限制。
2、問題處理
那么做兩個方面的調整:
1)Mongodb數據庫的最大連接數改大到20000(Mongodb允許的最大的連接數是20000),避免再次出現最大連接數限制:
vim mongodb.conf
添加:
maxConns=20000
2)在應用里面設置poolLimit,讓mgo盡量多地復用現存的數據庫連接,不要再無限制地增加Mongodb連接了,先設置為單個服務器最大200個連接。
Mgo里面,由於我的Mongodb集群是復制集,無法直接在mongodb的數據庫連接uri里面像這樣添加:
mongodb://xx:xx@10.xx.xx.xx:27017/index-config?maxPoolSize=10
因為我的復制集連接是這樣的:
mongodb://xx:xx@172.19.8.76:27017,172.19.8.77:27017,172.19.9.76:27017,172.19.9.77:27017/index-config?replicaSet=configrs
查下Mgo的官方文檔,看看怎么設置最大連接池數量限制,找到一項SetPoolLimit:
http://godoc.org/gopkg.in/mgo.v2#Session.SetPoolLimit
SetPoolLimit sets the maximum number of sockets in use in a single server before this session will block waiting for a socket to be available. The default limit is 4096.
這里面寫道,默認情況下,Mgo的最大連接數限制是4096,那么當然高過Mongodb默認的最大819限制了,添加限制,先設置為200:
Session.SetPoolLimit(200)
都改好,重啟服務,感覺又要解決一個問題了~
3、出現新的問題
打包、重新部署服務,重新刷新服務,恢復正常。
然而,沒過1分鍾,又收到告警郵件,看下服務,失敗量比之前還多:
納尼?!難道處理問題的姿勢不對?趕緊看看Mongodb 的master服務日志:
tail -f logs/mongodb.log
4、繼續排查問題
看到日志里面頻繁出現大量的Debug 跟Info級別的COMMAND,那么估計是我的日志級別開的不對,先調整下日志級別,關閉Debug級別的各項輸出:
/usr/local/mongodb/bin/mongo mongodb://xxx:xxx@172.19.8.76:27017,172.19.8.77:27017,172.19.9.76:27017,172.19.9.77:27017/admin?replicaSet=configrs
db.setLogLevel(0)
Mongodb里面,LogLevel分為0-5,其中0表示僅開啟Info級別日志,1-5表示Debug級別日志的打印數量,數字越大,打印的越多。
繼續查問題。先看看服務器狀態:
top下看看CPU、負載、內存使用率,這不看不知道,一看嚇了一大跳,CPU使用率居然高達96%,基本都被Mongodb占用了,而服務器負載高達幾百,內存使用率卻還剩下許多(緊急地處理問題,沒有截圖,寶貴的Top結果已經找不到了),說明當前的服務瓶頸出現在CPU。
首先分析是不是頻繁的IO導致服務器CPU消耗過大:
iostat
看到IO並不是CPU高占比的原因。
重新分析一遍問題,先前是時而正常時而有問題,現在的問題比之前更頻繁得多,那么跟第一次修復的連接數肯定有一定關系。
用mongostat看看服務:
/usr/local/mongodb/bin/mongostat --username=xxx --password=xxx --authenticationDatabase=admin
訪問情況基本是正常的。
進入Mongodb看看數據庫連接數:
db.serverStatus().connections
連接數也正常。
再看看網絡狀態,Establish狀態的是否很多:
netstat -anp | grep ESTABLISHED
看到應用服務器確實是有正在處理的連接請求,那么結合上下文,判斷應該是由於限制了最大單台機器200個連接,而申請的速度比釋放的速度快,導致了大量請求阻塞在連接釋放的地方,導致超時報錯。
開啟數據庫慢查詢看看:
db.setProfilingLevel(1,200)
db.system.profile.find()
打印出大量的慢查詢請求,集中在直接查詢用戶信息的user_config集合上面。
配置中心的請求分為兩種,一種是全局統一數據,通過用戶的不同APP版本,IMEI等信息范圍相應數據的灰度版本控制,或者APP配置信息等數據,一種是用戶相關,每個用戶各自讀寫信息的數據。
前一種數據使用的是緩存機制,用戶的請求命中的基本都是緩存;第二種數據太多,無法采用緩存,因此直接讀寫DB,當前來說,也即是user_config集合。
大量慢查詢請求出現在user_config上,說明查詢過慢,但IO明顯不是瓶頸。
這時候我突然想到原本計划上線時候需要做,但還沒做的索引,趕緊補充上去:
db.user_config.ensureIndex({"portal_id":1})
因為每次用戶查詢的索引值都是portal_id,所以僅需要對portal_id做索引。
為防止自己忘記,在代碼里面也添加自動索引的內容:
func init() {
db := mongodb.ConnectMongo()
defer db.Session.Close()
index := mgo.Index{
Key: []string{"portal_id"},
}
db.C(CollectionUserConfig).EnsureIndex(index)
}
Mongodb里面,如果不添加索引,對Mongodb數據表進行查詢操作的時候,需要把數據都加載到內存。當數據的數量達到幾十萬乃至上百萬的時候,這樣的加載過程會對系統造成較大的沖擊,並影響到其他請求的處理過程。
用戶表當前的記錄數量已經達到45萬,每次都加載這么多數據,查詢起來肯定是非常慢的。建立索引以后對索引字段進行查詢時,僅會加載索引數據,能極大地提高查詢速度。
添加索引以后,很快收到了服務恢復的郵件:
配置中心 RECOVERY.
再訪問服務,正常了!
本文引用:https://chen-kaka.github.io/problems/2017/08/21/Mongodb%E6%9F%A5%E8%AF%A2%E7%BC%93%E6%85%A2%E9%97%AE%E9%A2%98%E5%A4%84%E7%90%86/