Database Profiler

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

Enabling Profiling

To enable profiling, from the mongo shell invoke:

> db.setProfilingLevel(2);
{"was" : 0 , "ok" : 1}
> db.getProfilingLevel()
2

Profiling levels are:

0 - off
1 - log slow operations (>100ms)
2 - log all operations

Staring in 1.3.0, you can also enable on the command line, --profile=1

Viewing

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

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

To see output without $cmd (command) operations, invoke:

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

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}

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})

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

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.

Configuring "Slow"

Since 1.3.0 there are 2 ways to configure "slow"

--slowms on the command line when starting mongod (or file config)
db.setProfilingLevel( level , slowms )
```
db.setProfilingLevel( 1 , 10 );
```
will log all queries over 10ms to system.profile