Mongodb

MongoDB 中的一個數據庫突然獲得高鎖定百分比

  • July 4, 2015

我觀察到單個數據庫的 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

如您所見,鎖定期間的工作負載之間沒有顯著差異。兩者都dbdb_2不斷查詢,db混合了插入/更新/查找/刪除工作負載,而db_2僅使用upsert. 我正在嘗試分析查詢,但預測下一次鎖定的機會太低。

你知道這種麻煩的原因嗎?

UPD:我意識到 MongoDB 在滯後之前釋放了大量記憶體:

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.

引用自:https://dba.stackexchange.com/questions/80569