排查MongoDB CPU使用率高的問題
1.公司業務調整，把一部分數據由Redis轉至MongoDB，業務在測試環境正常，生產環境上線後發現壓力一上來MongoDB的服務直接把CPU佔滿了，和開發的同窗分析了一下也參考了一下百度上相似的問題，最後定位緣由：未使用索引。css
解決方法很簡單：對應的關鍵字段建立索引便可。linux
參考命令以下： mongodb
>use Data; #進入數據庫Data，注意區分大小寫；shell
>db.stats(); #查看數據庫的狀態；數據庫
>db.getCollectionNames(); #查看全部表名；服務器
>db.dynamic.find().limit(5); #查看dynamic表的前5條數據；app
>db.dynamic.find().count(); #統計dynamic表總共有多少數據；tcp
>db.dynamic.getIndexes(); #查詢表dynamic的索引測試
#新建索引：對dynamic的score字段以backgroud方式創建索引優化
>db.dynamic.ensureIndex({score:1} , {backgroud:true});
#狀態查看：20秒，每秒更新一次
mongostat -h 80.81.2.3 -p 27017 --rowcount 20 1
mingotop -h 80.81.2.3 -p 27017 --rowcount 20 1
開始建立索引的字段沒找準，效果不明顯，後來對關鍵字段建立索引後CPU使用率斷崖式下跌。
分析MongoDB數據庫正在執行的請求
- 經過Mongo Shell鏈接實例。
- 執行
db.currentOp()命令，查看數據庫當前正在執行的操做。
分析MongoDB數據庫的慢請求
雲數據庫MongoDB默認開啓了慢請求Profiling ，系統自動地將請求時間超過100ms的執行狀況記錄到對應數據庫下的system.profile集合裏。
- 經過 Mongo Shell 鏈接實例。
- 經過
use <database>命令進入指定數據庫。use mongodbtest - 執行以下命令，查看該數據下的慢請求日誌。
db.system.profile.find().pretty() - 分析慢請求日誌，查找引發MongoDB CPU使用率升高的緣由。
如下爲某個慢請求日誌示例，可查看到該請求進行了全表掃描，掃描了11000000個文檔，沒有經過索引進行查詢。
{ "op" : "query", "ns" : "123.testCollection", "command" : { "find" : "testCollection", "filter" : { "name" : "zhangsan" }, "$db" : "123" }, "keysExamined" : 0, "docsExamined" : 11000000, "cursorExhausted" : true, "numYield" : 85977, "nreturned" : 0, "locks" : { "Global" : { "acquireCount" : { "r" : NumberLong(85978) } }, "Database" : { "acquireCount" : { "r" : NumberLong(85978) } }, "Collection" : { "acquireCount" : { "r" : NumberLong(85978) } } }, "responseLength" : 232, "protocol" : "op_command", "millis" : 19428, "planSummary" : "COLLSCAN", "execStats" : { "stage" : "COLLSCAN", "filter" : { "name" : { "$eq" : "zhangsan" } }, "nReturned" : 0, "executionTimeMillisEstimate" : 18233, "works" : 11000002, "advanced" : 0, "needTime" : 11000001, "needYield" : 0, "saveState" : 85977, "restoreState" : 85977, "isEOF" : 1, "invalidates" : 0, "direction" : "forward", ....in" } ], "user" : "root@admin" }
一般在慢請求日誌中，您須要重點關注如下幾點。
- 全表掃描（關鍵字： COLLSCAN、 docsExamined ）
- 全集合（表）掃描COLLSCAN 。
當一個操做請求（如查詢、更新、刪除等）須要全表掃描時，將很是佔用CPU資源。在查看慢請求日誌時發現COLLSCAN關鍵字，極可能是這些查詢佔用了你的CPU資源。說明 若是這種請求比較頻繁，建議對查詢的字段創建索引的方式來優化。
- 經過查看docsExamined的值，能夠查看到一個查詢掃描了多少文檔。該值越大，請求所佔用的CPU開銷越大。
- 全集合（表）掃描COLLSCAN 。
- 不合理的索引（關鍵字： IXSCAN、keysExamined ）
經過查看keysExamined字段，能夠查看到一個使用了索引的查詢，掃描了多少條索引。該值越大，CPU開銷越大。
若是索引創建的不太合理，或者是匹配的結果不少。這樣即便使用索引，請求開銷也不會優化不少，執行的速度也會很慢。
以下所示，假設某個集合的數據，x字段的取值不多（假設只有一、2），而y字段的取值很豐富
{ x: 1, y: 1 }{ x: 1, y: 2 } { x: 1, y: 3 } ...... { x: 1, y: 100000} { x: 2, y: 1 } { x: 2, y: 2 } { x: 2, y: 3 } ...... { x: 1, y: 100000}要實現 {x: 1, y: 2} 這樣的查詢。
db.createIndex( {x: 1} ) 效果很差，由於x相同取值太多 db.createIndex( {x: 1, y: 1} ) 效果很差，由於x相同取值太多 db.createIndex( {y: 1 } ) 效果好，由於y相同取值不多 db.createIndex( {y: 1, x: 1 } ) 效果好，由於y相同取值少關於{y: 1} 與 {y: 1, x: 1} 的區別，可參考MongoDB索引原理及複合索引官方文檔。
- 大量數據排序（關鍵字： SORT、hasSortStage ）
-
當查詢請求裏包含排序的時候， system.profile 集合裏的 hasSortStage 字段會爲 true 。若是排序沒法經過索引知足， MongoDB 會在查詢結果中進行排序。而排序這個動做將很是消耗CPU資源，這種狀況須要對常常排序的字段創建索引的方式進行優化。
- 鏈接數
一、mongodb最大的鏈接數是819，在啓動裏面加參數 --maxConns=3000重啓mongodb服務後最大鏈接數仍是819。
二、實際上是linux系統的限制，Linux系統默認一個進程最大文件打開數目爲1024。須要修改此限制
三、由於將mongodb添加到開機啓動裏面，須要在rc.local文件下面加ulimit -n 的限制
vi /etc/rc.local
ulimit -n 20000
rm /usr/mongodb/log/mongodb.log
/usr/mongodb/bin/mongod --dbpath=/usr/mongodb/data/ --logpath=/usr/mongodb/log/mongodb.log --master --oplogSize 200
而後重啓機器再次查看mongodb的最大鏈接數發現變了
[root@DB192168129044 bin]# ./mongo
MongoDB shell version: 2.2.0
connecting to: test
> db.serverStatus（）。connections;
{ 「current」 : 1, 「available」 : 15999 }
MongoDB的CPU使用率高最佳實踐
問題症狀
mongodb 實例在平常使用中，有時會出現 CPU使用達到 80%以上 的狀況。
問題緣由
一、耗時的請求
1.一、全表掃描
關鍵字：COLLSCAN、 docsExamined
1.二、不合理的索引
關鍵字：IXSCAN、keysExamined
1.三、大量數據排序
關鍵字：SORT、hasSortStage
二、服務器能力達到上限
整個數據庫的查詢很是合理，全部的請求都是高效的走了索引，基本沒有優化的空間了，就是機器的服務能力已經達到上限了，應該升級配置了
三、服務器被攻擊
經過分析端口鏈接數，來源IP，日誌確認來源IP的訪問內容
3.1 查看端口鏈接數
[root@MONGO-17 ~]# netstat -anp | grep 22001 | wc -l
3.2 查看端口鏈接來源IP
[root@MONGO-17 ~]# netstat -n | grep 22001 |awk '/^tcp/ {print $5}'| awk -F: '{print $1}' | sort | uniq -c | sort -rn
3.3 查看日誌來源IP是什麼程序訪問
[root@mnkj-db02 data]# netstat -anp | egrep 120.78.231.86:5[0-9]* tcp 50 0 120.78.231.86:55402 106.11.68.13:80 ESTABLISHED 21343/wrapper
排查步驟
一、資源查看
1.1 佔用CPU高的進程
[root@MONGO-17 ~]# top top - 10:04:09 up 131 days, 17:30, 1 user, load average: 3.85, 2.97, 2.81 Tasks: 189 total, 1 running, 188 sleeping, 0 stopped, 0 zombie %Cpu0 : 35.6 us, 2.4 sy, 0.0 ni, 61.7 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu1 : 37.7 us, 3.3 sy, 0.0 ni, 58.7 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu2 : 59.5 us, 4.1 sy, 0.0 ni, 36.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu3 : 32.6 us, 3.4 sy, 0.0 ni, 64.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu4 : 38.7 us, 3.4 sy, 0.0 ni, 57.6 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu5 : 32.9 us, 2.4 sy, 0.0 ni, 64.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu6 : 44.0 us, 2.7 sy, 0.0 ni, 53.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu7 : 42.4 us, 3.7 sy, 0.0 ni, 53.6 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu8 : 45.1 us, 3.4 sy, 0.0 ni, 51.2 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu9 : 66.9 us, 5.4 sy, 0.0 ni, 27.4 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st %Cpu10 : 35.8 us, 3.4 sy, 0.0 ni, 60.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu11 : 34.3 us, 3.5 sy, 0.0 ni, 59.2 id, 0.0 wa, 0.0 hi, 3.1 si, 0.0 st %Cpu12 : 37.5 us, 2.7 sy, 0.0 ni, 59.8 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu13 : 45.3 us, 3.7 sy, 0.0 ni, 51.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu14 : 68.9 us, 2.7 sy, 0.0 ni, 28.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu15 : 43.6 us, 2.7 sy, 0.0 ni, 53.4 id, 0.0 wa, 0.0 hi, 0.3 si, 0.0 st KiB Mem : 32780412 total, 274896 free, 20882888 used, 11622628 buff/cache KiB Swap: 0 total, 0 free, 0 used. 11440020 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 24406 root 20 0 28.204g 0.018t 5976 S 919.6 58.4 477312:14 mongod 24297 root 20 0 3008300 1.148g 6456 S 0.7 3.7 1354:41 mongod 7823 zabbix 20 0 15372 1028 804 S 0.3 0.0 3:46.26 zabbix_agentd
1.2 肯定佔用CPU高的進程和線程
# 獲取進程id 24406 [root@MONGO-17 ~]# ps -ef | grep 24406 /opt/mongodb/bin/mongod --shardsvr --replSet shard17 --port 22001 --dbpath /data/mongodb/shard1/data --auth --keyFile=/opt/mongodb/key/authfile --logpath /data/mongodb/shard1/logs/shard.log --fork # 查看進程的線程top -p 24406 按 shift+h 查看cpu高的線程，查找線程點用cpu高且cpu時間很長 [root@MONGO-17 tmp]# top -p 24406 top - 13:44:28 up 131 days, 21:10, 2 users, load average: 1.19, 2.34, 2.17 Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie %Cpu(s): 1.4 us, 0.2 sy, 0.0 ni, 98.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 32780412 total, 3806372 free, 20931264 used, 8042776 buff/cache KiB Swap: 0 total, 0 free, 0 used. 11391328 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 24406 root 20 0 28.199g 0.018t 5772 S 23.6 58.5 477924:55 mongod top - 13:46:33 up 131 days, 21:13, 2 users, load average: 3.11, 2.37, 2.18 Threads: 812 total, 5 running, 807 sleeping, 0 stopped, 0 zombie %Cpu(s): 31.7 us, 1.2 sy, 0.0 ni, 67.0 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0 st KiB Mem : 32780412 total, 3767812 free, 20957716 used, 8054884 buff/cache KiB Swap: 0 total, 0 free, 0 used. 11363284 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 25421 root 20 0 28.348g 0.018t 5772 R 95.4 58.5 4544:58 conn173 14810 root 20 0 28.255g 0.021t 5592 R 99.7 67.3 0:11.06 conn3223924 2360 root 20 0 28.255g 0.021t 5592 R 93.0 67.3 133:33.64 conn3118924 11174 root 20 0 28.255g 0.021t 5592 R 46.5 67.3 182:49.85 conn3125456 1514 root 20 0 28.255g 0.021t 5592 S 41.2 67.3 191:05.51 conn3118283 15026 root 20 0 28.255g 0.021t 5592 R 28.9 67.3 159:31.74 conn3128335 11941 root 20 0 28.218g 0.018t 5776 R 99.7 58.7 0:25.09 conn3221759 12277 root 20 0 28.218g 0.018t 5776 R 99.7 58.7 0:11.82 conn3222028
1.3 分析佔用CPU高的線程ID執行內容
# 獲取12月14號00:00pm 到12月14號07:30pm執行超過1000ms查詢 [root@MONGO-17 tmp]# mlogfilter /data/mongodb/shard1/logs/shard.log --slow 1000 --from 2017-12-14 00:00 --to 2017-12-14 7:30 > /tmp/121400_07.log # 截取線程ID 25421的線程執行的內容 [root@MONGO-17 tmp]# sed -n '/\[conn173\]/p' 121400.log 2017-12-14T14:00:56.590+0800 W COMMAND [conn173] Use of the aggregate command without the 'cursor' option is deprecated. See http://dochub.mongodb.org/core/aggregate-without-cursor-deprecation.
1.4 分析mongodb shard.log日誌
#安裝mtools
# 獲取12月13號凌晨開始執行超過1000ms的前20條查詢，結果見附件《121300_20.txt》
[root@MONGO-17 logs]# mlogfilter shard.log --from 2017-12-13 0:00 --slow 1000 | head -n20 > /tmp/121300_20.txt
# 獲取日誌基本信息
[root@MONGO-17 logs]# mloginfo shard.log
source: shard.log
host: MONGO-17:22001
start: 2017 Sep 12 01:08:48.487
end: 2017 Dec 14 10:15:56.643
date format: iso8601-local
length: 33471780
binary: mongod
version: 3.4.7
storage: wiredTiger
# 獲取12月11號凌晨開始語句的執行次數、用時等統計信息
[root@MONGO-17 logs]# mlogfilter shard.log --from 2017-12-11 0:00 > /tmp/121100.log
[root@MONGO-17 tmp]# mloginfo 121100.log --queries > /tmp/queries.txt
[root@MONGO-17 tmp]# head -n 20 queries.txt
二、分析mongodb統計數據
2.1 monogtop 統計信息
[root@MONGO-17 tmp]# /opt/mongodb/bin/mongotop -h 127.0.0.1:22001 -udbadmin -pxxx --authenticationDatabase=admin 2017-12-14T11:30:39.461+0800 Failed: error connecting to db server: server returned error on SASL authentication step: Authentication failed.
該用戶沒法在admin庫下認證成功，當前只對mongos開啓了認證
2.2 mongostat統計信息
2.3 mongodb 狀態查看
[root@MONGO-16 ~]# echo 'db.serverStatus().connections' | /opt/mongodb/bin/mongo 127.0.0.1:27017/admin -udbadmin -puRqVxwYflphBgOH
MongoDB shell version v3.4.7
connecting to: mongodb://127.0.0.1:27017/admin
MongoDB server version: 3.4.7
{ "current" : 1564, "available" : 50864, "totalCreated" : 116536 }
3、擴展信息
- mongotop能夠查看MongoDB實例花銷在讀數據或寫數據上的時間，它提供集合級別的統計數據
- mongostat是提供數據庫級別的統計數據
4、建議
- 由分析mongodb的shard日誌，omdmain.item_region、stock.region_product_inventory、order.order集合find操做關鍵字：IXSCAN，走不合理的索引以及執行count操做時間過長致使CPU飆高的主要緣由。
- 建議調整索引繼續觀察
相關文章
- 1. 【生產問題】線上CPU使用率過高問題排查
- 2. java應用cpu使用率太高問題排查
- 3. linux上Java應用的CPU佔用率高的問題排查
- 4. CPU使用率高排查思路
- 5. Java進程CPU使用率高排查
- 6. 故障排查——CPU使用率過高
- 7. CPU使用率過高排查
- 8. cpu使用率飆高排查過程
- 9. cpu過高問題排查
- 10. CPU高問題排查
- 更多相關文章...
- • Redis悲觀鎖解決高併發搶紅包的問題 - 紅包項目實戰
- • Redis樂觀鎖解決高併發搶紅包的問題 - 紅包項目實戰
- • 使用Rxjava計算圓周率
- • Composer 安裝與使用
相關標籤/搜索
每日一句
-
每一个你不满意的现在，都有一个你没有努力的曾经。
最新文章
- 1. CVPR 2020 論文大盤點-光流篇
- 2. Photoshop教程_ps中怎麼載入圖案？PS圖案如何導入？
- 3. org.pentaho.di.core.exception.KettleDatabaseException:Error occurred while trying to connect to the
- 4. SonarQube Scanner execution execution Error --- Failed to upload report - 500: An error has occurred
- 5. idea 導入源碼包
- 6. python學習 day2——基礎學習
- 7. 3D將是頁遊市場新賽道？
- 8. osg--交互
- 9. OSG-交互
- 10. Idea、spring boot 圖片(pgn顯示、jpg不顯示)解決方案
歡迎關注本站公眾號,獲取更多信息
相關文章
- 1. 【生產問題】線上CPU使用率過高問題排查
- 2. java應用cpu使用率太高問題排查
- 3. linux上Java應用的CPU佔用率高的問題排查
- 4. CPU使用率高排查思路
- 5. Java進程CPU使用率高排查
- 6. 故障排查——CPU使用率過高
- 7. CPU使用率過高排查
- 8. cpu使用率飆高排查過程
- 9. cpu過高問題排查
- 10. CPU高問題排查