We can enable profiling from the command line as well as from the mongo console. Let's start it from the command line, as follows:
$ sudo mongod run --config /etc/mongodb.conf --rest -vvvv --profile=1
This enables the profiling and sets it at level 1.
Tip
There are three modes of profiling:
0: This indicates profiling is disabled.
1: This indicates profiling suited to write only slow operations.
2: This indicates profiling suited to write all operations.
Even if profiling is disabled, the slow queries (the ones taking longer than 100 ms by default) get logged to the console!
If you already have a MongoDB service running, we can enable this from the mongo console, too. This can be done as follows:
mongo> db.setProfilingLevel(1)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
mongo>
To see profiling in action, we can issue the following commands on the mongo console:
mongo> db.system.profile.find()
{ "ts" : ISODate("2012-06-08T07:26:43.186Z"), "op" : "query", "ns" : "sodibee_development.authors", "query" : { "name" : /in/ }, "nscanned" : 609, "nreturned" : 101, "responseLength" : 6613, "millis" : 10, "client" : "127.0.0.1", "user" : "" }
When we enable profiling, the information is logged in to the db.system.profile collection. Let's dig deeper. Have a look at the following:
mongo> db.setProfilingLevel(1)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
mongo>
The slowms option tells MongoDB what should be the threshold time for slow queries. The was field tells us what the earlier profiling level was. Now, let's see a profile log. Execute the following command:
mongo> db.system.profile.find()
{ "ts" : ISODate("2012-06-08T07:26:43.186Z"),
"op" : "query", "ns" : "sodibee_development.authors",
"query" : { "name" : /in/ }, "nscanned" : 609, "nreturned" : 101, "responseLength" : 6613, "millis" : 10, "client" : "127.0.0.1", "user" : "" }
In the preceding command op and ns parameters specify the operation and the collection that was profiled. The query parameter logs the query that was fired. The nscanned parameter specifies the number of objects that were scanned for fetching the result. The nreturned parameter specifies the number of objects in the result.
Tip
Optimization and performance tuning — tip 1
If you see that the nscanned parameter is much higher than nreturned, it means that there are a lot of unnecessary objects being scanned.
To resolve this, add an index on these fields used in the search criteria.
Have a look at the previous command a third time:
mongo> db.system.profile.find()
{ "ts" : ISODate("2012-06-08T07:26:43.186Z"),
"op" : "query", "ns" : "sodibee_development.authors",
"query" : { "name" : /in/ }, "nscanned" : 609, "nreturned" : 101,
"responseLength" : 6613, "millis" : 10,
"client" : "127.0.0.1", "user" : ""
}
The responseLength or reslen parameter specifies the number of bytes in the result and the millis parameter indicates the time in milliseconds taken by MongoDB for processing this query.
Tip
Optimization and performance tuning — tip 2
If you see that reslen is huge—a few hundred kilobytes or more—the resultant data being returned is huge and this impacts on the performance. Use the field selector in the find method to retrieve only the fields you need.
If I need only the names of authors, we can optimize the query to db.authors.find({ name: /in/ }, {name: 1}), so that it will fetch the authors that have an in in their name but return only their names and not all the fields. This will reduce the length of the result set.