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