Overview of the MongoDB Database Profiler

Any type of database faces performance issues when data grows. Simple steps like rewriting problematic queries or analyzing/optimizing the database schema can drastically improve the performance of the database. MongoDB provides some excellent features which make this process very easy for DBAs. For instance, Query Profiler, Mongostat, Mongotop, good logging support, etc.

Most of the time, it is the database system which decides how a query will execute. The user just provides the details about the result that he/she wants via a query language. In this article, we will discuss how we can use MongoDB query profiler to find slow and resource-intensive queries. MongoDB Profiler is a built-in tool which gives you the actual query level insights. It allows you to analyze all the queries which are being run by the database system.

Enabling/Configuring the MongoDB Profiler

Generally, the profiler stores all the data in system.profile collection which can be queried like any other normal MongoDB collection. Profiler has 3 profiling levels. By default profiler level is set to 0 for any database.

You can run the following commands to get some information about profiler.

• To get current profiling level.

  db.getProfilingLevel()

  Output:

  0

• To check current profiling status

  db.getProfilingStatus()

  Output:

  { "was" : 0, "slowms" : 100 }

• To set profiling level

  db.setProfilingLevel(1, 40)

  Output:

  { "was" : 0, "slowms" : 100, "ok" : 1 }

  MongoDB will print old profiling level and returns OK that means profiling level is set to 1 now.

  Slowms is a threshold value for profiler which means the profiler will log all the queries which take more time than the threshold value to execute.

Understanding the Profiler Output

Run this command to get 1 document from the system.profile collection.

db.system.profile.find().limit(1).pretty()

Output:

{
    "op" : "query",
    "ns" : "mydb.Log",
    "query" : {
        "find" : "Log",
        "filter" : {
            "EMP_ID" : "01778"
        }
    },
    "keysExamined" : 0,
    "docsExamined" : 90022,
    "cursorExhausted" : true,
    "keyUpdates" : 0,
    "writeConflicts" : 0,
    "numYield" : 703,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(1408)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(704)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "r" : NumberLong(704)
            }
        }
    },
    "nreturned" : 60,
    "responseLength" : 17676,
    "protocol" : "op_command",
    "millis" : 40,
    "execStats" : {
        "stage" : "COLLSCAN",
        "filter" : {
            "EMP_ID" : {
                "$eq" : "01778"
            }
        },
        "nReturned" : 60,
        "executionTimeMillisEstimate" : 30,
        "works" : 90024,
        "advanced" : 60,
        "needTime" : 89963,
        "needYield" : 0,
        "saveState" : 703,
        "restoreState" : 703,
        "isEOF" : 1,
        "invalidates" : 0,
        "direction" : "forward",
        "docsExamined" : 90022
    },
    "ts" : ISODate("2018-09-09T07:24:56.487Z"),
    "client" : "127.0.0.1",
    "allUsers" : [ ],
    "user" : ""
}

This is one document from system.profile collection. We can see that it contains lots of useful information for us. Let’s understand some of the useful fields from this document.

• Op field stores the type of operation.
• Ns field stores target database and collection name
• Query field stores the information about the query and result. The result will be truncated if the document size is greater than 50KB
• keysExamined stores the number of index keys examined by DB to execute the query
• docsExamined stores the total number of documents examined by the DB
• Nreturned stores the number of documents returned by the query
• Millis contains the actual time in milliseconds taken by this query to execute
• Ts stores the timestamp of the query

We can get lots of information about how the query operation was carried out by the database system by examining these fields and use it to optimize the performance of database. For example, if the keysExamined value is greater than “nreturns” value then it shows that DB is scanning many indexes to get the result which is never a good sign. So you should adjust your database indexes properly.

Useful Queries to Analyze Profiler Output

1. Most useful query is to sort all the documents by millis to get the top 10 slow queries.

   db.system.profile.find().sort({millis:-1}).limit(10).pretty();

2. Find all queries which are taking more than 30 milliseconds to execute

   db.system.profile.find({millis:{$gt:30}}).pretty()

3. Find top 10 slowest aggregation/command queries

   db.system.profile.find({op: {$eq: “command” }}).sort({millis:-1}).limit(10).pretty();

4. Find all the operations for which some documents were moved

   db.system.profile.find({moved:true}).pretty()

5. Find queries which are performing large scans on the database

   db.system.profile.find({docsExamined:{$gt:10000}}).pretty()

6. Find maximum and average time taken by each type of operations using aggregation

   db.system.profile.aggregate(
   { $group : { 
      _id :"$op", 
      count:{$sum:1},
      "max_time":{$max:"$millis"},
      "avg_time":{$avg:"$millis"}
   }}).pretty()

7. Find maximum and average time taken by queries in each database using aggregation

   db.system.profile.aggregate(
   { $group : {
     _id :"$ns",
     count:{$sum:1}, 
     "max_time":{$max:"$millis"}, 
     "avg_time":{$avg:"$millis"}  
   }}.pretty()

Conclusion

MongoDB Profiler is very useful tool to get insights of how database carry out any queries/commands. If you plan to use profiler in a production environment, then you should do proper testing because it can impact on your database throughput especially when you are logging all the queries i.e profiling level is set to 2. Another aspect of using this tool is defining what slow means. You have to decide that what all queries can be considered as slow. Based on that, you can set the minimum threshold to log the queries. This will reduce the impact of using this tool on DB performance