Enable log duration by default for :debug-level logging.

lib/mongo/collection.rb

@@ -87,7 +87,6 @@ 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/connection.rb

@@ -36,7 +36,7 @@ module Mongo
 
     mongo_thread_local_accessor :connections
 
-    attr_reader :logger, :log_duration, :size, :auths, :primary, :safe, :host_to_try,
+    attr_reader :logger, :size, :auths, :primary, :safe, :host_to_try,
       :pool_size, :connect_timeout, :pool_timeout,
       :primary_pool, :socket_class, :op_timeout
 
@@ -63,8 +63,6 @@ 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,
@@ -558,11 +556,10 @@ module Mongo
       @primary      = nil
       @primary_pool = nil
 
-      @logger = opts[:logger] || nil
+      @logger = opts.fetch(:logger, nil)
 
       if @logger
         write_logging_startup_message
-        @log_duration = opts[:log_duration] || false
       end
 
       should_connect = opts.fetch(:connect, true)

lib/mongo/cursor.rb

@@ -43,7 +43,6 @@ 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

@@ -1,8 +1,10 @@
 module Mongo
   module Logging
 
+    DEBUG_LEVEL = defined?(Logger) ? Logger::DEBUG : 0
+
     def write_logging_startup_message
-      log(:warn, "Please note that logging negatively impacts client-side performance. " +
+      log(:debug, "Please note that logging negatively impacts client-side performance. " +
       "You should set your logging level no lower than :info in production.")
     end
 
@@ -10,42 +12,43 @@ module Mongo
     def log(level, msg)
       return unless @logger
       case level
-        when :debug then
-          @logger.debug "MONGODB [DEBUG] #{msg}"
-        when :warn then
-          @logger.warn "MONGODB [WARNING] #{msg}"
-        when :error then
-          @logger.error "MONGODB [ERROR] #{msg}"
         when :fatal then
           @logger.fatal "MONGODB [FATAL] #{msg}"
-        else
+        when :error then
+          @logger.error "MONGODB [ERROR] #{msg}"
+        when :warn then
+          @logger.warn "MONGODB [WARNING] #{msg}"
+        when :info then
           @logger.info "MONGODB [INFO] #{msg}"
+        when :debug then
+          @logger.debug "MONGODB [DEBUG] #{msg}"
+        else
+          @logger.debug "MONGODB [DEBUG] #{msg}"
       end
     end
 
     # Execute the block and log the operation described by name and payload.
     def instrument(name, payload = {}, &blk)
-      time_elapse = @log_duration ? Time.now : nil
+      start_time = Time.now
       res = yield
-      log_operation(name, payload, time_elapse)
+      if @logger && (@logger.level == DEBUG_LEVEL)
+        log_operation(name, payload, start_time)
+      end
       res
     end
 
     protected
 
-    def log_operation(name, payload, time_elapse=nil)
-      @logger ||= nil
-      return unless @logger
-      msg = "#{payload[:database]}['#{payload[:collection]}'].#{name}("
-      msg += payload.values_at(:selector, :document, :documents, :fields ).compact.map(&:inspect).join(', ') + ")"
-      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
+    def log_operation(name, payload, start_time)
+      msg = "MONGODB "
+      msg << "(#{((Time.now - start_time) * 1000).to_i}ms) "
+      msg << "#{payload[:database]}['#{payload[:collection]}'].#{name}("
+      msg << payload.values_at(:selector, :document, :documents, :fields ).compact.map(&:inspect).join(', ') + ")"
+      msg << ".skip(#{payload[:skip]})"   if payload[:skip]
+      msg << ".limit(#{payload[:limit]})" if payload[:limit]
+      msg << ".sort(#{payload[:order]})"  if payload[:order]
+
+      @logger.debug(msg)
     end
 
   end

test/connection_test.rb

@@ -141,8 +141,8 @@ class TestConnection < Test::Unit::TestCase
     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\)/)
+    connection = standard_connection(:logger => logger).db(MONGO_TEST_DB)
+    assert_match /\(\d+ms\)/, output.string
     assert output.string.include?("admin['$cmd'].find")
   end
 
@@ -157,21 +157,6 @@ 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')

test/unit/collection_test.rb

@@ -5,7 +5,8 @@ class CollectionTest < Test::Unit::TestCase
   context "Basic operations: " do
     setup do
       @logger = mock()
-      @logger.expects(:warn)
+      @logger.stubs(:level => 0)
+      @logger.expects(:debug)
     end
 
     should "send update message" do

test/unit/cursor_test.rb

@@ -5,8 +5,10 @@ class CursorTest < Test::Unit::TestCase
     setup do
       @logger     = mock()
       @logger.stubs(:debug)
-      @connection = stub(:class => Connection, :logger => @logger, :slave_ok? => false, :read_preference => :primary)
-      @db         = stub(:name => "testing", :slave_ok? => false, :connection => @connection, :read_preference => :primary)
+      @connection = stub(:class => Connection, :logger => @logger,
+        :slave_ok? => false, :read_preference => :primary, :log_duration => false)
+      @db         = stub(:name => "testing", :slave_ok? => false,
+        :connection => @connection, :read_preference => :primary)
       @collection = stub(:db => @db, :name => "items", :read_preference => :primary)
       @cursor     = Cursor.new(@collection)
     end
@@ -100,7 +102,8 @@ class CursorTest < Test::Unit::TestCase
     setup do
       @logger     = mock()
       @logger.stubs(:debug)
-      @connection = stub(:class => Connection, :logger => @logger, :slave_ok? => false)
+      @connection = stub(:class => Connection, :logger => @logger, :slave_ok? => false,
+        :log_duration => false)
       @db = stub(:slave_ok? => true, :name => "testing", :connection => @connection)
       @collection = stub(:db => @db, :name => "items", :read_preference => :primary)
     end