mongodb Profiling 通过慢查询日志分析查询慢的原因 相应优化

殇帝刘玢你

　　0  摘要
　　在MySQL中，慢查询日志是经常作为我们优化查询的依据，那在MongoDB中是否有类似的功能呢？答案是肯定的，那就是开启Profiling功能。该工具在运行的实例上收集有关MongoDB的写操作，游标，数据库命令等，可以在数据库级别开启该工具，也可以在实例级别开启。该工具会把收集到的所有都写入到system.profile集合中，该集合是一个capped collection。更多的信息见：http://docs.mongodb.org/manual/tutorial/manage-the-database-profiler/
　　1  慢查询分析流程
　　慢查询日志一般作为优化步骤里的第一步。通过慢查询日志，定位每一条语句的查询时间。比如超过了200ms，那么查询超过200ms的语句需要优化。然后它通过 .explain() 解析影响行数是不是过大，所以导致查询语句超过200ms。
　　所以优化步骤一般就是：
　　1.用慢查询日志（system.profile）找到超过200ms的语句
　　2.然后再通过.explain()解析影响行数，分析为什么超过200ms
　　3.决定是不是需要添加索引
　　2  开启慢查询
　　2.1  Profiling级别说明
　　

0：关闭，不收集任何数据。　　
1：收集慢查询数据，默认是100毫秒。
　　
2：收集所有数据
　　

　　2.2  开启Profiling和设置
　　1：通过mongo shell:
　　需要进入server
　　mongo 而不是路由器mongoos
　　#查看状态：级别和时间
　　

PRIMARY> db.getProfilingStatus()　　
{ "was" : 1, "slowms" : 200 }
　　
#查看级别
　　
PRIMARY> db.getProfilingLevel()
　　
1
　　
#设置级别
　　
PRIMARY> db.setProfilingLevel(2)
　　
{ "was" : 1, "slowms" : 100, "ok" : 1 }
　　
#设置级别和时间
　　
PRIMARY> db.setProfilingLevel(1,200)
　　
{ "was" : 2, "slowms" : 100, "ok" : 1 }
　　

　　注意：
　　1  以上要操作要是在test集合下面的话，只对该集合里的操作有效，要是需要对整个实例有效，则需要在所有的集合下设置或则在开启的时候开启参数
　　2 每次设置之后返回给你的结果是修改之前的状态（包括级别、时间参数）。
　　2：不通过mongo shell:
　　在mongoDB启动的时候
　　mongod --profile=1  --slowms=200
　　或则在配置文件里添加2行：
　　

profile = 1　　
slowms = 200
　　

　　3：关闭Profiling
　　

### 关闭Profiling　　
PRIMARY> db.setProfilingLevel(0)
　　
{ "was" : 1, "slowms" : 200, "ok" : 1 }
　　

　　4：修改“慢查询日志”的大小
　　

#关闭Profiling　　
PRIMARY> db.setProfilingLevel(0)
　　
{ "was" : 0, "slowms" : 200, "ok" : 1 }
　　
#删除system.profile集合
　　
PRIMARY> db.system.profile.drop()
　　
true
　　
#创建一个新的system.profile集合 --- 4M

　　
PRIMARY> db.createCollection( "system.profile", { capped: true,>　　
{ "ok" : 1 }
　　
#重新开启Profiling
　　
PRIMARY> db.setProfilingLevel(1)
　　
{ "was" : 0, "slowms" : 200, "ok" : 1 }
　　

　　注意：要改变Secondary的system.profile的大小，你必须停止Secondary，运行它作为一个独立的mongodb，然后再执行上述步骤。完成后，重新启动加入副本集。
　　2.3  Profile 效率
　　Profiling功能肯定是会影响效率的，但是不太严重，原因是他使用的是system.profile 来记录，而system.profile 是一个capped collection， 这种collection 在操作上有一些限制和特点，但是效率更高。
　　3   慢查询(system.profile)分析
　　通过 db.system.profile.find() 查看当前所有的慢查询日志，使用pretty()方法使显示的结果更美观：db.BizUser.find().pretty()。下面的例子说明各个参数的含义，更多信息见：http://docs.mongodb.org/manual/reference /database-profiler/
　　3.1：参数含义  -- (这是一个query 类型的 慢查询)
　　

> db.system.profile.find().pretty();　　
{
　　"op" : "query",  #操作类型，有insert、query、update、remove、getmore、command
　　"ns" : "onroad.route_model", #操作的集合
　　"query" : {
　　"$query" : {
　　"user_id" : 314436841,
　　"data_time" : {
　　"$gte" : 1436198400
　　}
　　},
　　"$orderby" : {
　　"data_time" : 1
　　}
　　},
　　"ntoskip" : 0, #指定跳过skip()方法 的文档的数量。
　　"nscanned" : 2, #为了执行该操作，MongoDB在 index 中浏览的文档数。 一般来说，如果 nscanned 值高于 nreturned 的值，说明数据库为了找到目标文档扫描了很多文档。这时可以考虑创建索引来提高效率。
　　"nscannedObjects" : 1,  #为了执行该操作，MongoDB在 collection中浏览的文档数。
　　"keyUpdates" : 0, #索引更新的数量，改变一个索引键带有一个小的性能开销，因为数据库必须删除旧的key，并插入一个新的key到B-树索引
　　"numYield" : 1,  #该操作为了使其他操作完成而放弃的次数。通常来说，当他们需要访问还没有完全读入内存中的数据时，操作将放弃。这使得在MongoDB为了放弃操作进行数据读取的同时，还有数据在内存中的其他操作可以完成
　　"lockStats" : {  #锁信息，R：全局读锁；W：全局写锁；r：特定数据库的读锁；w：特定数据库的写锁
　　"timeLockedMicros" : {  #该操作获取一个级锁花费的时间。对于请求多个锁的操作，比如对 local 数据库锁来更新 oplog ，该值比该操作的总长要长（即 millis ）
　　"r" : NumberLong(1089485),
　　"w" : NumberLong(0)
　　},
　　"timeAcquiringMicros" : {  #该操作等待获取一个级锁花费的时间。
　　"r" : NumberLong(102),
　　"w" : NumberLong(2)
　　}
　　},
　　"nreturned" : 1,  // 返回的文档数量
　　"responseLength" : 1669, // 返回字节长度，如果这个数字很大，考虑值返回所需字段
　　"millis" : 544, #消耗的时间（毫秒）
　　"execStats" : {  #一个文档,其中包含执行 查询 的操作，对于其他操作,这个值是一个空文件， system.profile.execStats 显示了就像树一样的统计结构，每个节点提供了在执行阶段的查询操作情况。
　　"type" : "LIMIT", ##使用limit限制返回数
　　"works" : 2,
　　"yields" : 1,
　　"unyields" : 1,
　　"invalidates" : 0,
　　"advanced" : 1,
　　"needTime" : 0,
　　"needFetch" : 0,
　　"isEOF" : 1,  #是否为文件结束符
　　"children" : [
　　{
　　"type" : "FETCH",  #根据索引去检索指定document
　　"works" : 1,
　　"yields" : 1,
　　"unyields" : 1,
　　"invalidates" : 0,
　　"advanced" : 1,
　　"needTime" : 0,
　　"needFetch" : 0,
　　"isEOF" : 0,
　　"alreadyHasObj" : 0,
　　"forcedFetches" : 0,
　　"matchTested" : 0,
　　"children" : [
　　{
　　"type" : "IXSCAN", #扫描索引键
　　"works" : 1,
　　"yields" : 1,
　　"unyields" : 1,
　　"invalidates" : 0,
　　"advanced" : 1,
　　"needTime" : 0,
　　"needFetch" : 0,
　　"isEOF" : 0,
　　"keyPattern" : "{ user_id: 1.0, data_time: -1.0 }",
　　"boundsVerbose" : "field #0['user_id']: [314436841, 314436841], field #1['data_time']: [1436198400, inf.0]",
　　"isMultiKey" : 0,
　　"yieldMovedCursor" : 0,
　　"dupsTested" : 0,
　　"dupsDropped" : 0,
　　"seenInvalidated" : 0,
　　"matchTested" : 0,
　　"keysExamined" : 2,
　　"children" : [ ]
　　}
　　]
　　}
　　]
　　},
　　"ts" : ISODate("2015-10-15T07:41:03.061Z"), #该命令在何时执行
　　"client" : "10.10.86.171", #链接ip或则主机
　　"allUsers" : [
　　{
　　"user" : "martin_v8",
　　"db" : "onroad"
　　}
　　],
　　"user" : "martin_v8@onroad"
　　
}
　　

　　3.2: 分析
　　如果发现 millis 值比较大，那么就需要作优化。
　　1  如果nscanned数很大，或者接近记录总数（文档数），那么可能没有用到索引查询，而是全表扫描。
　　2  如果 nscanned 值高于 nreturned 的值，说明数据库为了找到目标文档扫描了很多文档。这时可以考虑创建索引来提高效率。
　　3.3  system.profile补充
　　‘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
　　4  性能（explain）分析
　　

SECONDARY> db.route_model.find({ "user_id" : 313830621, "data_time" : { "$lte" : 1443715200, "$gte" : 1443542400 } }).explain()　　
{
　　"cursor" : "BtreeCursor user_id_1_data_time_-1",  #返回游标类型，有BasicCursor和BtreeCursor，后者意味着使用了索引。
　　"isMultiKey" : false,
　　"n" : 23, #返回的文档行数。
　　"nscannedObjects" : 23,  #这是MongoDB按照索引指针去磁盘上查找实际文档的次数。如果查询包含的查询条件不是索引的一部分，或者说要求返回不在索引内的字段，MongoDB就必须依次查找每个索引条目指向的文档。
　　"nscanned" : 23,  #如果有使用索引，那么这个数字就是查找过的索引条目数量，如果本次查询是一次全表扫描，那么这个数字就代表检查过的文档数目
　　"nscannedObjectsAllPlans" : 46,
　　"nscannedAllPlans" : 46,
　　"scanAndOrder" : false,  #MongoDB是否在内存中对结果集进行了排序
　　"indexOnly" : false, #MongoDB是否只使用索引就能完成此次查询
　　"nYields" : 1,  #为了让写入请求能够顺利执行，本次查询暂停暂停的次数。如果有写入请求需求处理，查询会周期性的释放他们的锁，以便写入能够顺利执行
　　"nChunkSkips" : 0,
　　"millis" : 1530,  #数据库执行本次查询所耗费的毫秒数。这个数字越小，说明效率越高
　　"indexBounds" : {  #这个字段描述了索引的使用情况，给出了索引的遍历范围
　　"user_id" : [
　　[
　　313830621,
　　313830621
　　]
　　],
　　"data_time" : [
　　[
　　1443715200,
　　1443542400
　　]
　　]
　　},
　　"server" : "a7cecd4f9295:27017",
　　"filterSet" : false,
　　"stats" : {
　　"type" : "FETCH",
　　"works" : 25,
　　"yields" : 1,
　　"unyields" : 1,
　　"invalidates" : 0,
　　"advanced" : 23,
　　"needTime" : 0,
　　"needFetch" : 0,
　　"isEOF" : 1,
　　"alreadyHasObj" : 0,
　　"forcedFetches" : 0,
　　"matchTested" : 0,
　　"children" : [
　　{
　　"type" : "IXSCAN",#这里使用了索引
　　"works" : 23,
　　"yields" : 1,
　　"unyields" : 1,
　　"invalidates" : 0,
　　"advanced" : 23,
　　"needTime" : 0,
　　"needFetch" : 0,
　　"isEOF" : 1,
　　"keyPattern" : "{ user_id: 1.0, data_time: -1.0 }",
　　"boundsVerbose" : "field #0['user_id']: [313830621.0, 313830621.0], field #1['data_time']: [1443715200.0, 1443542400.0]",
　　"isMultiKey" : 0,
　　"yieldMovedCursor" : 0,
　　"dupsTested" : 0,
　　"dupsDropped" : 0,
　　"seenInvalidated" : 0,
　　"matchTested" : 0,
　　"keysExamined" : 23,
　　"children" : [ ]
　　}
　　]
　　}
　　
}
　　

　　详细解释 : https://docs.mongodb.org/manual/reference/database-profiler/
　　这里的分析类似于 system.profile
　　5  日常使用的慢日志（system.profile）查询
　　#返回最近的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)
　　#逆序排查下，查看最近三条的 Profile 记录 ，可以适当调大下。 ：
　　db.system.profile.find().sort({$natrual: -1}).limit(3)
　　#显示5个最近的事件
　　show profile
　　6  对慢查询语句建索引
　　详细请见下一篇博文
　　

     原文出自：http://blog.csdn.net/yisun123456/article/details/78274477