MongoDB 中的一個數據庫突然獲得高鎖定百分比
我觀察到單個數據庫的 MongoDB 集群中可重複的、突然的、短時間的
update
查詢速度變慢。這種減速持續約 30 秒,每天重複幾次。我發現了這一點,
lock %
並且page faults
在這個時刻達到了頂峰:
我跑過去
mongostat
看看,發生了什麼事。這是我得到的:insert query update delete getmore command flushes mapped vsize res faults locked db idx miss % qr|qw ar|aw netIn netOut conn set repl time 55 2166 2607 20 972 1408|0 0 440g 895g 26.3g 156 db:18.4% 0 4|0 0|0 1m 3m 10009 rs_1 PRI 20:28:16 39 2103 2431 12 985 1815|0 0 440g 895g 26.3g 136 db:13.7% 0 6|0 2|1 1m 2m 10009 rs_1 PRI 20:28:17 84 2097 2646 18 985 1832|0 0 440g 895g 26.3g 140 db:16.5% 0 0|0 1|0 1m 3m 10009 rs_1 PRI 20:28:18 59 2225 2700 19 989 1854|0 0 440g 895g 26.3g 157 db:18.0% 0 12|0 3|2 1m 3m 10009 rs_1 PRI 20:28:19 61 2065 2484 20 980 1787|0 0 440g 895g 26.3g 156 db:15.8% 0 9|0 0|0 1m 5m 10009 rs_1 PRI 20:28:20 86 2134 2660 24 946 1773|0 0 440g 895g 26.4g 393 db_2:118.7% 0 15|0 0|1 1m 3m 10009 rs_1 PRI 20:28:21 70 2113 2665 21 914 1719|0 0 440g 895g 26.4g 246 db_2:190.9% 0 18|0 0|1 1m 3m 10009 rs_1 PRI 20:28:22 72 2118 2671 24 920 1745|0 0 440g 895g 26.4g 310 db_2:193.9% 0 27|0 1|1 1m 2m 10009 rs_1 PRI 20:28:23 63 2127 2529 25 927 1720|0 0 440g 895g 26.4g 326 db_2:191.3% 0 55|0 1|1 1m 4m 10009 rs_1 PRI 20:28:24 59 2162 2754 22 845 1572|0 0 440g 895g 26.4g 251 db_2:191.4% 0 61|0 1|1 1m 2m 10009 rs_1 PRI 20:28:25 61 2186 2662 23 910 1676|0 0 440g 895g 26.4g 264 db_2:192.3% 0 87|2 3|3 1m 2m 10009 rs_1 PRI 20:28:26 79 2231 2642 26 908 1736|0 0 440g 895g 26.3g 227 db_2:190.7% 0 87|0 0|1 1m 2m 10009 rs_1 PRI 20:28:27 66 2310 2705 24 912 1740|0 0 440g 895g 26.3g 275 db_2:191.4% 0 97|0 0|2 1m 2m 10009 rs_1 PRI 20:28:28 56 2259 2640 22 920 1758|0 0 440g 895g 26.3g 345 db_2:190.6% 0 126|1 0|1 1m 3m 10009 rs_1 PRI 20:28:29 78 2513 2745 31 948 1768|0 0 440g 895g 26.3g 267 db_2:189.1% 0 136|0 0|1 1m 3m 10009 rs_1 PRI 20:28:30 ... 52 2361 2738 21 926 1753|0 0 440g 895g 26.4g 149 db_2:189.8% 0 14|0 0|1 1m 2m 10009 rs_1 PRI 20:28:57 45 2321 2570 13 921 1703|0 0 440g 895g 26.4g 161 db_2:190.2% 0 7|0 0|1 1m 3m 10009 rs_1 PRI 20:28:58 57 2329 2716 21 972 1841|0 0 440g 895g 26.4g 151 db:15.8% 0 1|0 0|4 1m 3m 10009 rs_1 PRI 20:28:59
如您所見,鎖定期間的工作負載之間沒有顯著差異。兩者都
db
被db_2
不斷查詢,db
混合了插入/更新/查找/刪除工作負載,而db_2
僅使用upsert
. 我正在嘗試分析查詢,但預測下一次鎖定的機會太低。你知道這種麻煩的原因嗎?
UPD:我意識到 MongoDB 在滯後之前釋放了大量記憶體:
之後,它將數據映射回來。我覺得很奇怪,繼續尋找原因。
UPD2:檢查
workingSet
並發現它現在完全適合記憶體:866 721 頁 * 4 KB/頁 ~ 3.3 GB 與節點上可用的 62 GB 記憶體。
鎖定峰值與 MMS 中的頁面錯誤峰值同時出現,這意味著在那段時間(看起來很短暫),有數據被分頁到磁碟外(即:不在記憶體中)。既然你提到你正在做更新,我猜想在那個時間範圍內的更新會觸及不再在記憶體中的數據的一個很少使用的部分(核心使用LRU來決定什麼留在記憶體中)。另一種可能性是,由於某些其他活動,您在此之前正在逐出 db2 頁面,然後嘗試再次使用該數據(即經典記憶體爭用)。
為了更好地了解這一點,您可以在比較前後使用mongoem 之類的東西進行比較,但這可能無法告訴您導致這種情況的使用模式是什麼,除非受影響的數據具有指示性。
在使用方面,隨著鎖定百分比達到更高的值,您應該會看到在此期間日誌文件中偶爾記錄的緩慢操作。如果不是,那麼可能會將您的slowms值從 100 毫秒預設值降低一點(例如 50 毫秒),然後查看是否有任何記錄。您可以在不重新啟動且不使用分析本身的情況下執行此操作,方法
db.setProfilingLevel()
如下:db.setProfilingLevel(0, 50)
這比完整分析的影響要小,您可以將其保留更長的時間以擷取緩慢的操作,儘管它會導致您的日誌文件更大,因此如果事情緊張,請注意日誌的磁碟空間。
為了幫助過濾和視覺化日誌文件,我強烈建議使用mtools,儘管通常的嫌疑人,如,
grep
等也都可以使用。與往常一樣,請注意誤報 - 高鎖定可能會導致其他定期執行的操作(如)顯示為緩慢。它們大部分時間都是症狀而不是原因,它們之所以出現是因為它們正在連續執行並且可能被繁忙的數據庫或高鎖阻塞。awk``sed``db.serverStatus()
問題的原因是錯誤的索引選擇。不知何故,Mongo 選擇了錯誤的索引並使用了 20-40 秒。不確定是否是由記憶體刷新引起的。很少有記錄大
nscanned
的慢日誌。我們用planCacheSetFilter
.