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

本文涉及的产品
云数据库 MongoDB,独享型 2核8GB
推荐场景:
构建全方位客户视图
日志服务 SLS,月写入数据量 50GB 1个月
简介:

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, size:4000000 } )
{ "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

本文转自奔跑在路上博客51CTO博客,原文链接http://blog.51cto.com/qiangsh/2052609如需转载请自行联系原作者


qianghong000

相关实践学习
MongoDB数据库入门
MongoDB数据库入门实验。
快速掌握 MongoDB 数据库
本课程主要讲解MongoDB数据库的基本知识,包括MongoDB数据库的安装、配置、服务的启动、数据的CRUD操作函数使用、MongoDB索引的使用(唯一索引、地理索引、过期索引、全文索引等)、MapReduce操作实现、用户管理、Java对MongoDB的操作支持(基于2.x驱动与3.x驱动的完全讲解)。 通过学习此课程,读者将具备MongoDB数据库的开发能力,并且能够使用MongoDB进行项目开发。   相关的阿里云产品:云数据库 MongoDB版 云数据库MongoDB版支持ReplicaSet和Sharding两种部署架构,具备安全审计,时间点备份等多项企业能力。在互联网、物联网、游戏、金融等领域被广泛采用。 云数据库MongoDB版(ApsaraDB for MongoDB)完全兼容MongoDB协议,基于飞天分布式系统和高可靠存储引擎,提供多节点高可用架构、弹性扩容、容灾、备份回滚、性能优化等解决方案。 产品详情: https://www.aliyun.com/product/mongodb
相关文章
|
1月前
|
存储 NoSQL MongoDB
掌握MongoDB索引优化策略:提升查询效率的关键
在数据库性能调优中,索引是提升查询效率的利器。本文将带你深入了解MongoDB索引的内部工作原理,探讨索引对查询性能的影响,并通过实际案例指导如何针对不同的查询模式建立有效的索引。不仅将涵盖单一字段索引,还会探讨复合索引的使用,以及如何通过分析查询模式和执行计划来优化索引,最终实现查询性能的最大化。
|
12天前
|
JSON 监控 JavaScript
Node.js-API 限流与日志优化
Node.js-API 限流与日志优化
|
14天前
|
监控 关系型数据库 MySQL
分析慢查询日志
【10月更文挑战第29天】分析慢查询日志
35 3
|
14天前
|
监控 关系型数据库 数据库
怎样分析慢查询日志?
【10月更文挑战第29天】怎样分析慢查询日志?
32 2
|
22天前
|
存储 NoSQL MongoDB
MongoDB 查询分析
10月更文挑战第21天
11 1
|
22天前
|
NoSQL MongoDB 索引
MongoDB 覆盖索引查询
10月更文挑战第21天
23 1
|
28天前
|
SQL NoSQL MongoDB
MongoDB 查询文档
10月更文挑战第15天
14 1
|
1月前
|
Arthas 监控 Java
JVM知识体系学习七:了解JVM常用命令行参数、GC日志详解、调优三大方面(JVM规划和预调优、优化JVM环境、JVM运行出现的各种问题)、Arthas
这篇文章全面介绍了JVM的命令行参数、GC日志分析以及性能调优的各个方面,包括监控工具使用和实际案例分析。
43 3
|
1月前
|
存储 Prometheus NoSQL
大数据-44 Redis 慢查询日志 监视器 慢查询测试学习
大数据-44 Redis 慢查询日志 监视器 慢查询测试学习
24 3
|
1月前
|
存储 监控 固态存储
如何监控和优化 WAL 日志文件的存储空间使用?
如何监控和优化 WAL 日志文件的存储空间使用?