是什麼形成了數據庫的卡頓

目錄

• 1、背景
• 2、問題定界
• 3、找出元兇
• 4、解決思路

聲明：本文同步發表於 MongoDB 中文社區，傳送門：
http://www.mongoing.com/archives/26201

1、背景

MongoDB 提供了很是強大的性能分析及監控的命令，諸如 mongostat、mongotop 可讓咱們對數據庫的運行態性能瞭如指掌。
然而，此次咱們在性能環境上就遇到一個很是棘手的問題：

某服務接口在 1-5分鐘內偶現超時致使業務失敗！

在接口調用上返回超時屬於前端的判斷，一般是設置的一個閾值(好比 3s)。
因爲問題是偶現，且沒辦法發現有明顯的規律，很難直接判斷出緣由。
而平臺在作了微服務拆分以後，問題定位的難度加大了很多，且當前的調用鏈功能也不夠完善。

2、問題定界

業務診斷

在一番分析後，梳理出接口調用的關係圖以下：

其中，服務A 經過 RPC調用服務B的接口，而服務B 又經過 MongoDB 進行數據讀寫。
MongoManager 是 用於管理 MongoDB 的一個代理服務，主要是實現一些數據備份、監控的任務。

在採集了一些數據以後，咱們基本把問題範圍鎖定到了 MongoDB 數據庫上面，這些手段包括：

• 經過對服務A、服務B的接口監控進行觀測
• 經過wiredshark 抓包，分析 DB讀寫上的響應包時延
• 經過CommandListener，將1s 以上的慢操做指標進行輸出

從接口監控及 wiredshark 抓包結果中確認到，DB 操做的響應時間都出現了偶現的超長(3s以上)。
而經過 CommandListener 將慢操做輸出統計後，獲得的圖表以下：

其中典型的慢操做語句如：

update app.BussinessData query: { snId: "c1190522-6b6f-9192-b40a-6665ba2b2tta" } update: { $set: { taskInfo.state: "Running", lastModifiedTime: new Date(1531857361579) } } 

然而，這些慢操做並無明顯的問題嫌疑，除了以寫操做爲主以外，索引的命中也沒有問題。

數據庫診斷

接下來，咱們將焦點集中到了數據庫上，檢查了 cpu、內存、網絡、磁盤這些常規指標後並無發現什麼異常。
經過 mongostat 觀察到的以下圖：

圖- mongostat

其中的一個異常點是 netout 會有偶現的積壓狀況。
而後是嘗試經過 db.currentOp() 這個命令來看看能不能揪出慢操做背後的元兇。

currentOp 仍是比較好用的，尤爲是在定位一些長時間慢操做問題上

然而，個人想法落空了，這個辦法並無任何發現！ 由於問題屬於偶現，因此執行currentOp 須要一些好的運氣..
儘管如此，咱們仍是大概能斷定，在出現慢操做的時候，數據庫出現了命令積壓(卡頓)的狀況

基於上面的這些診斷信息，咱們仍是沒辦法直接得出結論，可是你們都作出來一致的猜想：

"可能存在某個定時器的鎖，對業務操做產生了阻塞！"

那麼，鎖從哪裏來？ 咱們將目光移向了 MongoManager，的確這個程序承載了許多管理上的功能，包括監控、備份、升級這些雜事..
其中，執行數據庫信息採集的監控定時器存在最大的嫌疑！，那麼問題又來了，

"若是是定時器致使的卡頓，爲何慢操做卻沒有定時產生的規律呢？"

這個問題在前面也對咱們產生了很大的困擾，但一個比較合理的解釋是：

"MongoManager 是多節點的，而其中定時器是按照 時間間隔來運做的，而不是整點觸發。"
這樣就能解釋，爲何慢操做一般都是在1-5分鐘內不規律的出現了。
爲了證明這個想法，咱們直接將 MongoManager 逐個關閉到僅剩下一個，最終經過CommandListener收集到的慢操做圖表以下：

看，此次的慢操做很是的規律，基本每5分鐘就會出現一次卡頓！
而後咱們將所有的 MongoManager 關閉，業務的慢操做徹底消失了。

3、找出元兇

通過前面的問題定位，咱們已經能肯定是MongoManager的定時器搞的鬼了。
接下來走讀代碼，發現有下面這樣的一段實現：

public void testDbOperation() { try { MongoClient client = getClient(); MongoDatabase database = client.getDatabase("thisdb"); List<String> allCollections = new ArrayList<>(); //get all collections MongoCursor<String> iCollection = database.listCollectionNames().iterator(); while (iCollection.hasNext()) { allCollections.add(iCollection.next()); } if (allCollections.isEmpty()) { return; } //test a random collection String randomCollection = allCollections.get((int) (allCollections.size() * Math.random())); //issue find operation database.getCollection(randomCollection).find().first(); } catch (Exception e) { throw new DBMonitException("the db find test failed..", e); } }

爲了便於理解，上述的代碼作了比較多的簡化，大體的步驟是：

• 經過 listCollections 獲取數據庫的所有集合；
• 隨機選取一個集合，執行findOne操做；
• 一旦發現操做失敗，產生異常(告警)

上述的代碼由定時器在5分鐘觸發一次，跟出現慢操做的條件是吻合的。
其中 listCollections 會獲取到一個集合的列表，咱們猜想，這個操做可能會阻塞數據庫的操做。

經過搜索官方文檔，咱們發現該操做使用了一個共享讀鎖(S)：

圖-listCollection鎖

MongoDB 鎖機制

爲了說明阻塞的產生，這裏須要解釋下MongoDB的鎖機制：

在數據庫內部有下面這幾種鎖：

• 寫鎖(X)，對某個文檔或數據庫對象進行寫時加鎖
• 讀鎖(S)，對某個文檔或數據庫對象進行讀取時加鎖
• 意向寫鎖(IX)，對文檔寫操做時，對集合及數據庫產生意向寫鎖
• 意向讀鎖(IS)，對文檔讀操做時，對集合及數據庫產生意向讀鎖

意向鎖提供了數據庫系統的"多粒度鎖"的能力，是提高併發能力的關鍵手段， WiredTiger 也是基於此來實現行級鎖的。
幾種鎖的互斥關係以下表所示：

鎖類型	S	X	IS	IX
S	T	F	T	F
X	F	F	F	F
IS	T	F	T	T
IX	F	F	T	T

基於此，咱們能夠得出這樣的結論：

由定時器產生 的 listCollections 操做會對數據庫產生讀鎖(S)，從而對文檔寫操做(數據庫的意向寫鎖IX)產生了阻塞。

那麼，listCollections 從監控的意義上來看是不該該對數據庫產生阻塞的。
咱們認爲這應該是 MongoDB 3.4 版本一個Bug，而SERVER-34243 這裏提交的一個Issue已經獲得解決。
在最新的 4.x版本文檔中，能夠發現 listCollections 的權限已經變動成了 意向讀鎖(IS)。

經過 4.0 版本的 ReleaseNotes 能夠確認這點：

The command listCollections takes Intent Shared lock on the database. In previous versions, the command takes Shared lock on the database.

連接： https://docs.mongodb.com/manual/release-notes/4.0/index.html

4、解決思路

在瞭解了事情的前因後果以後，咱們能夠肯定這是 MongoDB 3.4 版本的一個不嚴謹的實現致使的問題。
因爲沒法直接升級整個數據庫版本(代價太大), 咱們在監控程序上作了優化，即將 listCollections 結果進行了緩存，避免定時器每次都去操做這個命令，而問題最終獲得瞭解決。

"監控不是銀彈，濫用也會有坑"，至少從此次的事件中，咱們獲得了一個教訓！
而要在這個問題上觸類旁通的話，那就是須要警戒一些數據庫操做潛在的鎖問題了，好比：

• 建立索引(默認Foreground模式)，會對數據庫產生寫鎖(X)，因此必定要用Background模式
• 刪除集合，dropCollection，會對數據庫產生寫鎖(X)，謹慎！
• MapReduce操做，會對數據庫產生讀鎖(S)和寫鎖(X)，謹慎！
• 鏈接鑑權，db.auth()，會對admin庫產生讀鎖，而admin是庫級鎖。

以上的這些事情，你 Get 到了嗎？