In this recipe, we will look at Mongo's in-built profiler that will be used to profile the operations executed on the MongoDB server. It is a utility that is used to log all operations or the slow ones and that can be used to analyze the performance of the server.
In this recipe, we will be performing some operations on a standalone Mongo instance and profiling them. We need to start a standalone server listening to any port for client connections; in this case, we will stick to the default 27017. If you are not aware of how to start a standalone server, refer to the Single node installation of MongoDB recipe in Chapter 1, Installing and Starting the MongoDB Server. We also need to start a shell that will be used to perform querying, enable profiling, and view the profiling operation.
- Once the server is started and the shell is connected to it, execute the following to get the current profiling level:
> db.getProfilingLevel()The default level should be
0(no profiling if we have not set it earlier) - Let us set the profiling level to
1(log slow operations only) and log all the operations slower than 50 ms. Execute the following command on the shell:> db.setProfilingLevel(1, 50) - Now, let us execute an
insertoperation into a collection and then execute a couple of queries:> db.profilingTest.insert({i:1}) > db.profilingTest.find() > db.profilingTest.find({$where:'sleep(70)'})
- Now execute the query on the following collection as follows:
> db.system.profile.find().pretty()
Profiling is something that will not be enabled by default. If you are happy with the performance of the database, there is no reason to enable the profiler. It is only when one feels that there is some room for improvement and wants to target some expensive operations taking place. An important question is, what classifies an operation to be slow? The answer is, it varies from application to application. By default, in Mongo, slow means any operation above 100 ms. However, while setting the profiling level, you may choose the threshold value.
There are three possible values for profiling levels:
0: Disable profiling1: Enable profiling for slow operations where the threshold value for an operation to be classified as ''slow'' is provided with the call while setting the profiling level2: Profile all operations
While profiling all operations might not be a very good idea and might not commonly be used, as we shall soon see, setting the value to 1 with a threshold provided to it is a good way to monitor slow operations.
If we look at the steps we executed, we see that we can get the current profiling level by executing the db.getProfilingLevel() operation. To get more information, such as what value is set as a threshold for the slow operations, we can execute db.getProfilingStatus(), which returns a document with the profiling level and the threshold value for slow operations.
For setting the profiling level, we call the db.setProfilingLevel() method. In our case, we set it for logging all operations taking more than 50 ms as db.setProfilingLevel(1, 50).
To disable profiling, simply execute db.setProfilingLevel(0).
What we do next is execute three operations; one to insert a document, one to find all documents, and finally, a find that calls sleep with a value of 70 ms to slow it down.
The final step is to see these profiled operations that are logged in the system.profile collection. We execute a find operation to see the operations logged. For my execution, the insert and the final find operation with the sleep were logged.
Obviously, this profiling has some overhead but a negligible one. Hence, we will not enable it by default, but only when we want to profile slow operations. Also, another question is, will this profiling collection increase over a period of time? The answer is no, as this is a capped collection. Capped collections are fixed-size collections, which preserve insertion orders and act as circular queues filling in the new documents and discarding the oldest when it gets full. A query on system.namespaces should show the stats. The query execution will show the following output for the system.profile collection:
{"name":"test.system.profile", "options":{"capped":true, "size":1048576 }}
As we see, the size of the collection is 1 MB, which is incredibly small. Setting the profiling level to 2 will thus easily overwrite the data on busy systems. One may also choose to explicitly create a collection, with the name system.profile, as a capped collection of any size you prefer, should you choose to retain more operations in it. To create a capped collection explicitly, you may execute the following query from the Mongo shell:
> db.createCollection('system.profile', {capped:1, size: 1048576})
Obviously, the size chosen is arbitrary, and you are free to allocate any size to this collection, based on how frequently the data gets filled and how much profiling data you want to keep before it gets overwritten.
As this is a capped collection, and the insertion order is preserved, a query with the sort order {$natural:-1} will be perfectly fine and very efficient at finding operations in the reverse order of execution time.
Finally, we will take a look at the document that got inserted in the system.profile collection and see which operations it has logged:
{ "op" : "query", "ns" : "test.profilingTest", "query" : { "$where" : "sleep(70)" }, "ntoreturn" : 0, "ntoskip" : 0, "nscanned" : 1, "keyUpdates" : 0, "numYield" : 0, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(188796), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(5), "w" : NumberLong(6) } }, "nreturned" : 0, "responseLength" : 20, "millis" : 188, "ts" : ISODate("2014-01-27T17:37:02.482Z"), "client" : "127.0.0.1", "allUsers" : [ ], "user" : "" }
As we see in the preceding document, there are indeed some interesting stats. Let us look at some of them in the following table. Some of these fields are identical to the fields we see when we execute the db.currentOp() operation from the shell: