使用Profile抓住慢查询

在很多情况下,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)的作用
会将当前库下超过0ms的操作记录到system.profile集合中,并写入日志文件中;
mongod也会将其他库中超过0ms的操作写进日志文件中,即使其他库并没有开启profile功能;
官方文档解释:
mongod writes the output of the database profiler to the system.profile collection.
mongod prints information about queries that take longer than the slowOpThresholdMs to the log even when the database profiler is not active.
总结:

故无论profile的模式是什么(0,1,2),只要超时阀值slowOpThresholdMs设定,就会被写入到日志文件中,即使你已经关闭了profile---db.setProfilingLevel(0);

So

一定不要随意将slowOpThresholdMs的值设置为0!
一定不要随意将slowOpThresholdMs的值设置为0!
一定不要随意将slowOpThresholdMs的值设置为0!
上一篇:如何使用DNN中的Calendar控件


下一篇:使用移动App开发框架Ionic构建应用的5个实用技巧