Mongodb慢查询笔记 (Mongodb slow query log)

-- ===========================
-- mongodb slow query log
-- ===========================

Reference: http://docs.mongodb.org/manual/tutorial/manage-the-database-profiler/

Profiling Levels：
1 resume
0 - the profiler is off, does not collect any data.
1 - collects profiling data for slow operations only. By default slow operations are those slower than 100 milliseconds.
You can modify the threshold for “slow” operations with the slowms runtime option or the setParameter command. See the Specify the Threshold for Slow Operations section for more information.
2 - collects profiling data for all database operations.

2 able
2.1
db.setProfilingLevel(1,500);
db.setProfilingLevel(2,500);
PRIMARY> db.setProfilingLevel(1,500);
{ "was" : 0, "slowms" : 500, "ok" : 1 }
PRIMARY>
PRIMARY>
PRIMARY>
PRIMARY> db.setProfilingLevel(1,500);
{ "was" : 1, "slowms" : 500, "ok" : 1 }
PRIMARY>
PRIMARY>
PRIMARY>
疑问：为什么需要set2次才能生效？
0代表关闭，1代表只记录slowlog，2代表记录所有操作，这里我们设置成了500，也就是500ms

2.2 check the status
PRIMARY> db.getProfilingStatus();
{ "was" : 2, "slowms" : 500 }
PRIMARY> db.getProfilingLevel();
PRIMARY>

2.3 see the last log info
db.system.profile.find().sort({$natural:-1})
PRIMARY> db.system.profile.find().sort({$natural:-1})
{ "ts" : ISODate("2013-05-14T08:13:37.098Z"), "op" : "insert", "ns" : "test.tickets", "millis" : 0, "client" : "127.0.0.1", "user" : "" }
{ "ts" : ISODate("2013-05-14T08:13:37.098Z"), "op" : "insert", "ns" : "test.tickets", "millis" : 0, "client" : "127.0.0.1", "user" : "" }
{ "ts" : ISODate("2013-05-14T08:13:37.098Z"), "op" : "insert", "ns" : "test.tickets", "millis" : 0, "client" : "127.0.0.1", "user" : "" }
PRIMARY>
ts：时间戳
op: 操作类型
ns：执行操作的对象集合
millis：操作所花时间，毫秒
client: 执行操作的客户端
user: 执行操作的mongodb连接用户

2.4 可以在mongodb启动之初设置slow生效
直接加在启动命令中：mongod --profile=1 --slowms=15
或者在配置文件中写好 用-f强制加载配置文件启动mongodb
profile=1
slowms=1000
[] 在replicaset中，必须把一个个instance都生效才行。每一个都需要生效一次。

3 see the log
db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty();
db.system.profile.find().limit(10).sort( { ts : 1 } ).pretty();

4 Disable Profiling
To disable profiling, use the following helper in the mongo shell: set the default value 0;
db.setProfilingLevel(0)

5 当profile表过小时，调整表大小为4MB
db.setProfilingLevel(0) -- profile失效
db.system.profile.drop() -- 删除
db.createCollection( "system.profile", { capped: true, size:4000000 } ) -- 重建
db.setProfilingLevel(1) -- profile生效

6 查看出来的慢mongo命令
6.1 显示最新的5条操作记录
show profile;

6.2 显示结果分析，查询大于5毫秒的slow command。
db.system.profile.find().sort({millis:-1}).limit(10);
db.system.profile.find( { millis : { $gt : 5 } } ).pretty();
{
"ts" : ISODate("2013-01-16T18:26:18.041Z"),
"op" : "query", -- 执行类型
"ns" : "ssodatabase.exchangetickets", -- 执行collection名称
"query" : {
"xid" : "X15e1481688254bc9a94701b3aa9e7abc627971358360754783"
}, -- 执行的内容
"ntoreturn" : 1,
"nscanned" : 382793,
"nreturned" : 1,
"responseLength" : 605,
"millis" : 5841, -- 执行的时间
"client" : "10.100.10.161", -- 执行的客户端
"user" : "" -- 执行的mongo用户
}
观察结果中的"query"字段。 没有直接db.test.insert({xxxxxxx.....})这样显示的，需要你自己根据query字段去拼接取值.

7 返回特定时间的慢查询记录
7.1普通的时间短查询
db.system.profile.find(
{
ts : {
$gt : new ISODate("2013-05-09T03:00:00Z") ,
$lt : new ISODate("2013-05-17T03:40:00Z")
}
}
).pretty();

run the command, follows:
PRIMARY> db.system.profile.find(
... {
... ts : {
... $gt : new ISODate("2013-05-09T03:00:00Z") ,
... $lt : new ISODate("2013-05-17T03:40:00Z")
... }
... }
... ).pretty();

{
"ts" : ISODate("2013-05-14T08:36:58.691Z"),
"op" : "query",
"ns" : "ssodatabase.digitalriverorderdetails",
"query" : {
"invoiceId" : "15539232823"
},
"ntoreturn" : 1,
"nscanned" : 1,
"nreturned" : 1,
"responseLength" : 1213,
"millis" : 663,
"client" : "10.100.10.162",
"user" : "admin"
}
{
"ts" : ISODate("2013-05-14T09:17:58.911Z"),
"op" : "insert",
"ns" : "ssodatabase.tickets",
"millis" : 527,
"client" : "10.100.10.154",
"user" : "admin"
}
{
"ts" : ISODate("2013-05-14T09:20:58.648Z"),
"op" : "insert",
"ns" : "ssodatabase.tickets",
"millis" : 529,
"client" : "10.100.10.153",
"user" : "admin"
}
......

7.2 带执行时间倒序排序,并且只输出用户信息
db.system.profile.find(
{
ts : {
$gt : new ISODate("2013-05-09T03:00:00Z") ,
$lt : new ISODate("2013-05-17T09:40:00Z")
}
},
{ user : 1 } -- 只输出用户信息
).sort( { millis : -1 } ) -- 倒序排序

PRIMARY> db.system.profile.find(
... {
... ts : {
... $gt : new ISODate("2013-05-09T03:00:00Z") ,
... $lt : new ISODate("2013-05-17T09:40:00Z")
... }
... },
... { user : 1 }
... ).sort( { millis : -1 } )
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }
{ "user" : "admin" }

7.3 带执行时间倒序排序,并且只输出用户信息
db.system.profile.find(
{
ts : {
$gt : new ISODate("2013-05-09T03:00:00Z") ,
$lt : new ISODate("2013-05-17T09:40:00Z")
}
}
).sort( { millis : -1 } ) -- 倒序排序