使用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 }

{ "was" : 1, "slowms" : 0 }

注：此時會導緻執行個體下任何庫的任何查詢都會被記錄到日志中

3.分别在不同庫下查詢

執行上述指令後，日志居然會記錄下來

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 }

{ "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 }

原因分析：

首先我們來看一下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！