MongoDB慢日志查询

6y45t4

MongoDB system.profile
前言

Part1:写在最前

    说到MongoDB的慢日志分析，就不得不提到profile分析器，profile分析器将记录的慢日志写到system.profile集合下，这个集合是一个固定集合。我们可以通过对这个集合的查询，来了解当前的慢日志，今儿对数据库进行优化。


Part2:整体环境

MongoDB 3.2.5



实战

Part1:输出示范

在查询system.profile的时候，我们能够观察到所有的操作，包括remove,update,find等等都会被记录到system.profile集合中，该集合中包含了诸多信息，如：


{
   "op" : "query",
   "ns" : "test.c",
   "query" : {
      "find" : "c",
      "filter" : {
         "a" : 1
      }
   },
   "keysExamined" : 2,
   "docsExamined" : 2,
   "cursorExhausted" : true,
   "keyUpdates" : 0,
   "writeConflicts" : 0,
   "numYield" : 0,
   "locks" : {
      "Global" : {
         "acquireCount" : {
            "r" : NumberLong(2)
         }
      },
      "Database" : {
         "acquireCount" : {
            "r" : NumberLong(1)
         }
      },
      "Collection" : {
         "acquireCount" : {
            "r" : NumberLong(1)
         }
      }
   },
   "nreturned" : 2,
   "responseLength" : 108,
   "millis" : 0,
   "execStats" : {
      "stage" : "FETCH",
      "nReturned" : 2,
      "executionTimeMillisEstimate" : 0,
      "works" : 3,
      "advanced" : 2,
      "needTime" : 0,
      "needYield" : 0,
      "saveState" : 0,
      "restoreState" : 0,
      "isEOF" : 1,
      "invalidates" : 0,
      "docsExamined" : 2,
      "alreadyHasObj" : 0,
      "inputStage" : {
         "stage" : "IXSCAN",
         "nReturned" : 2,
         "executionTimeMillisEstimate" : 0,
         "works" : 3,
         "advanced" : 2,
         "needTime" : 0,
         "needYield" : 0,
         "saveState" : 0,
         "restoreState" : 0,
         "isEOF" : 1,
         "invalidates" : 0,
         "keyPattern" : {
            "a" : 1
         },
         "indexName" : "a_1",
         "isMultiKey" : false,
         "isUnique" : false,
         "isSparse" : false,
         "isPartial" : false,
         "indexVersion" : 1,
         "direction" : "forward",
         "indexBounds" : {
            "a" : [
               "[1.0, 1.0]"
            ]
         },
         "keysExamined" : 2,
         "dupsTested" : 0,
         "dupsDropped" : 0,
         "seenInvalidated" : 0
      }
   },
   "ts" : ISODate("2015-09-03T15:26:14.948Z"),
   "client" : "127.0.0.1",
   "allUsers" : [ ],
   "user" : ""}


Part2:输出解读

system.profile.op

这一项主要包含如下几类

    insert

    query

    update

    remove

    getmore

    command


代表了该慢日志的种类是什么，是查询、插入、更新、删除还是其他。


system.profile.ns

该项表明该慢日志是哪个库下的哪个集合所对应的慢日志。


system.profile.query

该项详细输出了慢日志的具体语句和行为


system.profile.keysExamined

该项表明为了找出最终结果MongoDB搜索了多少个key


system.profile.docsExamined

该项表明为了找出最终结果MongoDB搜索了多少个文档


system.profile.keyUpdates

该项表名有多少个index key在该操作中被更改，更改索引键也会有少量的性能消耗，因为数据库不单单要删除旧Key，还要插入新的Key到B-Tree索引中


system.profile.writeConflicts

写冲突发生的数量，例如update一个正在被别的update操作的文档


system.profile.numYield

为了让别的操作完成而屈服的次数，一般发生在需要访问的数据尚未被完全读取到内存中，MongoDB会优先完成在内存中的操作


system.profile.locks

在操作中产生的锁，锁的种类有多种，如下：
Global

	Represents global lock.
MMAPV1Journal	Represents MMAPv1 storage engine specific lock to synchronizejournal writes; for non-MMAPv1 storage engines, the mode forMMAPV1Journal is empty.
Database	Represents database lock.
Collection	Represents collection lock.
Metadata	Represents metadata lock.
oplog	Represents lock on the oplog.

锁的模式也有多种，如下：
Lock ModeDescription
RRepresents Shared (S) lock.
WRepresents Exclusive (X) lock.
rRepresents Intent Shared (IS) lock.
wRepresents Intent Exclusive (IX) lock.
system.profile.locks.acquireCoun
在各种不用的种类下，请求锁的次数

system.profile.nreturned
该操作最终返回文档的数量

system.profile.responseLength
结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果

system.profile.millis
该操作从开始到结束耗时多少，单位为毫秒

system.profile.execStats
包含了一些该操作的统计信息，只有query类型的才会显示


system.profile.execStats.stage
包含了该操作的详细信息，例如是否用到索引


system.profile.ts
该操作执行时的时间

system.profile.client
哪个客户端发起的该操作，并显示出该客户端的ip或hostname

system.profile.allUsers
哪个认证用户执行的该操作

system.profile.user
是否认证用户执行该操作，如认证后使用其他用户操作，该项为空

——总结——

system.profile集合是定位慢SQL的手段之一，了解每一个输出项的含义有助于我们更快的定位问题。由于笔者的水平有限，编写时间也很仓促，文中难免会出现一些错误或者不准确的地方，不妥之处恳请读者批评指正。