慢查詢?cè)跀?shù)據(jù)庫(kù)分析中是一個(gè)非常重要的參考。
我記得在PostgreSQL Conference 2009 中曾經(jīng)就有人專門(mén)講解了Hit the mole.（90%的數(shù)據(jù)庫(kù)性能問(wèn)題往往出現(xiàn)在10%的SQL上面.）
在MySQL,PostgreSQL數(shù)據(jù)庫(kù)中，用日志來(lái)記錄慢查詢。（比如為數(shù)據(jù)庫(kù)設(shè)置一下閥值100MS,運(yùn)行時(shí)間超過(guò)100MS的SQL將記錄到日志中.）
在mongoDB中也比較類似，使用profile 來(lái)配置慢查詢的閥值.已經(jīng)是否開(kāi)啟記錄慢查詢的功能。mongoDB的慢查詢被記錄到system.profile collection中。
在mongoDB? 1.7.x 以下版本中使用getProfilingLevel()查看當(dāng)前配置的數(shù)據(jù)庫(kù)profile.1.7.x以后改為getProfilingStatus().
配置profile可以通過(guò)參數(shù)文件,或在mongo shell中執(zhí)行命令來(lái)配置.
1. 參數(shù)文件
? --profile arg???????? 0=off 1=slow, 2=all? (0表示關(guān)閉profile,1表示只記錄執(zhí)行時(shí)間超過(guò)slowms配置的值的執(zhí)行內(nèi)容,2表示記錄所有執(zhí)行內(nèi)容)
? --slowms arg (=100)?? value of slow for profile and console log (如果profile配置為1并且沒(méi)有配置slowms的話默認(rèn)是100毫秒)
2. mongo shell
??db.setProfilingLevel( level , slowms )?
3. 查看profile
> db.getProfilingLevel()
1

配置舉例:
# 配置slowms=1,profile=1
> db.setProfilingLevel(1,1)?
{ "was" : 0, "slowms" : 100, "ok" : 1 }

# 注意這里返回的slowms : 100,實(shí)際上已經(jīng)配置為1了，估計(jì)是個(gè)BUG。在1.7.x里面可以通過(guò)以下命令查看:
> db.getProfilingStatus()
{ "was" : 1, "slowms" : 1 }

# 插入測(cè)試數(shù)據(jù)
> for (var i=0;i<10000;i++) {
... db.userinfo.insert({"firstname" : "zhou","lastname" : "digoal" + i,"age" : i})
... }

# 在1.6.5的環(huán)境下,沒(méi)有辦法通過(guò)db.getProfilingLevel()查看slowms的具體配置,不過(guò)通過(guò)以下測(cè)試可以知道,前面配置的slowms=1已經(jīng)生效.
> db.userinfo.find({"firstname" : "zhou"}).explain()
{
"cursor" : "BasicCursor",
"nscanned" : 10000,
"nscannedObjects" : 10000,
"n" : 10000,
"millis" : 5,
"indexBounds" : {

}
}
> db.system.profile.find()
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000 \nquery: { query: { firstname: \"zhou\" }, $explain: true } nreturned:1 5ms", "millis" : 5 }

# 使用以下方式查看效果也是一樣的
> db.system.profile.find( function() { return this.info.indexOf('$cmd')<0; } )
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000 \nquery: { query: { firstname: \"zhou\" }, $explain: true } nreturned:1 5ms", "millis" : 5 }
# 也可以使用規(guī)則表達(dá)式過(guò)濾出你關(guān)心的collection,如下.
> db.system.profile.find({"info" : /userinfo/})??
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000? \nquery: { query: { firstname: \"zhou\" }, $explain: true }? nreturned:1 5ms", "millis" : 5 }

# 或者按millis排個(gè)序
> db.system.profile.find().sort({"millis" : -1})
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000? \nquery: { query: { firstname: \"zhou\" }, $explain: true }? nreturned:1 5ms", "millis" : 5 }
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }

# 由于system.profile是capped collection,使用$natural? 可以按照記錄插入的插入順序查看結(jié)果.
> db.system.profile.find().sort({"$natural" : -1})??
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000? \nquery: { query: { firstname: \"zhou\" }, $explain: true }? nreturned:1 5ms", "millis" : 5 }
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }

# 使用show profile 查看最近5%的超過(guò)1ms執(zhí)行時(shí)間的事件
> show profile

5ms Sun Jan 09 2011 09:07:21
query admin.userinfo reslen:202 nscanned:10000??
query: { query: { firstname: "zhou" }, $explain: true }? nreturned:1 5ms


1ms Sun Jan 09 2011 09:02:56
insert admin.userinfo

輸出格式:
1. ts : 記錄下捕獲的時(shí)間戳,(SQL執(zhí)行結(jié)束時(shí)間,如下)
> Date()
Sun Jan 09 2011 09:42:31 GMT+0800 (CST)
> db.userinfo.ensureIndex({"lastname" : 1,"detail.city" : 1})
> db.system.profile.find().sort({"$natural" : -1}).limit(1)
{ "ts" : "Sun Jan 09 2011 09:42:46 GMT+0800 (CST)", "info" : "insert admin.system.indexes 14374ms", "millis" : 14374 }
# 從時(shí)間上看是執(zhí)行結(jié)束時(shí)間.
2.?millis : 執(zhí)行時(shí)間,注意不包含lock請(qǐng)求時(shí)間和network傳輸時(shí)間，只包含了server處理這條請(qǐng)求的時(shí)間.
3. info : 執(zhí)行詳細(xì)信息,包含(query,update,insert,getmore)
??????? query : 數(shù)據(jù)庫(kù)查詢操作,包含以下信息:
??????????????? ntoreturn : Number of objects the client requested for return from a query. For example, <code>findOne()</code> sets ntoreturn to 1.<code>limit()</code> sets the appropriate limit. Zero indicates no limit.
??????????????? query : Details of the query spec.
??????????????? nscanned : Number of objects scanned in executing the operation.
??????????????? reslen : Query result length in bytes.
??????????????? nreturned : Number of objects returned from query.
???????? update : A database update operation. <code>save()</code> calls generate either an update or insert operation.
????????????????? 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 : Indicates on upsert performed.
????????????????? moved : Indicates the update moved the object on disk (not updated in place). This is slower than an in place update, and normally occurs when an object grows.
????????? insert : A database insert.
????????? getmore : For large queries, the database initially returns partial information. getmore indicates a call to retrieve further information.
# 例:
> db.userinfo.find().sort({"age" : -1}).limit(1)?????
{ "_id" : ObjectId("4d2910734f7371f2497bd6ad"), "firstname" : "zhou", "lastname" : "digoal999998", "age" : 999998, "detail" : { "city" : "HangZhou", "corp" : "sky-mobi" } }
> db.system.profile.find().sort({"$natural" : -1}).limit(1)
{ "ts" : "Sun Jan 09 2011 09:53:42 GMT+0800 (CST)", "info" : "query admin.userinfo ntoreturn:1 scanAndOrder? reslen:169 nscanned:2009998? \nquery: { query: {}, orderby: { age: -1.0 } }? nreturned:1 3140ms", "millis" : 3140 }
# 性能優(yōu)化相關(guān)
從上面的profile結(jié)果看出ntoreturn = 1,nscanned = 2009998，也就是說(shuō)返回結(jié)果是1條，但是掃描了200多W條記錄。如果這種查詢非常多的話建議在"age"上建立索引。對(duì)于update操作同樣適用.（當(dāng)然，還要考慮索引對(duì)寫(xiě)入帶來(lái)的overhead）
如果reslen這個(gè)值比較大,表示返回結(jié)果非常多,建議調(diào)整find()限制輸出結(jié)果.

調(diào)整profileSIZE:
1. 關(guān)閉profile
> db.setProfilingLevel(0)
{ "was" : 1, "slowms" : 1, "ok" : 1 }
2. 調(diào)整profile size
> db.system.profile.renameCollection("system.oldprofile")
{ "ok" : 1 }
> show collections???????????????????????????????????????
system.indexes
system.oldprofile
system.users
userinfo
version
# 調(diào)整為100MB
> db.createCollection("system.profile",{"capped" : true, "size" : 102400000})
{ "ok" : 1 }
> db.system.profile.stats()??????????????????????????????????????????????????
{
??????? "ns" : "admin.system.profile",
??????? "count" : 0,
??????? "size" : 0,
??????? "avgObjSize" : NaN,
??????? "storageSize" : 102400256,
??????? "numExtents" : 1,
??????? "nindexes" : 0,
??????? "lastExtentSize" : 102400256,
??????? "paddingFactor" : 1,
??????? "flags" : 0,
??????? "totalIndexSize" : 0,
??????? "indexSizes" : {

??????? },
??????? "capped" : 1,
??????? "max" : 2147483647,
??????? "ok" : 1
}
3. 重新開(kāi)啟profile
> db.setProfilingLevel(1,1)
{ "was" : 0, "slowms" : 1, "ok" : 1 }
4. oldprofile中的數(shù)據(jù)無(wú)法插入到profile
測(cè)試:
> for (var c = db.system.oldprofile.find(); c.hasNext();) {
... b = c.next();
... db.system.profile.insert({"ts" : c.ts,"info" : c.info,"millis" : c.millis});?
... }
> db.system.profile.count()
0
# 沒(méi)有插進(jìn)去
# 非常抱歉,插入到test是OK的.system.profile 不可以手工插入記錄
> for (var c = db.system.oldprofile.find(); c.hasNext();) {??????????????
... b = c.next();
... db.test.insert({"ts" : c.ts,"info" : c.info,"millis" : c.millis});??????????
... }
> db.test.count()
6

5. 刪除oldprofile
> db.system.oldprofile.drop()
Sun Jan? 9 10:38:57 uncaught exception: drop failed: {
??????? "ns" : "admin.system.oldprofile",
??????? "errmsg" : "exception: can't drop system ns",
??????? "code" : 12502,
??????? "ok" : 0
}
# system下面的collection不允許刪除,所以要先rename一下.
> db.system.oldprofile.renameCollection("oldprofile")
{ "ok" : 1 }
> db.oldprofile.drop()
true

注意事項(xiàng):
1. system.profile 是capped collection,默認(rèn)配置比較小,所以如果需要放更多的內(nèi)容需要調(diào)整size和max (具體的話可以參考我以前寫(xiě)過(guò)的capped collection topic)
如:
> db.system.profile.stats()?
{
??????? "ns" : "admin.system.profile",
??????? "count" : 1,
??????? "size" : 68,
??????? "avgObjSize" : 68,
??????? "storageSize" : 131328,
??????? "numExtents" : 1,
??????? "nindexes" : 0,
??????? "lastExtentSize" : 131328,
??????? "paddingFactor" : 1,
??????? "flags" : 0,
??????? "totalIndexSize" : 0,
??????? "indexSizes" : {

??????? },
??????? "capped" : 1,
??????? "max" : 2147483647,
??????? "ok" : 1
}
> db.system.profile.totalSize()
131328

2. 開(kāi)啟profile對(duì)性能略有影響.

3. 通過(guò)命令行開(kāi)啟profile只對(duì)當(dāng)前數(shù)據(jù)庫(kù)生效,并且重啟數(shù)據(jù)庫(kù)后失效.
# 例如在admin庫(kù)中使用mongo shell開(kāi)啟了profile，轉(zhuǎn)到test庫(kù)后是沒(méi)有開(kāi)啟的.
> use test
switched to db test
> show collections
system.indexes
system.users
userinfo
> db.getProfilingLevel()
0
> db.setProfilingLevel(1,1)
{ "was" : 0, "slowms" : 1, "ok" : 1 }
> db.getProfilingLevel()???
1
# 使用mongo shell開(kāi)啟的profile重啟后失效,如下
# 重啟mongoDB
[root@db5 ~]# /opt/mongodb/bin/mongo 127.0.0.1:5281/admin
MongoDB shell version: 1.6.5
connecting to: 127.0.0.1:5281/admin
> db.auth("digoal","DIGOAL")
1
> db.getProfilingLevel()
0
# 顯然system.profile是還在的.
> show collections
system.indexes
system.profile
system.users
userinfo
version
> db.system.profile.find()
{ "ts" : "Sun Jan 09 2011 09:02:56 GMT+0800 (CST)", "info" : "insert admin.userinfo", "millis" : 1 }
{ "ts" : "Sun Jan 09 2011 09:07:21 GMT+0800 (CST)", "info" : "query admin.userinfo reslen:202 nscanned:10000? \nquery: { query: { firstname: \"zhou\" }, $explain: true }? nreturned:1 5ms", "millis" : 5 }

4. system.profile 不可以手工插入記錄

總結(jié)

以上是生活随笔為你收集整理的Using mongoDB's Profiler analyze the performance of database operations的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。