Monthly Archives: November 2011

A Walk Through the Valley of Indexing in MongoDB

As you walk through the valley of MongoDB performance, you will undoubtedly find yourself wanting to optimize your indexes at some point or other.

How to Watch Your Queries

Run your database with profiling on. I have an alias for starting up mongo in profile mode (‘p’ stands for profile):

alias mongop="<mongodb-install>/bin/mongod
      --smallfiles --noprealloc --profile=1 --dbpath <mongodb-install>/data/db"

This will default to considering queries > 100ms being deemed “slow.”

Add a logger (if you are using MongoMapper) and tail the log file to see the queries.

##### MONGODB SETTINGS #####
# You can use :logger => Rails.logger, to get output of the mongo queries, or create a separate logger.
logger = Logger.new('mongo-development.log')
MongoMapper.connection = Mongo::Connection.new('localhost', 27017, {:pool_size => 5, :auto_reconnect => true, :logger => logger})
MongoMapper.database = "mdalert-development"

Run your query/exercise the app.

Examine the mongo log (trimmed for legibility), and look for the primary collection you were querying (bolded below).

['$cmd'].find(#"settings", "query"=>{:identifier=>"ItemsPerPage"}, "fields"=>nil}>).limit(-1)
['$cmd'].find(#"accounts", "query"=>{:state=>"active"}, "fields"=>nil}>).limit(-1)
['accounts'].find({:state=>"active"}).limit(15).sort(email1)
['settings'].find({:identifier=>"AutoEmail"}).limit(-1)

Use MongoDB’s Explain to dig deeper.

Open up the mongo shell (<mongodb-install>/bin/mongo) and enter the query that you want explained. Hint, you can take much of it from the query in the log.

Without any indexes, you can see the query is scanning the entire table basically. A bad thing! Another tip is the cursor type is “BasicCursor.”

> db.accounts.find({state: "active"}).limit(15).sort({email: 1}).explain();
{
  "cursor" : "BasicCursor",
  "nscanned" : 11002,
  "nscannedObjects" : 11002,
  "n" : 15,
  "scanAndOrder" : true,
  "millis" : 44,
  "nYields" : 0,
  "nChunkSkips" : 0,
  "isMultiKey" : false,
  "indexOnly" : false,
  "indexBounds" : {
  }
}

Since I was doing a find on state, and a sort on email (or last_name), I added a compound index using MongoMapper (you could have just as easily done it at the mongo console).

Account.ensure_index([[:state,1],[:email,1]])
Account.ensure_index([[:state,1],[:last_name,1]])

Re-running the explain, you can see

  • the cursor type is now BtreeCursor (i.e., using an index)
  • the entire table is not scanned.
  • The retrieval went from 44 millis down to 2 millis
  • Success!!
> db.accounts.find({state: "active"}).limit(15).sort({email: 1}).explain();
{
  "cursor" : "BtreeCursor state_1_email_1",
  "nscanned" : 15,
  "nscannedObjects" : 15,
  "n" : 15,
  "millis" : 2,
  "nYields" : 0,
  "nChunkSkips" : 0,
  "isMultiKey" : false,
  "indexOnly" : false,
  "indexBounds" : {
    "state" : [ [ "active", "active" ] ],
    "email" : [ [ {"$minElement" : 1}, {"$maxElement" : 1} ] ]
  }
}

Fiddling a Bit More – Using the Profiler

You can drop into the mongo console and see more specifics using the mongo profiler.

> db.setProfilingLevel(1,15)
{ "was" : 1, "slowms" : 100, "ok" : 1 }

For this example, I cleared the indexes on accounts. and I ran the following query, and examined its profile data.
Note: the timing can vary over successive runs, but it generally is fairly consistent — and it is close to the “millis” value you see in explain output.

> db.accounts.find({state: "active"}).limit(15).sort({email: 1})
> db.system.profile.find();
{ "ts" : ISODate("2011-11-27T21:09:04.237Z"),
  "info" : "query mdalert-development.accounts
  ntoreturn:15 scanAndOrder
  reslen:8690
  nscanned:11002
  query: { query: { state: "active" },
    orderby: { email: 1.0 } }
    nreturned:15 163ms", "millis" : 43 }

Now let’s add back the indexes… one at a time. First up, let’s add “state.”

> db.accounts.ensureIndex({state:1})
>db.accounts.find({state: "active"}).limit(15).sort({email: 1})
db.system.profile.find({info: /.accounts/})
{ "ts" : ISODate("2011-11-27T21:26:29.801Z"),
  "info" : "query mdalert-development.accounts
  ntoreturn:15 scanAndOrder
  reslen:546
  nscanned:9747
  query: { query: { state: "active" },
    orderby: { email: 1.0 }, $explain: true }
    nreturned:1 81ms", "millis" : 81 }

Hmmm. Not so good! Let’s add in the compound index that we know we need, and run an explain:

>db.accounts.ensureIndex({state:1,email:1})
> db.accounts.find({state: "active"}).limit(15).sort({email: 1}).explain()
{
	"cursor" : "BtreeCursor state_1_email_1",
	"nscanned" : 15,
	"nscannedObjects" : 15,
	"n" : 15,
	"millis" : 0,

And sure enough, we get good performance. The millis is so small, that this query will not show up in the profiler.

If you want to clear the profile stats, you’ll soon find out you can’t remove the documents. The only way I saw how to do it was as follows:

  • restart mongod in non-profiling mode
  • reopen the mongo console and type:
    db.system.profile.drop()

You should now see the profile being empty:

> show profile
db.system.profile is empty

Now you can restart mongod in profiling mode and see your latest profiling data without all the ancient history.

Some Gotchas

Regex searches cannot be indexed

If your query is a regex, then the index can’t help. With regex, retrieval is 501 ms (not bad, given 317K records):

> db.message_logs.find({patient_name:/ben franklin/i}).sort({created_at:-1}).explain()
{
	"cursor" : "BtreeCursor patient_name_1 multi",
	"nscanned" : 317265,
	"nscannedObjects" : 27,
	"n" : 27,
	"millis" : 501,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"isMultiKey" : false,
	"indexOnly" : false,
	"indexBounds" : {
		"patient_name" : [ [ "", { } ], [ /ben franklin/, /ben franklin/ ] ]
	}
}

Without regex, it is essentially instantaneous:

> db.message_logs.find({patient_name:'Ben Franklin'}).sort({created_at:-1}).explain()
{
	"cursor" : "BtreeCursor patient_name_1",
	"nscanned" : 27,
	"nscannedObjects" : 27,
	"n" : 27,
	"scanAndOrder" : true,
	"millis" : 0,
	"nYields" : 0,
	"nChunkSkips" : 0,
	"isMultiKey" : false,
	"indexOnly" : false,
	"indexBounds" : {
		"patient_name" : [ [ "Ben Franklin", "Ben Franklin" ] ]
	}
}

Tips for examining profiler output

  • Look at the most recent offenders:
    show profile
  • Look at a single collection:
    db.system.profile.find({info: /message_logs/})
  • Look at a slow queries:
    db.system.profile.find({millis : {$gt : 500}})
  • Look at a single collection with a specific query param, and a response >100ms:
    db.system.profile.find({info: /message_logs/, info: /patient_name/, millis : {$gt : 100}})

Summary

So here you have an example of how to see indexes in action, how to create them, and how to measure their effects.

References:

 

Configuring MongoMapper Indexes in Rails App

Not quite sure where the best place is to define MongoDB indexes via MongoMapper in a Rails app… My progression has been:

  1. as part of the key definition in the model class
  2. in a rails initializer
  3. hybrid between initializer and model
  4. rake task invoking model methods

Define Indexes on the Keys

This works fine during development.

class Account
  include MongoMapper::Document
  ...
  # Attributes ::::::::::::::::::::::::::::::::::::::::::::::::::::::
  key :login, String, :unique => true, :index => true
  key :msid, String, :index => true
  key :doctor_num, String, :index => true
  ...
end

Define Indexes in an Initializer

When I wanted to trigger a new index creation, I would add it here. Only problem is that restarting a production server with tons of data gets held up by the create index task.

# Rails.root/config/initializers/mongo_config.rb
Account.ensure_index(:last_name)
Group.ensure_index(:name)
Group.ensure_index(:group_num)
...

Define Indexes in a Class Method, Invoke in Initializer

A small tweak to putting indexes into an initializer was to place the knowledge of the indexes back into the model classes themselves. Then, all you needed to do was invoke the model class method to create it’s own indexes.

The Initializer Code

 
# Rails.root/config/initializers/mongo_config.rb
Event.create_indexes
Encounter.create_indexes
Setting.create_indexes

The Model(s) Code

 
class Setting
  include MongoMapper::Document
  # Attributes ::::::::::::::::::::::::::::::::::::::::::::::::::::::
  # What the user sees as a label
  key :label, String
  # How we reference it in code
  key :identifier, String, :required => true
  ...
  # Indexes :::::::::::::::::::::::::::::::::::::::::::::::::::::::::
  def self.create_indexes
    self.ensure_index(:identifier, :unique => true)
    self.ensure_index(:label, :unique => true)
  end
  ...
end

Enter the Rake!

Of course, you could also invoke the index creation code in a rake task, as pointed out here.

The beauty behind a rake task as best I can tell is this:

  • You can run it at any time to update the indexes
  • You do not bring a deploy to a screeching halt because you are waiting for index creation

I was already standardizing on how I was creating indexes inside each model class — where better to keep on top of what the indexes for a class should be than in the class itself!

# app/models/setting.rb
class Setting
  ...
  def self.create_indexes
    self.ensure_index(:identifier, :unique => true)
    self.ensure_index(:label, :unique => true)
  end
  ...
end

I created a new class in the model directory (so that it is close to where the models are defined) that simply loops through each model class to generate the proper indexes:

# app/models/create_indexes.rb
class CreateIndexes
  def self.all
    puts "*"*15 + " GENERATING INDEXES" + "*"*15
    MongoMapper.database.collection_names.each do |coll|
      # Avoid "system.indexes"
      next if coll.index(".")

      model = coll.singularize.camelize.constantize
      model.create_indexes if model.respond_to?(:create_indexes)
      model.show_indexes if model.respond_to?(:show_indexes)
    end
  end
end

You can invoke it easily from the Rails console: CreateIndexes.all

Next I created a rake task (in lib/tasks/indexes.rake) that invoked the ruby code to do the indexing mojo.

namespace :db do
  namespace :mongo do
    desc "Create mongo_mapper indexes"
    task :index => :environment do
      CreateIndexes.all
    end
  end
end

Any tips/comments/insights appreciated…

PS: self.show_indexes Mix-in

I created a mix-in for the “show_indexes()” class method for each model. I could not add it directly to the MongoMapper::Document class unfortunately — I ran into errors and finally gave up. Here’s the mix-in that I defined in lib/mongo_utils.rb:

module MongoMapper
  module IndexUtils
    puts "Customizing #{self.inspect}"
    module ClassMethods
      def show_indexes
        puts "%s #{self.name} INDEXES %s" % ["*"*12, "*"*12]
        self.collection.index_information.collect do |index|
          puts "    #{index[0]}#{index[1].has_key?("unique") ? " (unique)":"x"}"
        end
      end
    end
    def self.included(base)
      #puts "#{base} is being extended'"
      base.extend(ClassMethods)
    end
  end
end

And you use it as follows:

require 'mongo_mapper'
require 'mongo_utils'
class Setting
  include MongoMapper::Document
  include MongoMapper::IndexUtils
  ...