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

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

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

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

Profiler 分級

Profiler 一共分三級:

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

如何取得目前狀態

db.getProfilingStatus()

預期會得到下面的結果

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

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

如何設定 profiler

db.setProfilingLevel(1)

預期會得到以下回覆

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

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

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

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

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

設定 slow 門檻

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

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.

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 指令有點相似，因此我在這也跳過很多部分。下一篇會直接介紹常用的指令給大家，方便在查問題能夠快速定位。

本系列文章會同步發表於我個人的部落格 Pie Note