Database Profiler

Mongo includes a profiling tool to analyze the performance of database operations.

See also the currentOp command.

Enabling Profiling

Through the profile command

You can enable and disable profiling from the mongo shell, or through a driver, via the profile command.

> db.commandHelp("profile") // see how to run from drivers

When using the profile command, profiling is enabled or disabled per database. A system.profile collection will be created for the database.

To enable profiling, from the mongo shell invoke:

> db.setProfilingLevel(2);
{"was" : 0 , "slowms" : 100, "ok" : 1} // "was" is the old setting
> db.getProfilingLevel()
2

Profiling levels are:

• 0 - off
• 1 - write slow operations (by default, >100ms is considered slow) to the system.profile collection
• 2 - write all operations to the system.profile collection

In addition to the default levels you can also specify a slowms option:

> db.setProfilingLevel(1,20) // log slow operations, slow threshold=20ms
> db.getProfilingStatus() // new shell helper method as of v1.7+
{ "was" : 1, "slowms" : 20 }

Note: the profiling level controls which operations get written to the system.profile collection. However, even if the profiler is off, queries slower than the "slowms" level will get written to the logs.

Through the command-line/config-file

You can also enable profiling on the command line; for example:

$ mongod --profile=1 --slowms=15

Using with Sharding

Enabling and aggregating profile data globally is not yet available. For now, connect directly to a mongod of interest with the shell, and follow the instructions on this page. You can then repeat the same procedure on other shards if necessary.

Viewing the Data

Profiling data is recorded in the database's system.profile collection. Query that collection to see the results.

Because profile data is written to system.profile, you will see write activity on the database, even if only reading, because of the writes to system.profile.

> db.system.profile.find()
{"ts" : "Thu Jan 29 2009 15:19:32 GMT-0500 (EST)" , "info" : "query test.$cmd ntoreturn:1 reslen:66 nscanned:0  <br>query: { profile: 2 }  nreturned:1 bytes:50" , "millis" : 0}
...

Filtering example

As an example, to see output without $cmd (command) operations, invoke:

db.system.profile.find( function() { return this.info.indexOf('$cmd')<0; } )

Likewise we could query for indexOf(...)>=0 to see only those lines.

View stats for only one collection example

To view operations for a particular collection:

> db.system.profile.find( { info: /test.foo/ } )
{"ts" : "Thu Jan 29 2009 15:19:40 GMT-0500 (EST)" , "info" : "insert test.foo" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:19:42 GMT-0500 (EST)" , "info" : "insert test.foo" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:19:45 GMT-0500 (EST)" , "info" : "query test.foo ntoreturn:0 reslen:102 nscanned:2  <br>query: {}  nreturned:2 bytes:86" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:21:17 GMT-0500 (EST)" , "info" : "query test.foo ntoreturn:0 reslen:36 nscanned:2  <br>query: { $not: { x: 2 } }  nreturned:0 bytes:20" , "millis" : 0}
{"ts" : "Thu Jan 29 2009 15:21:27 GMT-0500 (EST)" , "info" : "query test.foo ntoreturn:0 exception  bytes:53" , "millis" : 88}

View slow operations only

To view operations slower than a certain number of milliseconds:

> db.system.profile.find( { millis : { $gt : 5 } } )
{"ts" : "Thu Jan 29 2009 15:21:27 GMT-0500 (EST)" , "info" : "query test.foo ntoreturn:0 exception  bytes:53" , "millis" : 88}

To see newest information first

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

To view information from a certain time range

> db.system.profile.find(
...{ts:{$gt:new ISODate("2011-07-12T03:00:00Z"),
...     $lt:new ISODate("2011-07-12T03:40:00Z")}
...})

In the next example we look at the time range, suppress the user field from the output to make it easier to read, and sort the results by how long each operation took to run.

> db.system.profile.find(
...{ts:{$gt:new ISODate("2011-07-12T03:00:00Z"),
...     $lt:new ISODate("2011-07-12T03:40:00Z")}
...}
...,{user:0}).sort({millis:-1})

The show profile shell helper

The mongo shell includes a helper to see the most recent 5 profiled events that took at least 1ms to execute.  Type

show profile

at the command prompt to use this feature.

Understanding the Output

The output reports the following values:

• ts Timestamp of the profiled operation.
• millis Time, in milliseconds, to perform the operation. This time does not include time to acquire the lock or network time, just the time for the server to process.
• info Details on the operation.
  • query A database query operation. The query info field includes several additional terms:
    • ntoreturn Number of objects the client requested for return from a query. For example, <code>findOne()</code> sets ntoreturn to 1. <code>limit()</code> sets the appropriate limit. Zero indicates no limit.
    • query Details of the query spec.
    • nscanned Number of objects scanned in executing the operation.
    • reslen Query result length in bytes.
    • nreturned Number of objects returned from query.
  • update A database update operation. <code>save()</code> calls generate either an update or insert operation.
    • fastmod Indicates a fast modify operation. See Updates. These operations are normally quite fast.
    • fastmodinsert - indicates a fast modify operation that performed an upsert.
    • upsert Indicates on upsert performed.
    • moved Indicates the update moved the object on disk (not updated in place). This is slower than an in place update, and normally occurs when an object grows.
    • key updates How many index keys changed during the update. Key updates are a little bit expensive since the db needs to remove the old key and insert a new key into the b-tree index.
  • insert A database insert.
  • getmore For large queries, the database initially returns partial information. getmore indicates a call to retrieve further information.

Optimizing Query Performance

• If nscanned is much higher than nreturned, the database is scanning many objects to find the target objects. Consider creating an index to improve this.

• reslen A large number of bytes returned (hundreds of kilobytes or more) causes slow performance. Consider passing <code>find()</code> a second parameter of the member names you require.

Note: There is a cost for each index you create. The index causes disk writes on each insert and some updates to the collection. If a rare query, it may be better to let the query be "slow" and not create an index. When a query is common relative to the number of saves to the collection, you will want to create the index.

Optimizing Update Performance

• Examine the nscanned info field. If it is a very large value, the database is scanning a large number of objects to find the object to update. Consider creating an index if updates are a high-frequency operation.
• Use fast modify operations when possible (and usually with these, an index). See Updates.

Profiler Overhead

When enabled, profiling affects performance, although not severely.

Profile data is stored in the database's system.profile collection, which is a Capped Collection. By default it is set to a very small size and thus only includes recent operations.

Profiling and Replication

In v1.9+, you can use profiling on secondaries in addition to the current primary. In older versions of MongoDB, use profiling on the primary only.

Changing the system.profile Collection Size

Profiling information is written to the system.profile capped collection.  There is a separate profile collection per database.  By default the collection is very small and like all capped collections works in a rotating RRD-like style.  To make it bigger you can create it explicitly.  You will need to drop it first; you may need to disable profiling before the drop/recreate.  Example in the shell:

> db.system.profile.drop()
> db.createCollection("system.profile", {capped:true, size:4000000})
> db.system.profile.stats()

Alternatives to Profiling

The profiler can generate write locks as it writes to the profile collection. Thus other tools to consider for optimizing queries are:

1. Running db.currentOp(), perhaps many times in a row to get a good sample;
2. Using the explain() helper in the shell

See Also

• Optimization
• explain()
• Viewing and Terminating Current Operation