Database Reference
In-Depth Information
U
SING
THE
PROFILER
For identifying slow queries, you can't beat the built-in profiler. Profiling is disabled by
default, so let's get started by enabling it. From the MongoDB shell, enter the following:
use stocks
db.setProfilingLevel(2)
First you select the database you want to profile; profiling is always scoped to a particu-
lar database. Then you set the profiling level to
2
. This is the most verbose level; it
directs the profiler to log every read and write. A couple other options are available.
To l o g o n l y s l o w ( 1 0 0 m s ) o pe r a ti o n s , s e t t h e p r o f i l in g l e v e l t o
1
. To disable the query
profiler altogether, set it to
0
. And to log only operations taking longer than a certain
threshold in milliseconds, pass the number of milliseconds as the second argument
like this:
use stocks
db.setProfilingLevel(1, 50)
Once you've enabled the profiler, it's time to issue some queries. Let's run another
query on the stocks database. Try finding the highest closing price in the data set:
db.values.find({}).sort({close: -1}).limit(1)
The profiling results are stored in a special capped collection called
system.profile
.
Recall that capped collections are fixed in size and that data is written to them in a cir-
cular way so that once the collection reaches its max size, new documents overwrite
the oldest documents. The
system.profile
collection is allocated 128
KB
, thus ensur-
ing that the profile data never consumes much in the way of resources.
You can query
system.profile
as you would any capped collection. For instance,
you can find all queries that took longer than 150 ms like so:
db.system.profile.find({millis: {$gt: 150}})
And because capped collections maintain natural insertion order, you can use the
$natural
operator to sort so that the most recent results are displayed first:
db.system.profile.find().sort({$natural: -1}).limit(5)
Returning to the query you just issued, you should see an entry in the result set that
looks something like this:
{ "ts" : ISODate("2011-09-22T22:42:38.332Z"),
"op" : "query", "ns" : "stocks.values",
"query" : { "query" : { }, "orderby" : { "close" : -1 } },
"ntoreturn" : 1, "nscanned" : 4308303, "scanAndOrder" : true,
"nreturned" : 1, "responseLength" : 194, "millis" : 14576,
"client" : "127.0.0.1", "user" : "" }
Another expensive query: this one took nearly 15 seconds! In addition to the time it
took to complete, you get all same information about the query that you saw in the
MongoDB log's slow query warning, which is enough to start the deeper investigation
that we'll cover in the next section.
