使用Profile抓住慢查询

2020-04-29 17:53:40

官方查询地址：https://docs.mongodb.com/v3.2/tutorial/manage-the-database-profiler/

在很多情况下，DBA都要对数据库的性能进行分析处理，找出降低性能的根源

而Mongo就有一种分析工具来检测并追踪影响性能的慢查询---Profile

有两种方式可以控制Profiling的开关和级别，

种是直接在启动参数中进行设置，如下:

如果想要全局开启Profiling，则可以在mongod启动时加上参数

mongod --profile 1 --slowms 100          # 1表示追踪级别，100表示慢查询判定时间(ms)

若是配置文件中开启的话，配置如下：

operationProfiling:
   slowOpThresholdMs: 100
   mode: slowOp

第二种是在mongo shell进行实时配置，命令如下：

> db.setProfilingLevel(1,200)          ---1表示level，200表示慢查询时间(ms)，也可以省略时间设置
{ "was" : 1, "slowms" : 100, "ok" : 1 }     ---100表示之前的慢查询时间设定值
> db.getProfilingStatus()               ---查询当前慢查询的状态信息
{ "was" : 1, "slowms" : 200 }          ---was后的值表示级别
> db.getProfilingLevel()               ---只查询Profiling级别可用此命令
1

级别可以取0，1，2 三个值，他们表示的意义如下：

　　0 – 不开启

　　1 – 记录慢命令 (默认为>100ms)

　　2 – 记录所有命令

Mongo Profile慢查询记录直接记录在db中，记录位置是当前开启Profile功能的库下的system.profile集合中，所以只需要直接查询这个集合就行

例：

查询执行时间大于200ms的Profile记录：

> db.system.profile.find( { millis : { $gt : 5 } } )

查看近的10条记录

>db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty()

查看关于某个collection的相关慢查询操作：

>db.system.profile.find({ns:'mydb.table1'}).pretty()

1、查询当前库慢查询的SQL:

db.system.profile.find({millis:{$gt:5000}}).sort({ts:-1})     ---查询时间超过5s的近SQL

只显示某些重要指标：

db.system.profile.find({millis:{$gt:1000}},{allUsers:1,client:1,millis:1,nns:1,op:1,query:1,ts:1}).sort({ts:-1})

#近10分钟的慢日志,超过1秒

db.system.profile.aggregate(
[
    {$match : {
        millis : { $gt : 1000 } ,
        ts : { $gt : new Date(new Date()-10*60*1000) }
          }
    },
    {$group : {  _id :{"op":"$op","ns":"$ns"},count: { $sum: 1 }}},
    {$sort : {count : -1}}
]
);

show profile命令

此命令查询执行时间超过1ms的近5条记录

对于Profile的相关信息解释：

op:操作的类型，比如：insert,query,command,remove...

ns:被查询目标的命名空间，一般是数据库名和collection名的组合

query:查询的具体语句，如果是insert操作，则会是insert的语句

command：如果操作是一个command，则command语句记录在此

keysExamined:以前是nscanned，3.2版本之后改为keysExamined，表示执行此次操作所扫描的索引键记录数

updateobj：如果操作是一个update，则update语句记录在此

ndeleted：此次操作删除的文档数

ninserted: 此次操作插入的文档数

nModified:此次操作的update的文档数

writeConflicts：如果一个update语句正在操作一个文档，而另一个update同时进行操作此文档，从而造成的冲突数量

locks：此次操作产生锁的相关信息

nreturned：此次操作返回的文档数

responseLength:操作结果集的大小，

moved：表明本次update是否移动了硬盘上的数据，如果新记录比原记录短，通常不会移动当前记录，如果新记录比原记录长，那么可能会移动记录到其它位置，这时候会导致相关索引的更新.磁盘操作更多，加上索引更新，会使得这样的操作比较慢.（不过这个选在仅针对引擎是MMAPv1）

MongoDB 查询优化

如果keysExamined (扫描索引建的记录数)远大于nreturned(返回结果的记录数)的话，那么我们就要考虑通过加索引来优化记录定位了。

responseLength 如果过大，那么说明我们返回的结果集太大了，可能会影响性能，这时请查看find函数的第二个参数是否只写上了你需要的属性名（限制于仅需要查询的字段）。(类似于MySQL中不要总是select *)

对于创建索引的建议是：如果很少读，那么尽量不要添加索引，因为索引越多，写操作会越慢。如果读量很大，那么创建索引还是比较划算的。

Profiler 的效率

　　Profiling 功能肯定是会影响效率的，但是不太严重，原因是他使用的是system.profile 来记录，而system.profile 是一个capped collection 这种collection 在操作上有一些限制和特点，但是效率更高

也可以对system.profile的size进行设置，具体设置如下：

db.setProfilingLevel()

db.system.profile.drop()

db.createCollection( "system.profile", { capped: true, size:4000000 } )

db.setProfilingLevel(1)

Profile导致的日志骤增异常

异常描述：

设置profile慢查询db.setProfilingLevel(1,0)后, 日志量剧增，导致单个日志文件增大到120G

问题复现：

1.如下的操作默认情况下是不会记录到日志中

shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 100 }
shardrs1:PRIMARY> db
testdb
shardrs1:PRIMARY> db.t1.find()
{ "_id" : 1, "a" : 1 }

2.在testdb库开启所有查询都抓取

shardrs1:PRIMARY> db.setProfilingLevel(1,0)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 1, "slowms" : 0 }

注：此时会导致实例下任何库的任何查询都会被记录到日志中

3.分别在不同库下查询

shardrs1:PRIMARY> db
testdb
shardrs1:PRIMARY> db.t1.find()
{ "_id" : 1, "a" : 1 }

执行上述命令后，日志居然会记录下来

2019-06-18T11:39:13.358+0800 I COMMAND  [conn2755] command testdb.t1 command: find { find: "t1", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:114 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms

testdb2库下查询时，也会被记录

shardrs1:PRIMARY> use testdb2
switched to db testdb2
shardrs1:PRIMARY> db.t2.find()
{ "_id" : 2, "b" : 2 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 0 }

日志记录如下：

2019-06-18T11:41:11.309+0800 I COMMAND  [conn2755] command testdb2.t2 command: find { find: "t2", filter: {} } planSummary: COLLSCAN keysExamined:0 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:115 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 0ms

4.此时关闭Profile等级为0,但日志中依然会记录上述find信息

shardrs1:PRIMARY> use testdb
switched to db testdb
shardrs1:PRIMARY> db.setProfilingLevel(0)
{ "was" : 1, "slowms" : 0, "ok" : 1 }
shardrs1:PRIMARY> db.getProfilingStatus()
{ "was" : 0, "slowms" : 0 }

原因分析：

首先我们来看一下db.setProfilingLevel( 1, ,0)的作用