CPU Utilisation and Slow Queries in MongoDB

If we have a  performance issue on MongoDB database, there are a number of things to look at, such as indexing strategies, database schema design issues, abnormal traffic load, network problems, inadequate available physical memory resources, locking problems, inappropriate access strategies, hardware limitations, and the number of open database connections.Web

An obvious place to start is to check for long-running MongoDB queries, and queries that are executed frequently but aren’t optimized. The slow queries can happen when you do not have proper DB indexes. Indexes support the efficient execution of queries in MongoDB. Without indexes, MongoDB must perform a collection scan, i.e. scan every document in a collection, to select those documents that match the query statement. And it can take a while if you have many documents in your collection.

Your working set is the amount of data and indexes that will be active and in use by your instance. If you have a particularly large system, you need to figure out what parts of your data are most used before you’re able to determine what your working set will be. If this is a particularly new instance, figuring out the growth of your system over a year will help you determine how much RAM to assign for your cache size.

How to detect the queries that lead to load spikes:

db.currentOp()

The db.currentOp() method is used to return a document that contains information on in-progress operations for the database instance.

$ > db.currentOp(true);
{
			"opid" : "shard3:466404288",
			"active" : false,
			"waitingForLock" : false,
			"op" : "query",
			"ns" : "sd.usersEmails",
			"query" : {
				
			},
			"client_s" : "10.121.13.8:34473",
			"desc" : "conn"
		},
  • opid – every operation has a unique ID and if you are using sharding, shows which shard the operation is running on.
  • active – shows whether the operation is actually being run or if it’s queued.
  • waitingForLock – locking operations first request the lock and if it has yet to be granted, this will be true.
  • op – the operation type e.g. query, insert, remove.
  • ns – the namespace that is being operated on. This is usually database.collection, in this case the users Emails collection in the sd database.
  • query – if an actual query is being executed the parameters will be displayed here.
  • client_s – the source of the operation. In this case it is a mongos on server 10.121.13.8
  • desc – conn is a normal client connection whereas other values indicate internal operations
  • secs_running – Indicate how long the query is running.

Queries not using any index

The below example will help you find query operations using no index { “planSummary”: “COLLSCAN” }

> db.adminCommand({"currentOp": true,"op" : "query","planSummary": "COLLSCAN"}) ;

 

Operations with high numYields

The below example will help you find all operations with numYields greater than or 100 on db1 database.

> db.adminCommand({
"currentOp": true,
"ns": /^db1\./,
"numYields" : {"$gte": 100}
})

Operations waiting for a lock

The following example returns information on all the write operations that are waiting for a lock.

> db.adminCommand({
"currentOp": true,
"waitingForLock" : true,
"$or": [
{ "op" : { "$in" : [ "insert", "update", "remove" ] } },
{ "query.findandmodify": { "$exists": true } }
]
})

Long running query

The following example returns information on all the operations running longer than 300 milliseconds.

> db.adminCommand({
"currentOp": true,
"microsecs_running" : {"$gte" : 300000}
})
db.currentOp({“secs_running”: {$gte: 3}})

To ensure you capture all your operations over certain period of time, you may execute the db.currentOp() command in a while loop as shown below.

var i = 0;
while(i++<10) {
printjson(db.currentOp());
// sleep for 10 ms if required.
sleep(10)
}

 Profiler 

The database profiler collects fine grained data about MongoDB queries longer than the specific threshold — threshold in milliseconds at which the database profiler considers a query slow. The database profiler writes all the data it collects to system.profile collection so that we can analyse later. Collection system.profile is a capped collection ( default 1 MB in size).

The profiler is off by default. You can enable the profiler on a per-database or per-instance basis at one of several profiling levels.

Profiling Levels

The following profiling levels are available:

Level Description
0 The profiler is off and does not collect any data. This is the default profiler level.
1 The profiler collects data for operations that take longer than the value of slowms.
2 The profiler collects data for all operations.

You also can set some bigger value as the threshold to minimise the amount of queries for analysis.

By default, the slow operation threshold is 100 milliseconds. Databases with a profiling level of 1 will profile operations slower than the threshold.

To enable profiling for a MongoDB , you can use following function:

db.setProfilingLevel(level, slowms)

level – This refers to verbosity level of profiling

slowms – This is optional. It is used to define the slow operation threshold in milliseconds.

For example, the following command sets the profiling level for the current database to 1 and the slow operation threshold is 1000 milliseconds:

user:PRIMARY> db.setProfilingLevel(1, 1000)
{ “was” : 0, “slowms” : 100, “ok” : 1 }
user:PRIMARY> db.getProfilingStatus()
{ “was” : 1, “slowms” : 1000 }

Database will log operations slower than 1000 milliseconds into system.profile collection.

Now you can query for the data against this collection and analize:

db.system.profile.find().pretty()
// or get 'query' operations only and specified fields
db.system.profile.find( { op: { $eq : 'query' } } , {"millis": 1, "ns": 1, "ts": 1,"query": 1}).sort( { ts : -1 } ).pretty()

Histogram of the slowest collections (collections with the slowest queries) – number of queries per collection

This presents a histogram of slow collections

> db.system.profile.group({key: {ns: true}, initial: {count: 0}, reduce: function(obj,prev){ prev.count++;}})

Histogram of the slowest collections (collections with the slowest queries) – number of millies spent in each collection

> db.system.profile.group({key: {ns: true}, initial: {millis: 0}, reduce: function(obj, prev){ prev.millis += obj.millis;}})

Find the most recent slow query

> db.system.profile.find().sort({$natural: -1}).limit(1)

Find the single slowest query in the capped system.profile collection right now

> db.system.profile.find().sort({millis: -1}).limit(1)

Top 10 Slow queries

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

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

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

If we want to log all operations instead, we just need to set the profiling level to 2:

> db.setProfilingLevel(2)
For setting mongodb profiling level persistently we need to add following parameter in /etc/mongod.conf and restart the mongodb server process.

 

operationProfiling:
  slowOpThresholdMs: 1000
  mode: slowOp
Imp Note : Using the profiler negatively effect the  performance because the profiler records the entire database operations.There can be a noticeable impact on throughput when the profiler is enabled and configured to log operations.
When adding a new query to an app, you should run the query on production data to check its speed. You can also ask Mongo to explain what its doing when running the query, so you can check things like which index its using etc.
db.collection.find(query).explain()
{
    // BasicCursor means no index used, BtreeCursor would mean this is an indexed query
    "cursor" : "BasicCursor",
    
    // The bounds of the index that were used, see how much of the index is being scanned
    "indexBounds" : [ ],
    
    // Number of documents or indexes scanned
    "nscanned" : 57594,
    
    // Number of documents scanned
    "nscannedObjects" : 57594,
    
    // The number of times the read/write lock was yielded
    "nYields" : 2 ,
    
    // Number of documents matched
    "n" : 3 ,
    
    // Duration in milliseconds
    "millis" : 108,
    
    // True if the results can be returned using only the index
    "indexOnly" : false,
    
    // If true, a multikey index was used
    "isMultiKey" : false
}

An efficient index for a query is easily identifiable: the number of document returned by a query is equal to the number of document fetched from a collection and is equal to the number of keys in the index used.

Working Set Is Larger Than Allowed RAM 

Your working set is the amount of data and indexes that will be active and in use by your instance. If you have a particularly large system, you need to figure out what parts of your data are most used before you’re able to determine what your working set will be. If this is a particularly new instance, figuring out the growth of your system over a year will help you determine how much RAM to assign for your cache size.

mongostat –port 27001 -o “time=time, dirty=dirty,used=used,insert=I,qrw=qrw,arw=arw”

Focus on the columns “dirty” and “used”. These two columns should be relatively the same in an optimal environment. If the “used” column is a significantly higher percentage than your “dirty” column, then you have not allowed enough RAM for your instance.

TroubleshootingSlowQueriesinMongoDB-1

This can be fixed by setting your cache size higher. In your config file set the cacheSizeGB to the required amount for your working set.

Storage:
wiredTiger:
engineConfig:
cacheSizeGB:

Reference : https://docs.mongodb.com/manual/tutorial/manage-the-database-profiler/

https://docs.mongodb.com/manual/tutorial/manage-the-database-profiler/#profiler-overhead

 

 

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

Powered by WordPress.com.

Up ↑

%d bloggers like this: