add log_duration system to add time spend in database

lib/mongo/collection.rb

@@ -87,6 +87,7 @@ module Mongo
       @db, @name  = db, name
       @connection = @db.connection
       @logger     = @connection.logger
+      @log_duration = @connection.log_duration
       @cache_time = @db.cache_time
       @cache = Hash.new(0)
       unless pk_factory

lib/mongo/cursor.rb

@@ -43,6 +43,7 @@ module Mongo
       @collection = collection
       @connection = @db.connection
       @logger     = @connection.logger
+      @log_duration = @connection.log_duration
 
       # Query selector
       @selector   = opts[:selector] || {}

lib/mongo/util/logging.rb

@@ -25,14 +25,15 @@ module Mongo
 
     # Execute the block and log the operation described by name and payload.
     def instrument(name, payload = {}, &blk)
+      time_elapse = @log_duration ? Time.now : nil
       res = yield
-      log_operation(name, payload)
+      log_operation(name, payload, time_elapse)
       res
     end
 
     protected
 
-    def log_operation(name, payload)
+    def log_operation(name, payload, time_elapse=nil)
       @logger ||= nil
       return unless @logger
       msg = "#{payload[:database]}['#{payload[:collection]}'].#{name}("
@@ -40,8 +41,12 @@ module Mongo
       msg += ".skip(#{payload[:skip]})"  if payload[:skip]
       msg += ".limit(#{payload[:limit]})"  if payload[:limit]
       msg += ".sort(#{payload[:order]})"  if payload[:order]
+      if time_elapse
+        @logger.debug "MONGODB (#{Time.now - time_elapse}s) #{msg}"
+      else
         @logger.debug "MONGODB #{msg}"
       end
+    end
 
   end
 end

test/connection_test.rb

@@ -137,6 +137,15 @@ class TestConnection < Test::Unit::TestCase
     assert output.string.include?("admin['$cmd'].find")
   end
 
+  def test_logging_duration
+    output = StringIO.new
+    logger = Logger.new(output)
+    logger.level = Logger::DEBUG
+    connection = standard_connection(:logger => logger, :log_duration => true).db(MONGO_TEST_DB)
+    assert output.string.index(/\(0.\d+s\)/)
+    assert output.string.include?("admin['$cmd'].find")
+  end
+
   def test_connection_logger
     output = StringIO.new
     logger = Logger.new(output)