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 } )  -- 倒序排序