MongoDB 查看慢查询级别及慢查询日志

Posted 2023-04-04 阿福Chris

1. MongoDB 慢查询记录功能简介

如何定位 MongoDB 数据库的慢查询，我想应该是很多刚使用 MongoDB 数据库的朋友最想知道的问题。通过慢查询的定位，可以辅助对 MongoDB 中的 collection 进行优化。

MongoDB 数据库的慢查询数据其实存放在一个数据库集合 ( collection ) 中（system.profile），如果你不主动创建 system.profile 这个集合，那这个集合就固定1M大小，当慢查询记录超过1M，就会将历史数据覆盖，循环使用，所以在这里需要根据业务实际情况设置集合大小。

在 MongoDB 中慢查询功能（Profiling）设置有三个级别，分别代表如下含义：

• 0：代表关闭，不收集任何慢查询
• 1：收集慢查询数据，默认收集超过100毫秒的慢查询
• 2：收集任何操作记录数据

可以通过在 MongoDB 中执行如下命令查看当前数据库的配置，需要特别注意的是，如果你在某一数据库中调整了该设置，那么该操作只对该数据库有效，其他数据库仍需要单独设置：

use test
'switched to db test'
db.getProfilingStatus()
 was: 1, slowms: 1000, sampleRate: 1, ok: 1 

2. 如何设置慢查询

2.1 检查慢查询是否开启

执行 db.getProfilingStatus() 查询数据库，返回结果是 was: 0 代表 MongoDB 没有开启慢查询功能；对应的如果不是 0 则表示开启了慢查询监控功能。

2.2 开启慢查询功能

如果你想指定监控慢查询在某一毫秒值之上的查询，例如超过 1000 毫秒的查询被记录，可以通过如下语句进行设置：

db.setProfilingLevel(1,  slowms: 1000 )

下面这个例子表示将慢查询的级别设置为 2

db.setProfilingLevel(2)
 was: 1, slowms: 500, sampleRate: 1, ok: 1 
db.getProfilingStatus()
 was: 2, slowms: 500, sampleRate: 1, ok: 1 

关掉慢查询功能

db.setProfilingLevel(0)

3. 如何查询慢查询日志

假设上面我们已经开启了慢查询监控功能，那在数据库使用过程中，会将 1000 ms 以上的执行查询进行记录，下面我们来看一下如何查询这些慢查询。

3.1 慢查询日志查看

查询最近的 10 个慢查询日志 (运行时间大于等于 8000 毫秒)

db.system.profile.find("millis":$gte:8000).limit(10).sort(  ts : -1  ).pretty()

查询大于 100 秒的日志

db.system.profile.find(  millis :  $gt : 100000   ).pretty()

查询时间从 2023-01-03 15 点整到 2023-01-03 15点30分 之间的日志

db.system.profile.find(ts : $gt: new ISODate("2023-01-03T07:00:00Z"),$lt: new ISODate("2023-01-03T07:30:00Z")).pretty()

备注：注意 Mongo 里面存储的 ISO 时间是格林尼治时间，我们当前CST时间为北京时间，需要在 ISO 上 +8，所以你可以看到上面我查询输入的时间为 7 点，但实际上查询的是 15 点的数据。

End～

mongodb 跟踪SQL语句及慢查询收集

有个需求：跟踪mongodb的SQL语句及慢查询收集

第一步：通过mongodb自带函数可以查看在一段时间内DML语句的运行次数。

在bin目录下面运行  ./mongostat -port 端口号  则可以看到下面的数据

 

它的输出有以下几列：

• inserts/s 每秒插入次数
• query/s 每秒查询次数
• update/s 每秒更新次数
• delete/s 每秒删除次数
• getmore/s 每秒执行getmore次数
• command/s 每秒的命令数，比以上插入、查找、更新、删除的综合还多，还统计了别的命令
• flushs/s 每秒执行fsync将数据写入硬盘的次数。
• mapped/s 所有的被mmap的数据量，单位是MB，
• vsize 虚拟内存使用量，单位MB
• res 物理内存使用量，单位MB
• faults/s 每秒访问失败数（只有Linux有），数据被交换出物理内存，放到swap。不要超过100，否则就是机器内存太小，造成频繁swap写入。此时要升级内存或者扩展
• locked % 被锁的时间百分比，尽量控制在50%以下吧
• idx miss % 索引不命中所占百分比。如果太高的话就要考虑索引是不是少了
• q t|r|w 当Mongodb接收到太多的命令而数据库被锁住无法执行完成，它会将命令加入队列。这一栏显示了总共、读、写3个队列的长度，都为0的话表示mongo毫无压力。高并发时，一般队列值会升高。
• conn 当前连接数
• time 时间戳

上面只是大体的查看，并没有跟踪到SQL语句。下面开启慢查询

 

在mongodb客户端运行

db.getProfilingLevel()

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

0 – 不开启

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

2 – 记录所有命令

 更改此值的方法是:假如更改成2

db.setProfilingLevel(2)

 

Profile 记录在级别1时会记录慢命令，那么这个慢的定义是什么？上面我们说到其默认为100ms，当然有默认就有设置，其设置方法和级别一样有两种，一种是通过添加–slowms启动参数配置。第二种是调用db.setProfilingLevel时加上第二个参数：

db.setProfilingLevel( level , slowms )
db.setProfilingLevel( 1 , 10 );

 

 

Mongo Profile 记录是直接存在系统db里的，记录位置 system.profile ，所以，我们只要查询这个Collection的记录就可以获取到我们的 Profile 记录了。

db.system.profile.find()
{"ts" : "Thu Jan 29 2009 15:19:32 GMT-0500 (EST)" , "info" : "query test.$cmd ntoreturn:1 reslen:66 nscanned:0
query: { profile: 2 }  nreturned:1 bytes:50" , "millis" : 0}
db.system.profile.find( { info: /test.foo/ } )
{"ts" : "Thu Jan 29 2009 15:19:40 GMT-0500 (EST)" , "info" : "insert test.foo" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:19:42 GMT-0500 (EST)" , "info" : "insert test.foo" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:19:45 GMT-0500 (EST)" , "info" : "query test.foo ntoreturn:0 reslen:102 nscanned:2
query: {}  nreturned:2 bytes:86" , "millis" : 0}

查看最新的 Profile 记录：

db.system.profile.find().sort({$natural:-1})

 Profile 信息内容详解：
ts-该命令在何时执行.
millis Time-该命令执行耗时，以毫秒记.
info-本命令的详细信息.
query-表明这是一个query查询操作.

ntoreturn-本次查询客户端要求返回的记录数.比如, findOne()命令执行时 ntoreturn 为 1.有limit(n) 条件时ntoreturn为n.
query-具体的查询条件（如x>3）.
nscanned-本次查询扫描的记录数.
reslen-返回结果集的大小.
nreturned-本次查询实际返回的结果集.

update-表明这是一个update更新操作.

fastmod-Indicates a fast modify operation. See Updates. These operations are normally quite fast.
fastmodinsert – indicates a fast modify operation that performed an upsert.
upsert-表明update的upsert参数为true.此参数的功能是如果update的记录不存在，则用update的条件insert一条记录.
moved-表明本次update是否移动了硬盘上的数据，如果新记录比原记录短，通常不会移动当前记录，如果新记录比原记录长，那么可能会移动记录到其它位置，这时候会导致相关索引的更新.磁盘操作更多，加上索引更新，会使得这样的操作比较慢.

insert-这是一个insert插入操作.
getmore-这是一个getmore 操作，getmore通常发生在结果集比较大的查询时，第一个query返回了部分结果，后续的结果是通过getmore来获取的。

如果只查看query的筛选方法如下：

 db.system.profile.find({"op":"query"})