MongoDB Profiler Cheat Sheet

gistfile1.js

// a list of useful queries for profiler analysis.  Starting with the most basic.
// 2.4 compatible
//

// output explained:
//
{
 "ts" : ISODate("2012-09-14T16:34:00.010Z"),  			// date it occurred
	"op" : "query",						// the operation type
	"ns" : "game.players",					// the db and collection
	"query" : { "total_games" : 1000 },			// query document
	"ntoreturn" : 0,					// # docs returned with limit()
	"ntoskip" : 0,						// # of docs to skip()			
	"nscanned" : 959967,					// number of docs scanned
	"keyUpdates" : 0,					// updates of secondary indexes
	"numYield" : 1,						// # of times yields took place
	"lockStats" : { ... },					// subdoc of lock stats
	"nreturned" : 0,					// # docs actually returned
	"responseLength" : 20,					// size of doc
	"millis" : 859,						// how long it took
	"client" : "127.0.0.1",					// client asked for it
	"user" : ""						// the user asking for it
}


// last few entries
show profile                                                     

// sort by natural order (time in)
db.system.profile.find({}).sort({$natural:-1})

// sort by slow queries first
db.system.profile.find({}).sort({$millis:-1})Alimit(10);

// anything > 20ms                  
db.system.profile.find({"millis":{$gt:20}})

// single coll order by response time                      
db.system.profile.find({"ns":"test.foo"}).sort({"millis":-1})

// regular expression on namespace
db.system.profile.find( { "ns": /test.foo/ } ).sort({millis:-1,$ts:-1})

// anything thats moved    
db.system.profile.find({"moved":true})

// large scans                           
db.system.profile.find({"nscanned":{$gt:10000}})

// anything doing range or full scans                 
db.system.profile.find({"nreturned":{$gt:1}})

//
// using the agg framework
//  

// response time by operation type
db.system.profile.aggregate(
{ $group : { 
   _id :"$op", 
   count:{$sum:1},
   "max response time":{$max:"$millis"},
   "avg response time":{$avg:"$millis"}
}});

// slowest by namespace
db.system.profile.aggregate(
{ $group : {
  _id :"$ns",
  count:{$sum:1}, 
  "max response time":{$max:"$millis"}, 
  "avg response time":{$avg:"$millis"}  
}},
{$sort: {
 "max response time":-1}
});


// slowest by client
db.system.profile.aggregate(
{$group : { 
  _id :"$client", 
  count:{$sum:1}, 
  "max response time":{$max:"$millis"}, 
  "avg response time":{$avg:"$millis"}  
}},
{$sort: { 
  "max response time":-1} 
});

// summary moved vs non-moved
db.system.profile.aggregate(
 { $group : {
   _id :"$moved",
   count:{$sum:1}, 
   "max response time":{$max:"$millis"}, 
   "avg response time":{$avg:"$millis"} 
 }});

db.system.profile.aggregate([	
	{ $project : {
			"op" : "$op",
			"millis" : "$millis",
			"timeAcquiringMicrosrMS" : { $divide : [ "$lockStats.timeAcquiringMicros.r", 1000 ] },
			"timeAcquiringMicroswMS" : { $divide : [ "$lockStats.timeAcquiringMicros.w", 1000 ] },
			"timeLockedMicrosrMS" : { $divide : [ "$lockStats.timeLockedMicros.r", 1000 ] },
			"timeLockedMicroswMS" : { $divide : [ "$lockStats.timeLockedMicros.w", 1000 ] } }	
	},
	{ $project : {	
			"op" : "$op",
			"millis" : "$millis",
			"total_time" : { $add : [ "$millis", "$timeAcquiringMicrosrMS", "$timeAcquiringMicroswMS" ] },
			"timeAcquiringMicrosrMS" : "$timeAcquiringMicrosrMS",
			"timeAcquiringMicroswMS" : "$timeAcquiringMicroswMS",
			"timeLockedMicrosrMS" : "$timeLockedMicrosrMS",
			"timeLockedMicroswMS" : "$timeLockedMicroswMS" }
	},
	{ $group : { 	
			_id : "$op",
			"average response time" : { $avg : "$millis" },
			"average response time + acquire time": { $avg: "$total_time"},
			"average acquire time reads" : { $avg : "$timeAcquiringMicrosrMS" },
			"average acquire time writes" : { $avg : "$timeAcquiringMicroswMS" },
			"average lock time reads" : { $avg : "$timeLockedMicrosrMS" },
			"average lock time writes" : { $avg : "$timeLockedMicroswMS" } }
	}
]);