Merge pull request #85 from shingara/log_duration

Add a log duration option.

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
@@ -264,8 +265,8 @@ module Mongo
     # @return [OrderedHash, Nil]
     #   a single document or nil if no result is found.
     #
-    # @param [Hash, ObjectId, Nil] spec_or_object_id a hash specifying elements 
-    #   which must be present for a document to be included in the result set or an 
+    # @param [Hash, ObjectId, Nil] spec_or_object_id a hash specifying elements
+    #   which must be present for a document to be included in the result set or an
     #   instance of ObjectId to be used as the value for an _id query.
     #   If nil, an empty selector, {}, will be used.
     #
@@ -413,7 +414,7 @@ module Mongo
     # @option opts [Boolean] :upsert (+false+) if true, performs an upsert (update or insert)
     # @option opts [Boolean] :multi (+false+) update all documents matching the selector, as opposed to
     #   just the first matching document. Note: only works in MongoDB 1.1.3 or later.
-    # @option opts [Boolean] :safe (+false+) 
+    # @option opts [Boolean] :safe (+false+)
     #   If true, check that the save succeeded. OperationFailure
     #   will be raised on an error. Note that a safe check requires an extra
     #   round-trip to the database. Safe options provided here will override any safe
@@ -906,12 +907,12 @@ module Mongo
           if [Mongo::ASCENDING, Mongo::DESCENDING, Mongo::GEO2D, Mongo::GEOHAYSTACK].include?(f[1])
             field_spec[f[0].to_s] = f[1]
           else
-            raise MongoArgumentError, "Invalid index field #{f[1].inspect}; " + 
+            raise MongoArgumentError, "Invalid index field #{f[1].inspect}; " +
               "should be one of Mongo::ASCENDING (1), Mongo::DESCENDING (-1) or Mongo::GEO2D ('2d')."
           end
         end
       else
-        raise MongoArgumentError, "Invalid index specification #{spec.inspect}; " + 
+        raise MongoArgumentError, "Invalid index specification #{spec.inspect}; " +
           "should be either a string, symbol, or an array of arrays."
       end
       field_spec

lib/mongo/connection.rb

@@ -36,7 +36,7 @@ module Mongo
 
     mongo_thread_local_accessor :connections
 
-    attr_reader :logger, :size, :auths, :primary, :safe, :host_to_try,
+    attr_reader :logger, :log_duration, :size, :auths, :primary, :safe, :host_to_try,
       :pool_size, :connect_timeout, :pool_timeout,
       :primary_pool, :socket_class, :op_timeout
 
@@ -63,6 +63,8 @@ module Mongo
     #   to a single, slave node.
     # @option opts [Logger, #debug] :logger (nil) A Logger instance for debugging driver ops. Note that
     #   logging negatively impacts performance; therefore, it should not be used for high-performance apps.
+    # @option opts [Boolean, #debug] :log_duration (nil) A boolean to say if you want see information about log_duration on logger
+    #   like logging, log_duration negatively impacts performance; therefore, it should not be used for high-performance apps.
     # @option opts [Integer] :pool_size (1) The maximum number of socket self.connections allowed per
     #   connection pool. Note: this setting is relevant only for multi-threaded applications.
     # @option opts [Float] :pool_timeout (5.0) When all of the self.connections a pool are checked out,
@@ -348,7 +350,7 @@ module Mongo
       self["admin"].command(oh)
     end
 
-    # Checks if a server is alive. This command will return immediately 
+    # Checks if a server is alive. This command will return immediately
     # even if the server is in a lock.
     #
     # @return [Hash]
@@ -383,7 +385,7 @@ module Mongo
       Thread.current[:socket_map] ||= {}
       Thread.current[:socket_map][self] ||= {}
       Thread.current[:socket_map][self][:writer] ||= checkout_writer
-      Thread.current[:socket_map][self][:reader] = 
+      Thread.current[:socket_map][self][:reader] =
         Thread.current[:socket_map][self][:writer]
     end
 
@@ -568,6 +570,7 @@ module Mongo
 
       if @logger
         write_logging_startup_message
+        @log_duration = opts[:log_duration] || false
       end
 
       should_connect = opts.fetch(:connect, true)

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] || {}
@@ -199,7 +200,7 @@ module Mongo
     # This method overrides any sort order specified in the Collection#find
     # method, and only the last sort applied has an effect.
     #
-    # @param [Symbol, Array] key_or_list either 1) a key to sort by or 2) 
+    # @param [Symbol, Array] key_or_list either 1) a key to sort by or 2)
     #   an array of [key, direction] pairs to sort by. Direction should
     #   be specified as Mongo::ASCENDING (or :ascending / :asc) or Mongo::DESCENDING (or :descending / :desc)
     #

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,7 +41,11 @@ module Mongo
       msg += ".skip(#{payload[:skip]})"  if payload[:skip]
       msg += ".limit(#{payload[:limit]})"  if payload[:limit]
       msg += ".sort(#{payload[:order]})"  if payload[:order]
-      @logger.debug "MONGODB #{msg}"
+      if time_elapse
+        @logger.debug "MONGODB (#{Time.now - time_elapse}s) #{msg}"
+      else
+        @logger.debug "MONGODB #{msg}"
+      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)
@@ -148,6 +157,21 @@ class TestConnection < Test::Unit::TestCase
     assert output.string.include?('testing')
   end
 
+  def test_connection_log_duration_with_logger
+    output = StringIO.new
+    logger = Logger.new(output)
+    logger.level = Logger::DEBUG
+    connection = standard_connection(:logger => logger, :log_duration => true)
+    assert logger, connection.logger
+    assert connection.log_duration
+  end
+
+  def test_connection_log_duration_without_logger
+    connection = standard_connection(:log_duration => true)
+    assert_nil connection.logger
+    assert !connection.log_duration
+  end
+
   def test_drop_database
     db = @conn.db('ruby-mongo-will-be-deleted')
     coll = db.collection('temp')