In this recipe, we will perform some operations on a standalone mongo instance and profile 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 how to start a standalone server, refer to Installing single node MongoDB in Chapter 1, Installing and Starting the Server. We also need to start a shell that would be used to perform querying, enabling profiling, and viewing the profiling operation.

Profiling is something that would not be enabled by default. If you are happy about the performance of the database, there is no reason one would enable the profiler. It is only when one feels 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 depends from application to application. 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:

While profiling all operations might not be a very good idea and might not be commonly used as we shall soon see, setting the value to 1 and a threshold provided to it is a good way to monitor slow operations.

If we look at the steps that we executed, we see that we can get the current profiling level by executing the operation db.getProfilingLevel(). To get more information, for example, what value is set as a threshold for the slow operations, we can use db.getProfilingStatus(). This 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).

Next we executed 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 was to see these profiled operations that are logged in the system.profile collection. We execute a find 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 it is negligible. Hence, we would not enable it by default but only when we want to profile slow operations. Also, another question would be, 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 that preserve insertion orders and act as a circular queue filling in the new documents, discarding the oldest when it gets full. A query on system.namespaces should show the stats. The query execution would show the following for the system.profile collection:

{"name":"test.system.profile", "options":{"capped":true, "size":1048576 }}

As we can see, the size of the collection is 1 MB, which is incredibly small. Setting the profiling level to 2 thus would 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 and of any size they prefer should they choose to retain more operations in it. To create a capped collection explicitly, you can execute the following:

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 of profiling data you want to keep before it gets overwritten.

As this is a capped collection and insertion order is preserved, a query with the sort order {$natural:-1} would be perfectly fine and very efficient to find the operations in the reverse order of the execution time.

We would finally take a look at the document that got inserted in the system.profile collection and see what all operations it has logged:

{
        "op" : "query",
        "ns" : "test.profilingTest",
        "query" : {
                "$where" : "sleep(70)"
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 1,
        "keyUpdates" : 0,
        "numYield" : 0,
        "lockStats" : {
                …<<<<snip>>>
       },
        "nreturned" : 0,
        "responseLength" : 20,
        "millis" : 188,
        "ts" : ISODate("2014-01-27T17:37:02.482Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}

As we can see in the document, there are indeed some interesting stats. Let's 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 and we then discussed in the previous recipe.