mtools-你可能沒用過的mongodb神器

前言接觸 mongodb 已經有一段時間了，從一開始的不瞭解，到現在已慢慢適應這個nosql領域的佼佼者，還是經歷了不少波折。在進行資料庫選型的時候，許多人總是喜歡拿 mongodb和mysql、oracle做比較，並總結出一套非常詳盡的分析結果。但是這種分析往往改變不了管理者(或是架構師)的 ...

前言

接觸 mongodb 已經有一段時間了，從一開始的不瞭解，到現在已慢慢適應這個nosql領域的佼佼者，還是經歷了不少波折。
在進行資料庫選型的時候，許多人總是喜歡拿 mongodb和mysql、oracle做比較，並總結出一套非常詳盡的分析結果。
但是這種分析往往改變不了管理者(或是架構師)的決策。因為往往在決定使用某種技術之前，管理者可能已經有了答案，而分析對比則是為了讓決策更加篤定，更有依據。
儘管這個說法有些令人沮喪，但現實中確實如此。

眾所周知的是，mongodb不是關係型資料庫，不遵循經典的"三個範式"，也沒有表關聯、事務(直到最新的4.0版本才實現)等傳統資料庫的特性。
然而mongodb自帶的無schema、副本集、自動分片等能力獲得了大量的青睞，而更值得一提的是資料庫本身提供了大量的監控、分析工具命令，對運維管理提供了很大的便利性。

既然談到了工具，本文要介紹的是一款叫mtools的工具。在此段期間，筆者一直在組織線上資料庫日誌的收集分析，由於沒有較好的工具支撐，每次的分析工作總需要投入大量的人力。
在這種情況下，mtools 便可以幫助於大幅度提升效率，下麵的篇幅開始介紹這個工具。

mtools是什麼

mtools 是由MongoDB 官方工程師實現的一套工具集，可以很快速的日誌查詢分析、統計功能，此外還支持本地集群部署管理，非常便於新手學習。
github地址，該套工具非官方公司維護，僅由作者做開源維護，目前項目的更新頻度並不高，但已經有大量的使用者。

mtools使用python編寫完成，可通過pipy網站獲取；
該工具包含了以下幾個關鍵組件

mlaunch
支持快速搭建本地測試環境，可以是單機、副本集、分片集群。
mlogfilter
日誌過濾組件，支持按時間檢索慢查詢、全表掃描操作，支持通過多個屬性進行信息過濾，支持輸出為JSON格式。
mplotqueries
支持將日誌分析結果轉換為圖表形式，依賴於tkinter(python圖形模塊)、和matplotlib模塊。
mlogvis
支持將日誌分析結果轉換為一個獨立的HTML頁面，實現與mplotqueries同樣的功能。

網上關於mtools的資料已經不少，包括其官方文檔的說明都比較詳細，這裡僅對工具的使用場景做簡單介紹

可以做什麼

1. 簡易集群管理

執行以下命令，可以啟動一個單節點的mongod進程。

# mlaunch init --single
launching: "mongod" on port 27017

可對比單節點手工搭建

再執行另外一個稍複雜點的命令：

# mlaunch init --sharded 2 --replicaset --nodes 3 --config 3 --csrs --mongos 3 --port 27050 --auth --username admin --password admin@2016 --auth-db admin 
launching: "mongod" on port 27053
launching: "mongod" on port 27054
launching: "mongod" on port 27055
launching: "mongod" on port 27056
launching: "mongod" on port 27057
launching: "mongod" on port 27058
launching: config server on port 27059
launching: config server on port 27060
launching: config server on port 27061
replica set 'configRepl' initialized.
replica set 'shard01' initialized.
replica set 'shard02' initialized.
launching: mongos on port 27050
launching: mongos on port 27051
launching: mongos on port 27052
adding shards. can take up to 30 seconds...
Username "admin", password "admin@2016"

什麼？已經完成了一個雙副本集分片集群的搭建！27050是起始埠，--sharded 2 表示有兩個分片，--replicaset 表示啟用副本集，
--config 3 --csrs 表示config 使用CSRS結構的3節點副本集，--auth 表示啟用鑒權， --username --password 為初始化的用戶，預設該用戶將擁有所有庫的管理許可權。
整個集群的架構如下圖所示：

可以通過以下命令進行管理

]# mlaunch list
PROCESS PORT STATUS PID
()
mongos 27050 running 13017
mongos 27051 running 13059
mongos 27052 running 13093
()
config server 27059 running 12134
config server 27060 running 12217
config server 27061 running 12261
()
shard01
    primary 27053 running 12404
    secondary 27055 running 12559
    mongod 27054 running 12509
()
shard02
    secondary 27057 running 12793
    secondary 27058 running 12845
    mongod 27056 running 12697
()
()
 auth: "admin:admin@2016"

啟動停止

# mlaunch stop
sent signal 15 to 12 processes.
# mlaunch start
launching: config server on port 27059
...

這是相當方便的，可以對比分散式集群搭建手記這篇文章所描述的流程，相比手工搭建，該工具可縮減幾十倍時間。

2. 日誌統計

mloginfo 是一個用於做日誌信息統計的工具，輸入以下命令：

# mloginfo mongo.log
     source: mongo.log
       host: MongoDB_1:10001
        start: 2018 May 18 16:33:11.692
        end: 2018 May 19 01:13:08.290
date format: iso8601-local
     length: 144480
     binary: mongod
    version: 3.4.10
    storage: wiredTiger

可以看到日誌的起止時間範圍、主機埠、版本、資料庫引擎等概要信息。

連接數
當我們希望檢查客戶端的連接數情況時，可以執行以下命令：

# mloginfo mongo.log --connections
CONNECTIONS
     total opened: 14282
     total closed: 14358
    no unique IPs: 4
socket exceptions: 0
127.0.0.1 opened: 12886 closed: 12889
172.21.0.29 opened: 658 closed: 716
172.21.0.28 opened: 461 closed: 490
172.21.0.27 opened: 277 closed: 263

通過這樣的信息，進一步判斷是否存在連接過載等異常情況。

事件統計
又或者，你希望統計出當前某些事件的發生頻次。

# mloginfo mongo.log --distinct
DISTINCT
   14358 end connection ... ( ... now open)
   14281 connection accepted from ... # ... ( ... now open)
   13075 received client metadata from ... :
    5340 Successfully authenticated as principal ... on
    1194 Use of the aggregate command without the 'cursor'
     338 build index on: ... properties:
     244 building index using bulk method; build may temporarily use up to ... megabytes of RAM
     234 ns: ... key: ... name:
     219 Refreshing chunks for collection ... based on version
     218 Refresh for collection ... took ... ms and found version
     179 Index ... :

慢查詢
在業務問題分析中，慢查詢是最常見的問題。

# mloginfo mongo.log --queries --sort count
QUERIES
namespace                  operation      pattern                              count      min (ms)    max (ms)  mean (ms)    95%-ile (ms) sum (ms)
nsspace.StatisticsHour   find             {"$and": [{"recordTime": 1}]..}     22331      276       747          345          414.0            7720736
nsspace.StatisticsHour   getmore       {"aggregate": 1, "cursor": ...}]}    231          200      304          227          272.0             52587
dmspace.DeviceInfo      remove          {"_id": 1}                              109        205      1786          420          771.0            45860
cmspace.DeviceData     update          {"appId": 1, "deviceId": 1}          95          201      1802          431          824.5            40966
dmspace.TaskHistory    update          {"_id": 1}                                54          268      2643          692          2019.0          37413
nsspace.StatisticsDay     find              {"$and": [{"recordTime": 1}], ..}   31          201      348            241          345.0            7472

如上面的命令，將顯示所有慢查詢，並按出現次數排序。

重啟信息

# mloginfo mongo.log --restart
RESTARTS
   May 18 21:37:51 version 3.4.10
   May 18 21:48:33 version 3.4.10

通過檢測重啟信息，對系統潛在的故障進行評估分析。

副本集切換
同樣，主備切換可能導致一定的業務失敗，需要定期監測。

# mloginfo mongo.log --rsstate
RSSTATE
date host state/message
()
May 18 21:48:53 172.21.0.29:10001 ARBITER
May 18 21:49:26 172.21.0.28:10001 SECONDARY

3. 日誌過濾

mlogfilter是一個強大的日誌過濾模塊，相比linux 的grep/egrep的文本過濾，該組件可以對日誌內容進行解析，並按我們想要的結果進行過濾。

查看超過10s的慢操作

# mlogfilter mongo.log --slow 10000 --shorten 200
2018-05-18T21:49:04.069+0800 I REPL [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2018-05-18T21:50:22.988+0800 I COMMAND [conn31] command dmspace.fs.chunks appName: "Mong...quireCount: { w: 46 } }, oplog: { acquireCount: { w: 46 } } } protocol:op_command 10804ms
2018-05-18T21:50:22.988+0800 I COMMAND [conn44] command dmspace.DeviceInfo command: inse...quireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 10931ms
2018-05-18T21:50:22.988+0800 I COMMAND [conn157] command dmspace.Lwm2mDevice command...quireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 10762ms
2018-05-18T21:50:22.988+0800 I COMMAND [conn156] command dmspace.TaskHistory command: in...quireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 10927ms
2018-05-18T21:50:50.104+0800 I COMMAND [conn31] command dmspace.DeviceInfo appName: "Mon...quireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 10020ms
2018-05-18T21:50:51.203+0800 I COMMAND [conn156] command dmspace.fs.chunks command: inse...quireCount: { w: 51 } }, oplog: { acquireCount: { w: 51 } } } protocol:op_command 10823ms

查看慢掃描操作
慢掃描是指該操作需要掃描過多的記錄(超過1w行)，且返回數量不足掃描數量的1/100，這樣的操作通常對CPU消耗很高，也比較低效，

# mlogfilter mongo.log --scan --shorten 200
2018-05-18T21:57:09.123+0800 I COMMAND [conn683] command cmspace.USER_LOGIN_HISTORY command: find ...e: { acquireCount: { r: 95 } }, Collection: { acquireCount: { r: 95 } } } protocol:op_command 556ms
2018-05-18T21:57:17.381+0800 I COMMAND [conn784] getmore nsspace.StatisticsDay query: { aggre...nt: { r: 10 }, timeAcquiringMicros: { r: 1667 } }, Collection: { acquireCount: { r: 890 } } } 214ms
2018-05-18T22:06:16.148+0800 I COMMAND [conn764] getmore nsspace.StatisticsHour query: { aggr...} }, Database: { acquireCount: { r: 69128 } }, Collection: { acquireCount: { r: 69128 } } } 12053ms
2018-05-18T22:06:24.962+0800 I COMMAND [conn764] getmore nsspace.StatisticsHour query: { aggr... } }, Database: { acquireCount: { r: 69106 } }, Collection: { acquireCount: { r: 69106 } } } 8782ms
2018-05-18T22:06:33.787+0800 I COMMAND [conn764] getmore nsspace.StatisticsHour query: { aggr... } }, Database: { acquireCount: { r: 69111 } }, Collection: { acquireCount: { r: 69111 } } } 8822ms

根據名稱空間過濾

# mlogfilter mongo.log --namespace dmspace.DeviceInfo
2018-05-18T21:50:58.105+0800 I COMMAND [conn31] command dmspace.DeviceInfo appName: "MongoDB Shell...adata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 2963ms
2018-05-18T21:50:59.195+0800 I COMMAND [conn31] command dmspace.DeviceInfo appName: "MongoDB Shell...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 936ms
2018-05-18T21:51:00.173+0800 I COMMAND [conn44] command dmspace.DeviceInfo command: insert { inser...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 745ms
2018-05-18T21:51:00.433+0800 I COMMAND [conn44] command dmspace.DeviceInfo command: insert { inser...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 252ms

根據操作類型過濾

# mlogfilter mongo.log --operation update
2018-05-18T21:56:25.114+0800 I WRITE [conn156] update dmspace.PolicyTask query: { _id: "###" } pla...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 2630ms
2018-05-18T21:56:25.114+0800 I WRITE [conn92] update nsspace.TimerTask query: { _id: "###" } planS...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 1264ms
2018-05-18T21:56:25.125+0800 I WRITE [conn43] update dmspace.TaskHistory query: { _id: "###" } pla...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 2643ms
2018-05-18T21:56:30.027+0800 I WRITE [conn532] update dmspace.TaskHistory query: { _id: "###" } pl...eCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 868ms
2018-05-18T21:56:32.115+0800 I WRITE [conn517] update dmspace.TaskHistory query: { _id: "###" } pl...eCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 497ms

獲取某時間點之後1小時的日誌

# mlogfilter mongo.log --from Apr 6 0:00 --to "+1h" | tail -n3
2018-05-19T00:59:59.876+0800 I COMMAND [conn16386] command nsspace.StatisticsHour command: find { find: "###", filter: { user: "###", region: "###", appKey: "###", recordTime: { $lte: "###" }, $and: [ { recordTime: { $gte: "###" } } ] }, shardVersion: [ "###", "###" ] } planSummary: ### keysExamined:249767 docsExamined:249767 cursorExhausted:1 numYields:1952 nreturned:84 reslen:29748 locks:{ Global: { acquireCount: { r: 3906 } }, Database: { acquireCount: { r: 1953 } }, Collection: { acquireCount: { r: 1953 } } } protocol:op_command 319ms
2018-05-19T00:59:59.879+0800 I COMMAND [conn15998] command nsspace.StatisticsHour command: find { find: "###", filter: { user: "###", region: "###", appKey: "###", recordTime: { $lte: "###" }, $and: [ { recordTime: { $gte: "###" } } ] }, shardVersion: [ "###", "###" ] } planSummary: ### keysExamined:249767 docsExamined:249767 cursorExhausted:1 numYields:1954 nreturned:84 reslen:29833 locks:{ Global: { acquireCount: { r: 3910 } }, Database: { acquireCount: { r: 1955 } }, Collection: { acquireCount: { r: 1955 } } } protocol:op_command 321ms

mlogfilter提供了非常靈活的日期條件設置，除了可以指定起始、結束時間之外，還能通過偏移量劃分範圍。

時區轉換

# mlogfilter mongo.log --tiemzone 2 > mongo-correct.log

以上命令將日期調大2個時區，輸出到mongo-correct.log，這在處理國際化系統的場景中非常有用。

更多詳情戳這裡

4. 圖表呈現

mplotqueries 是基於tkinter實現的圖表組件，可以將日誌中扁平的文字信息轉換為圖表形式。
輸入以下命令：

mplotqueries mongo.log --group operations --output-file operations.png

你可以得到一個按操作分組輸出的散點圖，如下圖：

左側的Y軸是duration，即操作的執行時長，下邊的X軸是時間。每個操作在圖中都會有一個描點，因此散點圖會存在許多重疊。
當然，你也可以通過集合名稱進行分組輸出，如下麵的命令：

mplotqueries mongo.log --group namespace --group-limit 20 --type scatter --yaxis nscanned --output-file namespace_nscan.png

輸出的圖表將按名稱空間進行分組(限顯示20個)，y軸為nscanned值，即掃描記錄數量。

預設情況下，y軸的呈現為時長(during)，可指定為其他指標：

指標名稱	說明
nscanned	掃描數
nupdated	更新數
ninserted	插入數
ntoreturn	返回數
numYields	讓步次數
r	讀鎖
w	寫鎖

有時候你並不關係具體的某個操作，而是希望看到某個時間段，某類操作或某個集合的操作占比。
比如每小時，每個集合的操作比例分佈，此時可以採用直方圖

mplotqueries mongo.log --group namespace --bucketsize 3600 --group-limit 10 --type histogram --output-file namespaces_perhour.png

在前面已經講過，連接數的監測工作非常重要，mplotqueries也提供了連接變更統計類型

mplotqueries mongo.log --type connchurn --bucketsize 3600 --output-file connchurn_perhour.png

在大部分情況下，低效的操作往往來自大量的scan掃描，尤其當return數遠小於scan時會更加低效。
可以通過指定 nscanned/n 參數輸出該維度的圖表，即掃描數/返回數

mplotqueries mongo.log --type nscanned/n --group-limit 20 --output-file nscan.png

輸出事件持續圖
往往在跟蹤某一類耗時操作或事件時需要用到，比如oplog的同步、創建索引等，我們希望看到事件的執行時段。
同時還需要伴隨一些操作統計，用於配合做資源監控分析。具體一點就是，你執行了一個耗時操作，在某些情況下對業務訪問可能
產生了影響，如業務訪問超時並伴隨DB伺服器資源的告警，如CPU飆高，在後續的分析中希望通過耗時操作、以及同時段業務訪問的分佈進行綜合分析。

以下的命令展示了一個典型用法

# 創建一個overlay
grep "index" mongo.log | mplotqueries --type durline --overlay
# 疊加overlay輸出圖表
mplotqueries mongo.log --group operation --output-file duration.png

By the way，如果不希望生成那麼多的圖表，mtools還提供了一個偷懶的工具 mlogvis。可以直接生成html頁面，內置強大的腳本
基本上覆蓋了mplotqueries的絕大多數圖表功能。

# mlogvis mongo.log

查看更多用法

希望你已經開始喜歡mtools，並已經躍躍欲試。下麵提供了簡單的安裝方法

如何安裝

由於篇幅所限，這裡僅提供Centos下的安裝方式

準備Python的環境(2.7或3.5)，目前大多數發行版本的linux都包含了python。
如果沒有Python，執行yum install python python-devel 完成安裝
確保pip已經安裝，執行pip進行檢測，如果沒有安裝可參考官方說明進行安裝。
安裝python-tk
執行命令如下：
```
yum install python-tools
```
其他linux系統(如ubuntu/opensuse)則需要安裝python-tk軟體包

安裝依賴模塊

pip install psutil
pip install pymongo
pip install matplotlib
pip install numpy

說明
每個模塊的作用可以參考下表：

模塊名稱	作用
psutil	用於管理進程的工具
pymongo	mongodb python驅動
matplotlib	python的2D圖表渲染模塊
numpy	支持科學計算的工具

安裝mtools
```
pip install mtools
```
至此，你應該獲得了一個已安裝好的mtools環境，如果希望安裝最新的非穩定版本，可以通過源碼安裝

參考文檔

Mongodb乾貨系列-定期巡檢之Mtools
關於mtools的介紹
 mtools安裝指導