mongodb慢日志

慢查询日志是针对数据库级别的，设置的时候，要先use 数据库，再开启；

查看慢日志状态

#查询Profiling级别
PRIMARY> db.getProfilingLevel()
1
#查询Profiling状态
PRIMARY> db.getProfilingStatus()
{ "was" : 1, "slowms" : 10 }

• “was”：
  0:不开启
  1:记录慢查询日志
  2:记录所有查询日志
• “slowms”:
  默认100，记录慢日志的阈值，单位为ms

设置慢日志参数

#设置级别为1，慢查询标准为200ms.
PRIMARY> db.setProfilingLevel(1,200)
{ "was" : 1, "slowms" : 200, "ok" : 1 }
##关闭设置Profiling
PRIMARY>db.setProfilingLevel(0)

查看慢日志内容

常使用的查询命令

#返回最近的10条记录
db.system.profile.find().limit(10).sort({ ts : -1 }).pretty()
#返回所有的操作，除command类型的
db.system.profile.find( { op: { $ne : ‘command‘ } }).pretty()
#返回特定集合
db.system.profile.find( { ns : ‘mydb.test‘ } ).pretty()
#返回大于5毫秒慢的操作
db.system.profile.find({ millis : { $gt : 5 } } ).pretty()
#从一个特定的时间范围内返回信息
db.system.profile.find(
                      {
                       ts : {
                             $gt : new ISODate("2015-10-18T03:00:00Z"),
                             $lt : new ISODate("2015-10-19T03:40:00Z")
                            }
                      }
                     ).pretty()
#特定时间，限制用户，按照消耗时间排序
db.system.profile.find(
                      {
                        ts : {
                              $gt : newISODate("2015-10-12T03:00:00Z") ,
                              $lt : newISODate("2015-10-12T03:40:00Z")
                             }
                      },
                      { user : 0 }
                     ).sort( { millis : -1 } )
#查看最新的 Profile  记录： 
db.system.profile.find().sort({$natural:-1}).limit(1)
# 显示5个最近的事件
show profile

profile内容信息

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 synchronize journal 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 Mode	Description
		R	Represents Shared (S) lock.
		W	Represents Exclusive (X) lock.
		r	Represents Intent Shared (IS) lock.
		w	Represents 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：是否认证用户执行该操作，如认证后使用其他用户操作，该项为空

示例

 
 
{
   "op" : "query", //system.profile.op 代表了慢日志的种类，是查询，插入，更新，删除还是其它
   "ns" : "test.c",//该项表示了哪个库下面的哪个集合对应的慢日志
   "query" : {     //该项详细输出了慢日志的具体语句和行为
      "find" : "c",
      "filter" : {
         "a" : 1
      }
   },
   "keysExamined" : 2,//该项表明了为了找出最终的结果，mongo搜索了多少个索引key
   "docsExamined" : 2, //该项表明了为了找出最终的结果，mongo搜索了多少个文档
   "cursorExhausted" : true,//
   "keyUpdates" : 0,   //表明了有多个索引key在本次操作中被修改，更改索引key也会有少量的性能消耗，因为mongo不仅要删除旧key，还要插入新key到B-Tree中
   "writeConflicts" : 0, //写冲突发生的数量，例如update一个正在被别的update操作的文档
   "numYield" : 0, //为了让别的操作完成而屈服的次数，一般发生在需要访问的数据尚未被完全读取到内存中，mongo会优先完成在内存中的操作
   "locks" : {  
      "Global" : {
         "acquireCount" : {
            "r" : NumberLong(2)
         }
      },
      "Database" : {
         "acquireCount" : {
            "r" : NumberLong(1)
         }
      },
      "Collection" : {
         "acquireCount" : {
            "r" : NumberLong(1)
         }
      }
   },
   "nreturned" : 2,//该操作最终返回的文档数
   "responseLength" : 108,//结果返回的大小，单位为bytes，该值如果过大，则需要考虑limit等方式减少输出结果。
   "millis" : 0, //该操作从开始到结束耗时多少，单位毫秒
   "execStats" : { //包含了一些该操作的统计信息，只有query类型才会显示
      "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", //发起请求的客户端ip。并显示出该客户端的ip或hostname
   "allUsers" : [ ],//哪个认证用户执行的操作
   "user" : ""}//是否认证用户执行该操作，如认证后使用其它用户操作，该项为空

慢日志分析

分析流程

慢查询日志一般作为优化步骤里的第一步。通过慢查询日志，定位每一条语句的查询时间。比如超过了200ms，那么查询超过200ms的语句需要优化。然后它通过 .explain() 解析影响行数是不是过大，所以导致查询语句超过200ms。

所以优化步骤一般就是：

1.用慢查询日志（system.profile）找到超过200ms的语句

2.然后再通过.explain()解析影响行数，分析为什么超过200ms

3.决定是不是需要添加索引

慢查询分析

如果发现 millis 值比较大，那么就需要作优化。

1 如果nscanned数很大，或者接近记录总数（文档数），那么可能没有用到索引查询，而是全表扫描。

2 如果 nscanned 值高于 nreturned 的值，说明数据库为了找到目标文档扫描了很多文档。这时可以考虑创建索引来提高效率。

‘type’的返回参数说明：

COLLSCAN #全表扫描
IXSCAN #索引扫描
FETCH #根据索引去检索指定document
SHARD_MERGE #将各个分片返回数据进行merge
SORT #表明在内存中进行了排序（与老版本的scanAndOrder:true一致）
LIMIT #使用limit限制返回数
SKIP #使用skip进行跳过
IDHACK #针对_id进行查询
SHARDING_FILTER #通过mongos对分片数据进行查询
COUNT #利用db.coll.explain().count()之类进行count运算
COUNTSCAN #count不使用Index进行count时的stage返回
COUNT_SCAN #count使用了Index进行count时的stage返回
SUBPLA #未使用到索引的$or查询的stage返回
TEXT #使用全文索引进行查询时候的stage返回
PROJECTION #限定返回字段时候stage的返回

对于普通查询，我们最希望看到的组合有这些：

Fetch+IDHACK
Fetch+ixscan
Limit+（Fetch+ixscan）
PROJECTION+ixscan
SHARDING_FILTER+ixscan

不希望看到包含如下的type：

COLLSCAN（全表扫），SORT（使用sort但是无index），不合理的SKIP，SUBPLA（未用到index的$or）

对于count查询，希望看到的有：

COUNT_SCAN

不希望看到的有:

COUNTSCAN