One of my favorite features in MongoDB 2.0 is the finer-grained output of the database profiler. In earlier versions, the bulk of the profile information was contained within a (structured, parseable) string, but as of 2.0 the fields have been broken out and made queryable.

Back in time

In production versions of MongoDB up to and including 1.8, database profiler output looked like this:

{"ts" : "Thu Jan 29 2009 15:19:45 GMT-0500 (EST)" ,
 "info" : "query test.foo ntoreturn:0 reslen:102 nscanned:2 query: {} nreturned:2 bytes:86" ,
 "millis" : 0}

That info string has a lot of useful information in it, but how can I get at it? It's log parsing all over again. The profiler documentation even suggests querying this collection with un-anchored regular expressions and server-side javascript, which can be painfully slow if you want to do anything automated with the profile information. Want to filter by date? Yeah, good luck.

Today

In 2.0, the profiler output looks like this (for the same fictional query as above):

{"ts": ISODate("2009-01-29T15:19:45Z"),
 "op": "query",
 "ns": "test.foo",
 "query": {
     "$query": {}
 },
 "responseLength": 102,
 "nscanned": 2,
 "nreturned": 2,
 "millis": 0
}

Much nicer. Now we have lots of data to get our hands on; we can filter by ns to find only queries against certain collections, sort by ts which is a proper, orderable date object; we can consider only queries slower or faster than a certain time, and we can even reach into the query itself and only look at operations touching a certain field, or containing a certain target value. Cool!

The profiler also contains entries on updates, inserts, removes, commands (like Map-Reduce, group, count, etc).

Get Started with the Profiler

If you haven't yet, read the documentation on the profiler. Even though it still references the old formats, it has a lot of useful information and warnings about using the profiler (hint: it has small, but non-zero, overhead on performance -- use with caution!).

Next fire up the profiler on your database:

test> db.runCommand({profile: 1, slowms: 5})

This tells MongoDB to log all operations that took 5 or more milliseconds to the system.profile collection. It's a capped collection which is initially set to 1MB. This is enough to capture around 4,000 small operations (for some reasonable value of "small").

To make the profile collection larger, just drop it and explicitly create it:

test> db.runCommand({profile: 0})
test> db.system.profile.drop()
true
test> db.createCollection("system.profile", {capped: true, size: 100 * 1024 * 1024})

{ "ok" : 1 } test> db.runCommand({profile: 1, slowms: 5})

And you're back up with a 100MB profile (which holds a lot of operations).

Wishlist

The profiler in MongoDB 2.0 has come a long way, but I'd like to see a few features added:

• logging of nScannedObjects, as in the explain() output, which will help diagnose queries that are hitting the collection too hard
• logging of the explain plan, or at least index, used to serve a query
• filtering options for entries going into the profile, like a whitelist/blacklist approach by collection name, op type, etc.

Coming Soon

I've written a web-based profile analyzer, named "Professor", that I'm presenting at tonight's MongoDB User Group. A post about it should be up in the next few days.