MongoDB数据库分析器

一、引言

当数据库运行慢时，我们需要找出其中的性能瓶颈。找出性能瓶颈的第一步就是找出数据库正在忙什么，然后再找出其中最慢的操作进行优化。MongoDB提供了数据库分析器收集在实例上执行的写操作、游标、命令等详细信息。MongoDB数据库分析器可以在实例级别打开，也可以在数据库级别打开。
MongoDB数据库分析器可以设置三个级别：
0 - 分析器处在关闭状态，不收集任何数据
1 - 仅仅收集较慢操作的分析数据。默认情况下如果一个操作花费的时间超过100ms，就认为是较慢的操作。
2 - 收集所有数据库操作的分析数据。

二、system.profile集合

MongoDB数据库分析器收集的数据将存放在system.profile集合中。system.profile是一个固定大小的集合，数据将循环写入该集合。当用完所有分配的空间后，MongoDB将会覆盖集合中最老的文档。默认情况下，system.profile集合大小为4M。

system.profile集合常用的字段包括：
ts：数据库操作发生的时间戳
op：操作类型，可能的取值为insert,query,update,remove,getmore,command
ns：操作对象的名字
query：查询语句
nreturned:返回的文档数
nscanned：为执行操作扫描的文档数
millis：执行操作花费的时间

三、设置数据库分析器级别

MongoDB数据库分析器具有三个级别，可以通过mongo Shell设置：

db.getProfilingLevel():获取当前的profile级别

db.getProfilingStatus()：获取当前的profile级别，同时返回slowms阈值。

db.setProfilingLevel()：设置profile级别

我们可以尝试着把分析器级别设置为1，把slowms设置为500ms:

db.setProfilingLevel(1,500)
{ "was" : 0, "slowms" : 100, "ok" : 1 }

执行结果中was字段显示原分析器级别为0，slowms字段显示原慢操作阈值为100ms。使db.getProfilingStatus()查询新的分析器设置：

db.getProfilingStatus()
{ "was" : 1, "slowms" : 500 }

执行结果显示分析器级别已设置为1，表明mongodb将记录执行时间超过500ms的所有操作。

四、查看分析器数据并进行分析

首先我们进行初始的数据准备，建立mydb库，在其中建test集合，并插入1000万条数据：

use mydb

db.test.drop()

for (var i=1;i<=10000000;i++)   db.test.insert({empno:i,name:i,address:'AAAAAAAAAAAAAAAAAAAAAAAAAAA'})

清空system.profile集合，设置分析级别为2，慢操作的阈值为100ms：
use mydb
db.setProfilingLevel(0)
db.system.profile.drop()
db.setProfilingLevel(2,100)

在没有索引的情况下查询empno大于99999999的文档：

db.test.find({empno:{$gt:9999999}})

查询到一条结果，因此网络：
{ "_id" : ObjectId("523ad4d465fdfe550ae05d97"), "empno" : 10000000, "name" : 10000000, "address" : "AAAAAAAAAAAAAAAAAAAAAAAAAAA" }

在empno创建索引：

db.test.ensureIndex({empno:1})

重新查询empno大于99999999的文档得到的结果相同。

查询system.profile中存储的分析数据，按照发生的时间排序：

db.system.profile.find().limit(10).sort( { ts : 1 } ).pretty()

得到结果：
{
        "op" : "query",
        "ns" : "mydb.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(44),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(2),
                        "w" : NumberLong(57806)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "ts" : ISODate("2013-09-19T10:47:00.656Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "userSource" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "query",
        "ns" : "mydb.test",
        "query" : {
                "empno" : {
                        "$gt" : 9999999
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 10000000,
        "keyUpdates" : 0,
        "numYield" : 29,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(59258536),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(29469480),
                        "w" : NumberLong(6)
                }
        },
        "nreturned" : 1,
        "responseLength" : 112,
        "millis" : 29861,
        "ts" : ISODate("2013-09-19T10:47:21.476Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "mydb.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(171),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(8),
                        "w" : NumberLong(4)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "ts" : ISODate("2013-09-19T10:48:00.661Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "userSource" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "query",
        "ns" : "mydb.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(41),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "ts" : ISODate("2013-09-19T10:49:00.677Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "userSource" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "insert",
        "ns" : "mydb.system.indexes",
        "query" : {
                "v" : 1,
                "key" : {
                        "empno" : 1
                },
                "ns" : "mydb.test",
                "name" : "empno_1"
        },
        "ninserted" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(0),
                        "w" : NumberLong(145940925)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(0),
                        "w" : NumberLong(292871)
                }
        },
        "millis" : 145977,
        "ts" : ISODate("2013-09-19T10:51:37.246Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "query",
        "ns" : "mydb.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 2,
        "keyUpdates" : 0,
        "numYield" : 1,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(598801),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(96316198),
                        "w" : NumberLong(13)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 1107,
        "ts" : ISODate("2013-09-19T10:51:38.122Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "userSource" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "query",
        "ns" : "mydb.system.indexes",
        "query" : {
                "expireAfterSeconds" : {
                        "$exists" : true
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 2,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(54),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(3),
                        "w" : NumberLong(2)
                }
        },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 0,
        "ts" : ISODate("2013-09-19T10:52:38.260Z"),
        "client" : "0.0.0.0",
        "allUsers" : [
                {
                        "user" : "__system",
                        "userSource" : "local"
                }
        ],
        "user" : "__system@local"
}
{
        "op" : "query",
        "ns" : "mydb.test",
        "query" : {
                "empno" : {
                        "$gt" : 9999999
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                "timeLockedMicros" : {
                        "r" : NumberLong(125810),
                        "w" : NumberLong(0)
                },
                "timeAcquiringMicros" : {
                        "r" : NumberLong(4),
                        "w" : NumberLong(6)
                }
        },
        "nreturned" : 1,
        "responseLength" : 112,
        "millis" : 125,
        "ts" : ISODate("2013-09-19T10:52:40.258Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}

我们看到执行的两次同样的查询和一次索引创建操作都在其中。
第一次查询的时间戳为2013-09-19T10:47:21.476Z，nscanned为1000万，nreturned为1 ，操作本身耗时29861ms。

上述查询是没有索引的情况下执行的，为优化查询，我们在empno上创建了索引。从system.profile查询结果可以看出创建索引的op为insert，操作的名字空间为mydb.system.indexes，创建的索引名称为empno_1。创建索引本身耗时145977ms。

我们第二次执行查询的时间戳为2013-09-19T10:52:40.258Z，nscanned为1，nreturned为1，操作本身耗时125ms。

从system.profile输出，我们可以看出有索引的查询要比没有索引的查询快很多。