DAY21 MongoDB Profiler 如何監控效能差的操作

有處理過資料庫效能問題的大概都知道 profiler 是什麼，MongoDB 也有這個功能。開啟此功能狀態下，會對資料庫效能有影響，至於多少還是需要多觀察與測試。

Profiler 是一個蒐集所有 MongoDB 操作細節的工具，除了一般的 CRUD 之外，包含管理員指令也會記錄，這細節有多細節，基本上就是完整指令以及對系統的影響、執行時間等等。

Profiler 資訊全部儲存在 system.profile 內，它是一個 capped collection，因此不用太擔心，如果不知道甚麼是 capped collection，請務必往前翻前面的文章，這是一個很重要的設計。

Profiler 分級

Profiler 一共分三級:

0, 關閉 profiler
1, 僅記錄查詢時間大於 slowms 的查詢資訊
2, 紀錄全部的查詢資訊

如何取得目前狀態

1	db.getProfilingStatus()

預期會得到下面的結果

1	{ "was" : 0, "slowms" : 100, "sampleRate" : 1 }

was 就是目前狀態
slowms 目前設定 slow 的門檻 (ms)
sampleRate 值介於 0~1，取樣率的概念，如果設為 0.5，則只有50%的樣本會被記錄下來。關於使用這個參數，4版後續還有一些調整，以官網的為主。一般當然是希望全搜集XD

如何設定 profiler

1	db.setProfilingLevel(1)

預期會得到以下回覆

1	{ "was" : 0, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }

最後的 ok 代表的是設定的結果。

還有剛剛提到的參數也可以一併設定，例如：

1
2
3

> db.setProfilingLevel(1, {"slowms":53, "sampleRate":0.9})

{ "was" : 1, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }

設定 slow 門檻

從上面得知當 profileLevel(1) 以上，會開始記錄 slow log，我們也可以設定多少是屬於 slow

1	db.setProfilingLevel(1, { slowms: 30 })

這樣執行超過 30ms，就會被判斷為慢囉！

Profile 範例

下面是一個完整的查詢結果範例

{
  "op": "query",
  "ns": "company.employee",
  "command": {
    "find": "company.employee",
    "filter": {
      "Date": {
        "$lt": NumberLong("637591968000000000")
      },
      "EmployeeId": {
        "$in": [
          1
        ]
      }
    },
    "$db": "company",
    "lsid": {
      "id": UUID("9388d090-3ef0-4fb5-85d9-4deb761742b2")
    }
  },
  "keysExamined": 8,
  "docsExamined": 0,
  "cursorExhausted": true,
  "numYield": 0,
  "nreturned": 0,
  "queryHash": "8DCA06C8",
  "planCacheKey": "73511877",
  "locks": {
    "ReplicationStateTransition": {
      "acquireCount": {
        "w": NumberLong(1)
      }
    },
    "Global": {
      "acquireCount": {
        "r": NumberLong(1)
      }
    },
    "Database": {
      "acquireCount": {
        "r": NumberLong(1)
      }
    },
    "Collection": {
      "acquireCount": {
        "r": NumberLong(1)
      }
    },
    "Mutex": {
      "acquireCount": {
        "r": NumberLong(1)
      }
    }
  },
  "flowControl": {
  },
  "responseLength": 123,
  "protocol": "op_msg",
  "millis": 0,
  "planSummary": "IXSCAN { Date: -1, EmployeeId: -1 }",
  "execStats": {
    "stage": "FETCH",
    "nReturned": 0,
    "executionTimeMillisEstimate": 0,
    "works": 9,
    "advanced": 0,
    "needTime": 8,
    "needYield": 0,
    "saveState": 0,
    "restoreState": 0,
    "isEOF": 1,
    "docsExamined": 0,
    "alreadyHasObj": 0,
    "inputStage": {
      "stage": "IXSCAN",
      "nReturned": 0,
      "executionTimeMillisEstimate": 0,
      "works": 9,
      "advanced": 0,
      "needTime": 8,
      "needYield": 0,
      "saveState": 0,
      "restoreState": 0,
      "isEOF": 1,
      "keyPattern": {
        "Date": -1,
        "MemberId": -1
      },
      "indexName": "mainIX",
      "isMultiKey": false,
      "multiKeyPaths": {
        "Date": [

        ],
        "MemberId": [

        ]
      },
      "isUnique": true,
      "isSparse": false,
      "isPartial": false,
      "indexVersion": 2,
      "direction": "forward",
      "indexBounds": {
        "Date": [
          "(637591968000000000, -inf.0]"
        ],
        "EmployeeId": [
          "[1, 1]"
        ]
      },
      "keysExamined": 8,
      "seeks": 9,
      "dupsTested": 0,
      "dupsDropped": 0
    }
  },
  "ts": ISODate("2021-06-13T08:51:57.916Z"),
  "client": "192.168.0.1",
  "allUsers": [
    {
      "user": "user1",
      "db": "admin"
    }
  ],
  "user": "user1@admin"
}

欄位解說

op

執行的操作，有以下這些 query, update, group, insert, remove, command, count, distinct, geoNear, getMore, mapReduce.

1	db.system.profile.find({"op": "update"})

ns

collection 的　namespace

commands

就是本次被記錄到的 slow log　詳細查詢內容與條件。

keysExamined

MongoDB 搜索了多少 index keys 去找到查詢的文件。
越少越好

docsExamined

MongoDB 搜索了多少文件以找到想查詢結果。
一樣也是越少越好

nReturned

依照你的 op 會有對應的結果，如 ninserted, ndeleted, nMatched, nModified　等

locks

Lock 有分四種：

R, Share (S) lock, read 類操作使用
W, Eclusive (X) lock, write 類操作使用
r, intent share (IS) lock
w, intent exclusive (IX) lock

詳細的 lock 機制還是放到別的篇幅去，在這邊會講不完

responseLength

回傳檔案的大小(bytes)

millis / ts

執行該操作消耗的時間與執行該操作的時間點

execStats 內的項目

stage

stage 是初步觀察項目，為執行該查詢的狀態，分別有以下幾種

COLLSCAN: 相當於 RDB 的 full table scan，是最糟的查詢
IXSCAN: 使用 index keys 掃描，最理想狀態
FETCH: 根據 index 去查詢　document，大部分情況

executionTimeMillisEstimate

執行該操作消耗的時間。
搭配　index 調整，確認查詢是否正確走在 index上。

client

執行該操作的用戶端IP

allUsers

當前 session 經認證的使用者名稱與資料庫

user

執行該操作的使用者權限

其實紀錄的欄位會跟 explain 指令有點相似，因此我在這也跳過很多部分。下一篇會直接介紹常用的指令給大家，方便在查問題能夠快速定位。

mycTW Note

2021 iThome 鐵人賽 - DAY21 MongoDB Profiler 如何監控效能差的操作