Profiling for Slow Query Log in MongoDB

Connect with

MongoDBIn 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 index and your query taking more time as per your expecation , so set profiling level and log slow query. Sometimes, even though you have built index on perticular field but still taking more than the expected time, you can log those query by setting profiler.

1. Syntax of Profiling

db.setProfilingLevel() method is used to modify the current database profiler level used by the database profiling system to log slow query log. The mongod writes the output of the database profiler to the system.profile collection.

Syntax:


db.setProfilingLevel(level, slowms)

There are 3 logging levels:

  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

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 so set 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, log all slow query which take more than 50ms.

2. How to get Slow Query log

There are two different options, you can pull from
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

3. 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 }

4. 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.

Note: You can set you profiler on per database, for that you have to first select you database. And then execute profiler commands.

Your suggestions and comments are welcome to encourage and improve this post.


Connect with

3 thoughts on “Profiling for Slow Query Log in MongoDB

  1. Pingback: Anonymous

Leave a Reply

Your email address will not be published. Required fields are marked *