Profiling for Slow Query Log in MongoDB

MongoDB slow query log profiling is easy using db.setProfilingLevel(). Enable slow query log mongoDB Profiling for logging for slow query with your threshlold time.

1. Overview of mongoDB Slow query log profiling

What is meaning of profiling here? In MongoDB you can provide your threshlold value to log sloq query in MongoDB. In mongoDB, you can log slow query log as per your convenient for monitoring of your MongoDB either for collections scan or index scan. Most of the time, you have built an index and your query taking more time as per your expectation, so set profiling level and log slow query in MongoDB. Sometimes, even though you have built an index on a particular field but still taking more than the expected time, you can log those queries by setting profiler using db.setProfilingLevel() command.

2. Syntax of Profiling MongoDB

In this section. you learn, how to use Profiling for slow query log in MongoDB and learn its parameters value, using db.setProfilingLevel() method. You can modify the current database profiler level as per your requirement and your buisness need. The mongod writes the output of the database profiler to the system.profile collection.

Syntax:

db.setProfilingLevel(level, slowms)

There are 3 logging levels for profiling for sloq query log in MonogDB:

1. Level 0 : the profiler is off, does not collect any data. This is the default profiler level. type of level is in int
2. Level 1 : Log profiling data for slow operations only. By default slow operations are those slower than 100 milliseconds. Type of level is in int.
3. Level 2 : Log profiling data for all database operations. Type of level is in int

First of all you have to set your bentchmark, your threshold value for slow query. Slow query does not mean slow for all the time, it means , how much ms (millisecond) is slow for you, let us say if any query is taking more than 100ms , then this is slow for me , I want to log those by setting profiler by using following command.

> db.getProfilingStatus();
{ "was" : 0, "slowms" : 100 }
> db.setProfilingLevel(1, 50)
{ "was" : 0, "slowms" : 100, "ok" : 1 }
> db.getProfilingStatus();
{ "was" : 1, "slowms" : 50 }

so, in the above mongoDB profiling example , log all slow query which take more than 50ms.

3. How to get Slow Query log MongoDB

There are two different options, you can pull slow query log in MongoDB.
1. from system.profile collection.

> db.system.profile.find()

Output:

> db.system.profile.find( { millis : { $gt:2} } ).sort( { ts : -1 } )
>
>
> db.system.profile.find( { millis : { $gt:2 } } ).sort( { ts : -1 } )
> db.setProfilingLevel(1, 2)
{ "was" : 1, "slowms" : 50, "ok" : 1 }
> db.getProfilingStatus();
{ "was" : 1, "slowms" : 2 }
>
>
> db.system.profile.find( { millis : { $gt:2 } } ).sort( { ts : -1 } )
> db.user.find();
{ "_id" : ObjectId("591713250aae4f83face612f"), "i" : 0, "username" : "user0", "age" : 88, "created" : ISODate("2017-05-13T14:07:33.192Z") }
{ "_id" : ObjectId("591713250aae4f83face6130"), "i" : 1, "username" : "user1", "age" : 90, "created" : ISODate("2017-05-13T14:07:33.656Z") }
{ "_id" : ObjectId("591713250aae4f83face6131"), "i" : 2, "username" : "user2", "age" : 1, "created" : ISODate("2017-05-13T14:07:33.661Z") }
{ "_id" : ObjectId("591713250aae4f83face6132"), "i" : 3, "username" : "user3", "age" : 14, "created" : ISODate("2017-05-13T14:07:33.684Z") }
{ "_id" : ObjectId("591713250aae4f83face6133"), "i" : 4, "username" : "user4", "age" : 95, "created" : ISODate("2017-05-13T14:07:33.685Z") }
{ "_id" : ObjectId("591713250aae4f83face6134"), "i" : 5, "username" : "user5", "age" : 35, "created" : ISODate("2017-05-13T14:07:33.686Z") }
{ "_id" : ObjectId("591713250aae4f83face6135"), "i" : 6, "username" : "user6", "age" : 107, "created" : ISODate("2017-05-13T14:07:33.687Z") }
{ "_id" : ObjectId("591713250aae4f83face6136"), "i" : 7, "username" : "user7", "age" : 100, "created" : ISODate("2017-05-13T14:07:33.688Z") }
{ "_id" : ObjectId("591713250aae4f83face6137"), "i" : 8, "username" : "user8", "age" : 10, "created" : ISODate("2017-05-13T14:07:33.689Z") }
{ "_id" : ObjectId("591713250aae4f83face6138"), "i" : 9, "username" : "user9", "age" : 90, "created" : ISODate("2017-05-13T14:07:33.692Z") }
{ "_id" : ObjectId("591713250aae4f83face6139"), "i" : 10, "username" : "user10", "age" : 36, "created" : ISODate("2017-05-13T14:07:33.693Z") }
{ "_id" : ObjectId("591713250aae4f83face613a"), "i" : 11, "username" : "user11", "age" : 91, "created" : ISODate("2017-05-13T14:07:33.694Z") }
{ "_id" : ObjectId("591713250aae4f83face613b"), "i" : 12, "username" : "user12", "age" : 66, "created" : ISODate("2017-05-13T14:07:33.695Z") }
{ "_id" : ObjectId("591713250aae4f83face613c"), "i" : 13, "username" : "user13", "age" : 31, "created" : ISODate("2017-05-13T14:07:33.696Z") }
{ "_id" : ObjectId("591713250aae4f83face613d"), "i" : 14, "username" : "user14", "age" : 15, "created" : ISODate("2017-05-13T14:07:33.697Z") }
{ "_id" : ObjectId("591713250aae4f83face613e"), "i" : 15, "username" : "user15", "age" : 101, "created" : ISODate("2017-05-13T14:07:33.698Z") }
{ "_id" : ObjectId("591713250aae4f83face613f"), "i" : 16, "username" : "user16", "age" : 89, "created" : ISODate("2017-05-13T14:07:33.699Z") }
{ "_id" : ObjectId("591713250aae4f83face6140"), "i" : 17, "username" : "user17", "age" : 68, "created" : ISODate("2017-05-13T14:07:33.701Z") }
{ "_id" : ObjectId("591713250aae4f83face6141"), "i" : 18, "username" : "user18", "age" : 36, "created" : ISODate("2017-05-13T14:07:33.702Z") }
{ "_id" : ObjectId("591713250aae4f83face6142"), "i" : 19, "username" : "user19", "age" : 115, "created" : ISODate("2017-05-13T14:07:33.702Z") }
Type "it" for more
> it
>
> db.system.profile.find( { millis : { $gt:2 } } ).sort( { ts : -1 } )
{ "op" : "query", "ns" : "training.user", "query" : {  }, "cursorid" : 25995520147, "ntoreturn" : 0, "ntoskip" : 0, "nscanned" : 0, "nscannedObjects" : 101, "keyUpdates" : 0, "writeConflicts" : 0, "numYield" : 1, "locks" : { "Global" : { "acquireCount" : { "r" : NumberLong(4) } }, "MMAPV1Journal" : { "acquireCount" : { "r" : NumberLong(2) } }, "Database" : { "acquireCount" : { "r" : NumberLong(2) } }, "Collection" : { "acquireCount" : { "R" : NumberLong(2) } } }, "nreturned" : 101, "responseLength" : 8495, "millis" : 23, "execStats" : { "stage" : "COLLSCAN", "filter" : { "$and" : [ ] }, "nReturned" : 101, "executionTimeMillisEstimate" : 30, "works" : 102, "advanced" : 101, "needTime" : 1, "needFetch" : 0, "saveState" : 1, "restoreState" : 1, "isEOF" : 0, "invalidates" : 0, "direction" : "forward", "docsExamined" : 101 }, "ts" : ISODate("2017-05-21T05:50:32.466Z"), "client" : "127.0.0.1", "allUsers" : [ ], "user" : "" }
>

for formated output, display last 1 ( limit(1) ) ts (timestamp) in descending order. you can use pretty() method on cursor, as follows.

> db.system.profile.find( { millis : { $gt:2 } } ).sort( { ts : -1 } ).limit(1).pretty();
{
        "op" : "query",
        "ns" : "training.system.profile",
        "query" : {
                "query" : {
                        "millis" : {
                                "$gt" : 2
                        }
                },
                "orderby" : {
                        "ts" : -1
                }
        },
        "ntoreturn" : 0,
        "ntoskip" : 0,
        "nscanned" : 0,
        "nscannedObjects" : 2,
        "scanAndOrder" : true,
        "keyUpdates" : 0,
        "writeConflicts" : 0,
        "numYield" : 0,
        "locks" : {
                "Global" : {
                        "acquireCount" : {
                                "r" : NumberLong(2)
                        }
                },
                "MMAPV1Journal" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Database" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Collection" : {
                        "acquireCount" : {
                                "R" : NumberLong(1)
                        }
                }
        },
        "nreturned" : 2,
        "responseLength" : 1864,
        "millis" : 13,
        "execStats" : {
                "stage" : "SORT",
                "nReturned" : 2,
                "executionTimeMillisEstimate" : 10,
                "works" : 8,
                "advanced" : 2,
                "needTime" : 4,
                "needFetch" : 0,
                "saveState" : 0,
                "restoreState" : 0,
                "isEOF" : 1,
                "invalidates" : 0,
                "sortPattern" : {
                        "ts" : -1
                },
                "memUsage" : 1860,
                "memLimit" : 33554432,
                "inputStage" : {
                        "stage" : "COLLSCAN",
                        "filter" : {
                                "millis" : {
                                        "$gt" : 2
                                }
                        },
                        "nReturned" : 2,
                        "executionTimeMillisEstimate" : 0,
                        "works" : 4,
                        "advanced" : 2,
                        "needTime" : 1,
                        "needFetch" : 0,
                        "saveState" : 0,
                        "restoreState" : 0,
                        "isEOF" : 1,
                        "invalidates" : 0,
                        "direction" : "forward",
                        "docsExamined" : 2
                }
        },
        "ts" : ISODate("2017-05-21T05:52:34.135Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}

2. from mongo log file using Linux tail utility command.

[root@ranjeetJha ~]# tail -f /var/log/mongodb/mongod.log

4. How to get profiling status?

The db.getProfilingStatus() method is used to return a document of current profiling level and the profiling threshold.

syntax:

> db.getProfilingStatus();

Output:

> db.getProfilingStatus();
{ "was" : 0, "slowms" : 100 }

5. Clear Profiler Log Data

To clear profiler log mean , removing system.profile collection. So for doing that first set profiler level to 0 and execute db.system.profile.remove()

 > use mydb;
 > db.system.profile.remove();

Now, the threshold is set to 100ms, which is bydefault.

To clear system.profile collection, profiling needs to be stopped. Just set the level to 0. Then, call db.system.profile.remove(). Now, the collection is empty.

Your suggestions and comments are welcome to encourage and improve this post how to enable slow query log MongoDB.