From b79d408a114dfa59efc43a7661f40f4cdf45012d Mon Sep 17 00:00:00 2001 From: Kyle Banker Date: Thu, 16 Feb 2012 14:00:52 -0500 Subject: [PATCH] Enable log duration by default for :debug-level logging. --- lib/mongo/collection.rb | 1 - lib/mongo/connection.rb | 7 ++---- lib/mongo/cursor.rb | 1 - lib/mongo/util/logging.rb | 49 +++++++++++++++++++----------------- test/connection_test.rb | 19 ++------------ test/unit/collection_test.rb | 3 ++- test/unit/cursor_test.rb | 9 ++++--- 7 files changed, 38 insertions(+), 51 deletions(-) diff --git a/lib/mongo/collection.rb b/lib/mongo/collection.rb index 9bdc14a..5ac7f1b 100644 --- a/lib/mongo/collection.rb +++ b/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 diff --git a/lib/mongo/connection.rb b/lib/mongo/connection.rb index b937b43..8856b66 100644 --- a/lib/mongo/connection.rb +++ b/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) diff --git a/lib/mongo/cursor.rb b/lib/mongo/cursor.rb index 9579562..ddbce9d 100644 --- a/lib/mongo/cursor.rb +++ b/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] || {} diff --git a/lib/mongo/util/logging.rb b/lib/mongo/util/logging.rb index b6f303d..eed04e3 100644 --- a/lib/mongo/util/logging.rb +++ b/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 diff --git a/test/connection_test.rb b/test/connection_test.rb index 8a64357..752a9ff 100644 --- a/test/connection_test.rb +++ b/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') diff --git a/test/unit/collection_test.rb b/test/unit/collection_test.rb index c6de84f..1fc796e 100644 --- a/test/unit/collection_test.rb +++ b/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 diff --git a/test/unit/cursor_test.rb b/test/unit/cursor_test.rb index 622e630..f7eac6f 100644 --- a/test/unit/cursor_test.rb +++ b/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