是什麼造成了數據庫的卡頓
- 2019 年 10 月 20 日
- 筆記
聲明：本文同步發表於 MongoDB 中文社區，傳送門：
http://www.mongoing.com/archives/26201
一、背景
MongoDB 提供了非常強大的性能分析及監控的命令，諸如 mongostat、mongotop 可以讓我們對數據庫的運行態性能了如指掌。
然而，這次我們在性能環境上就遇到一個非常棘手的問題：
某服務接口在 1-5分鐘內偶現超時導致業務失敗！
在接口調用上返回超時屬於前端的判斷，通常是設置的一個閾值(比如 3s)。
由於問題是偶現，且沒辦法發現有明顯的規律，很難直接判斷出原因。
而平台在做了微服務拆分之後，問題定位的難度加大了不少，且當前的調用鏈功能也不夠完善。
二、問題定界
業務診斷
在一番分析後，梳理出接口調用的關係圖如下：
其中，服務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 關閉，業務的慢操作完全消失了。
三、找出元兇
經過前面的問題定位，我們已經能確定是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
四、解決思路
在了解了事情的來龍去脈之後，我們可以確定這是 MongoDB 3.4 版本的一個不嚴謹的實現導致的問題。
由於無法直接升級整個數據庫版本(代價太大), 我們在監控程序上做了優化，即將 listCollections 結果進行了緩存，避免定時器每次都去操作這個命令，而問題最終得到了解決。
"監控不是銀彈，濫用也會有坑"，至少從這次的事件中，我們得到了一個教訓！
而要在這個問題上舉一反三的話，那就是需要警惕一些數據庫操作潛在的鎖問題了，比如：
- 創建索引(默認Foreground模式)，會對數據庫產生寫鎖(X)，所以一定要用Background模式
- 刪除集合，dropCollection，會對數據庫產生寫鎖(X)，謹慎！
- MapReduce操作，會對數據庫產生讀鎖(S)和寫鎖(X)，謹慎！
- 連接鑒權，db.auth()，會對admin庫產生讀鎖，而admin是庫級鎖。
以上的這些事情，你 Get 到了嗎？
