线上发现查询mongodb中的用户积分变慢(超过2s),mongodb有和mysql类似的慢查询诊断方法,先开启慢查询:
连上mongodb控制台,开启慢查询功能**:
[root@mongo ~]# mongo
mncg:PRIMARY> use admin
mncg:PRIMARY> db.auth('admin','*****')
mncg:PRIMARY> db.getProfilingLevel()
0
mncg:PRIMARY> db.setProfilingLevel(1,1000)
{ "was" : 0, "slowms" : 1000, "ok" : 1 }
mncg:PRIMARY> db.getProfilingLevel()
1 (已开启)
命令说明:
-- 查看跟踪级别(0为关闭,1是定义慢操作及时间,2是跟踪所有操作)
db.getProfilingLevel()
-- 设置慢操作级别和慢时间定义,单位毫秒(默认100ms)
db.setProfilingLevel(1,1000)
-- 查看当前设置
db.getProfilingStatus()
-- 禁用则设置为0
db.setProfilingLevel(0)
-- 也可以启动服务时设置
mongod --profile=1 --slowms=1000
此时我们从mongodb日志文件(看mongod.conf的中配置,我这里是/opt/mongodb-3.2.5/mongod.log
)中可以看到哪些超过1秒的慢查询,观察发现有以下慢查询:
2017-04-01T11:09:29.624+0800 I COMMAND [conn707607] query scoredb.user_score query: { orderby:score:−1, query: { orgId: 10, createDay: 20170331 } } planSummary: COLLSCAN, COLLSCAN cursorid:395774433451 ntoreturn:30 ntoskip:0 nscanned:0 nscannedObjects:231417 scanAndOrder:1 keyUpdates:0 writeConflicts:0 numYields:2092 nreturned:30 reslen:13697 locks:{ Global: { acquireCount: { r: 4186 } }, MMAPV1Journal: { acquireCount: { r: 2093 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 8825 } }, Database: { acquireCount: { r: 2093 } }, Collection: { acquireCount: { R: 2093 } } } 2284ms
发现scoredb.user_score query: { orderby:score:−1, query: { orgId: 10, createDay: 20170331 } } 这个耗时2.2s,explain分析一下这条查询:
db.user_score.find({ orgId: 10, createDay: 20170331}).sort({score: -1}).explain();
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "scoredb.user_score",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"createDay" : {
"$eq" : 20170331
}
},
{
"orgId" : {
"$eq" : 10
}
}
]
},
"winningPlan" : {
"stage" : "SORT",
"sortPattern" : {
"score" : -1
},
"inputStage" : {
"stage" : "COLLSCAN",
"filter" : {
"$and" : [
{
"createDay" : {
"$eq" : 20170331
}
},
{
"orgId" : {
"$eq" : 10
}
}
]
},
"direction" : "forward"
}
},
"rejectedPlans" : [ ]
}
"ok" : 1
}
从上面的解析结果可以看出,这条语句没有用到索引,创建索引:
db.user_score.ensureIndex({“orgId”:1, createDay: 1, score: -1},{background:1,unique:0,”name”:”idx_user_score_score_order”});
{
"queryPlanner" : {
"plannerVersion" : 1,
"namespace" : "scoredb.user_score",
"indexFilterSet" : false,
"parsedQuery" : {
"$and" : [
{
"createDay" : {
"$eq" : 20170331 }
},
{
"orgId" : {
"$eq" : 10 }
}
]
},
"winningPlan" : {
"stage" : "FETCH",
"inputStage" : {
"stage" : "IXSCAN",
"keyPattern" : {
"orgId" : 1,
"createDay" : 1,
"score" : -1 },
"indexName" : "idx_user_score_score_order",
"isMultiKey" : false,
"direction" : "forward",
"indexBounds" : {
"orgId" : [ "[10.0, 10.0]" ],
"createDay" : [ "[20170331.0, 20170331.0]" ],
"score" : [ "[MaxKey, MinKey]" ] }
}
},
"rejectedPlans" : [ ]
},
"ok" : 1
}
再次explain后,该语句已用上索引idx_user_score_score_order,再次访问接口时已非常快(20ms)!
附:更多诊断命令
1. mongostat:
查看mongoDB实例的统计信息 字段说明:
insert: 每秒插入量
query: 每秒查询量
update: 每秒更新量
delete: 每秒删除量
locked: 锁定量
qr | qw: 客户端查询排队长度(读|写)
ar | aw: 活跃客户端量(读|写)
conn: 连接数
time: 当前时间
它每秒钟刷新一次状态值,提供良好的可读性,通过这些参数可以观察到一个整体的性能情况。
[root@mongo bin]# ./mongostat -h 127.0.0.1 -u user -p p**** –authenticationDatabase=admin
insert query update delete getmore command flushes mapped vsize res faults qr|qw ar|aw netIn netOut conn set repl time
*0 *0 *0 *0 0 1|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 79b 13k 5 yongPRI 2017-04-01T13:42:27+08:00
*0 *0 *0 *0 0 3|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 195b 13k 5 yongPRI 2017-04-01T13:42:28+08:00
*0 *0 *0 *0 0 1|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 79b 13k 5 yongPRI 2017-04-01T13:42:29+08:00
*0 *0 *0 *0 0 3|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 195b 13k 5 yongPRI 2017-04-01T13:42:30+08:00
*0 *0 *0 *0 0 1|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 79b 13k 5 yongPRI 2017-04-01T13:42:31+08:00
*0 *0 *0 *0 0 3|0 0 992.0M 2.4G 166.0M 0 0|0 0|0 195b 13k 5 yongPRI 2017-04-01T13:42:32+08:00
2.db.serverStatus
查看实例运行状态
{
"host" : "mongo.xxx",
"advisoryHostFQDNs" : [
"mongo.mg.addr"
],
"version" : "3.2.5",
"process" : "mongod",
"pid" : NumberLong(2612),
"uptime" : 4507921,
"uptimeMillis" : NumberLong("4507920428"),
"uptimeEstimate" : 4400471,
"localTime" : ISODate("2017-04-01T06:27:47.470Z"),
"asserts" : {
"regular" : 0,
"warning" : 0,
"msg" : 0,
"user" : 1216,
"rollovers" : 0
},
"backgroundFlushing" : {
"flushes" : 75131,
"total_ms" : 1292618,
"average_ms" : 17.204855519026765,
"last_ms" : 29,
"last_finished" : ISODate("2017-04-01T06:27:21.165Z")
},
"connections" : {
"current" : 5,
"available" : 814,
"totalCreated" : NumberLong(169079)
}, ...
}
3.db.stats
db.stats 查看数据库状态信息:
yong:PRIMARY> db.stats()
{
"db" : "scoredb",
"collections" : 19,
"objects" : 256863,
"avgObjSize" : 366.16151022140207,
"dataSize" : 94053344,
"storageSize" : 141041664,
"numExtents" : 75,
"indexes" : 25,
"indexSize" : 8723792,
"fileSize" : 201326592,
"nsSizeMB" : 16,
"extentFreeList" : {
"num" : 0,
"totalSize" : 0
},
"dataFileVersion" : {
"major" : 4,
"minor" : 22
},
"ok" : 1
}