Tracing MongoDB Queries to Code With Cursor Comments

In this short blog post, we will discuss a helpful feature for tracing MongoDB queries: Cursor Comments.

Cursor Comments

Much like other database systems, MongoDB supports the ability for application developers to set comment strings on their database queries using the Cursor Comment feature. This feature is very useful for both DBAs and developers for quickly and efficiently tying a MongoDB query found on the database server to a line of code in the application source.

Once Cursor Comments are set in application code, they can be seen in the following areas on the server:

1. The db.currentOp() shell command. If Auth is enabled, this requires a role that has the inprog privilege.
2. Profiles in the system.profile collection (per-db) if profiling is enabled.
3. The QUERY log component.

Note: The Cursor Comment string shows as the field query.comment in the Database Profiler output, and as the field originatingCommand.comment in the output of the db.currentOp() command.

This is fantastic because this makes comments visible in the areas commonly used to find performance issues!

Often, it is very easy to find a slow query on the database server, but it is difficult to target the exact area of a large application that triggers the slow query. This can all be changed with Cursor Comments!

Python Example

Below is a snippet of Python code implementing a cursor comment on a simple query to the collection test.test. (Most other languages and MongoDB drivers should work similarly if you do not use Python.)

My goal in this example is to get the MongoDB Profiler to log a custom comment, and then we will read it back manually from the server afterward to confirm it worked.

In this example, I include the following pieces of data in my comment:

1. The Python class.
2. The Python method that executed the query.
3. The file Python was executing.
4. The line of the file Python was executing.

Unfortunately, three of the four useful details above are not built-in variables in Python, so the inspect module is required to fetch those details. Using the inspect module and setting a cursor comment for every query in an application is a bit clunky, so it is best to create a method to do this. I made a class-method named find_with_comment in this example code to do this. This method performs a MongoDB query and sets the cursor comment automagically, finally returning a regular pymongo cursor object.

Below is the simple Python example script. It connects to a Mongod on localhost:27017 and demonstrates everything for us. You can run this script yourself if you have the pymongo Python package installed.

Script:

from inspect import currentframe, getframeinfo
from pymongo import MongoClient
class TestClass:
    def find_with_comment(self, conn, query, db, coll):
        frame      = getframeinfo(currentframe().f_back)
        comment    = "%s:%s;%s:%i" % (self.__class__.__name__, frame.function, frame.filename, frame.lineno)
        collection = conn[db][coll]
        return collection.find(query).comment(comment)
    def run(self):
        uri   = "localhost:27017"
        conn  = MongoClient(uri)
        query = {'user.name': 'John Doe'}
        for doc in self.find_with_comment(conn, query, 'test', 'test'):
            print doc
        conn.close()
if __name__  == "__main__":
    t = TestClass()
    t.run()

There are a few things to explain in this code:

1. Line #6-10: The find_with_comment method runs a pymongo query and handles adding our special cursor comment string. This method takes in the connection, query, and db+collection name as variables.
2. Line #7 is using the inspect module to read the last Python “frame” so we can fetch the file and line number that called the query.
3. Line #12-18: The run method makes a database connection, runs the find_with_comment method with a query, prints the results, and closes the connection. This method is just boilerplate to run the example.
4. Line #20-21: This code initiates the TestClass and calls the run method to run our test.

Trying It Out

Before running this script, enable database profiling mode “2” on the “test” database. This is the database the script will query. The profiling mode “2” causes MongoDB to profile all queries:

$ mongo --port=27017
> use test
switched to db test
> db.setProfilingLevel(2)
{ "was" : 1, "slowms" : 100, "ratelimit" : 1, "ok" : 1 }
> quit()

Now let’s run the script. There should be no output from the script; it is only going to do a find query to generate a Profile.

I saved the script as cursor-comment.py and ran it like this from my Linux terminal:

$ python cursor-comment.py 
$

Now, let’s see if we can find any Profiles containing the query.comment field:

$ mongo --port=27017
> use test
> db.system.profile.find({ "query.comment": {$exists: true} }, { query: 1 }).pretty()
{
"query" : {
"find" : "test",
"filter" : {
"user.name" : "John Doe"
},
"comment" : "TestClass:run;cursor-comment.py:16"
}
}

Now we know the exact class, method, file, and line number that ran this profiled query! Great!

From this profile, we can conclude that the class-method TestClass:run initiated this MongoDB query from Line #16 of cursor-comment.py. Imagine this was a query that slowed down your production system and you need to know the source quickly. The usefulness of this feature/workflow becomes obvious, fast.

More on Python inspect 

Instead of constructing a custom comment like the example above, you can also use Python inspect to collect the Python source code comment that precedes the code that is running. This might be useful for projects that have code comments that would be more useful than class/method/file/line number. As the comment is a string, the sky is the limit on what you can set!

Read about the .getcomments() method of inspect here.

Aggregation Comments

MongoDB 3.5/3.6 added support for comments in aggregations. This is a great new feature, as aggregations are often heavy operations that would be useful to tie to a line of code as well!

This can be used by adding a comment field to your aggregate server command, like so:

db.runCommand({
  aggregate: "myCollection",
  pipeline: [
    { $match: { _id: "foo" } }
  ],
  comment: "fooMatch"
})

See more about this new feature in the following MongoDB tickets: SERVER-28128 and DOCS-10020.

Conclusion

Hopefully, this blog gives you some ideas on how this feature can be useful in your application. Start adding comments to your application today!

If you enjoyed this article and want to learn more about MongoDB, check out this collection of tutorials and articles on all things MongoDB.