Benchmark.ms

9 files changed, 43 insertions, 34 deletions

diff --git a/actionpack/lib/action_controller/benchmarking.rb b/actionpack/lib/action_controller/benchmarking.rb
index fa572ebf3d..732f774fbc 100644
--- a/actionpack/lib/action_controller/benchmarking.rb
+++ b/actionpack/lib/action_controller/benchmarking.rb
@@ -23,8 +23,8 @@ module ActionController #:nodoc:
       def benchmark(title, log_level = Logger::DEBUG, use_silence = true)
         if logger && logger.level == log_level
           result = nil
-          seconds = Benchmark.realtime { result = use_silence ? silence { yield } : yield }
-          logger.add(log_level, "#{title} (#{('%.1f' % (seconds * 1000))}ms)")
+          ms = Benchmark.ms { result = use_silence ? silence { yield } : yield }
+          logger.add(log_level, "#{title} (#{('%.1f' % ms)}ms)")
           result
         else
           yield
@@ -48,7 +48,7 @@ module ActionController #:nodoc:
           end
 
           render_output = nil
-          @view_runtime = Benchmark::realtime { render_output = render_without_benchmark(options, extra_options, &block) }
+          @view_runtime = Benchmark.ms { render_output = render_without_benchmark(options, extra_options, &block) }
 
           if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
             @db_rt_before_render = db_runtime
@@ -65,11 +65,11 @@ module ActionController #:nodoc:
     private
       def perform_action_with_benchmark
         if logger
-          seconds = [ Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001 ].max
+          ms = [Benchmark.ms { perform_action_without_benchmark }, 0.01].max
           logging_view          = defined?(@view_runtime)
           logging_active_record = Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
 
-          log_message  = "Completed in #{sprintf("%.0f", seconds * 1000)}ms"
+          log_message  = 'Completed in %.0fms' % ms
 
           if logging_view || logging_active_record
             log_message << " ("
@@ -87,21 +87,21 @@ module ActionController #:nodoc:
           log_message << " [#{complete_request_uri rescue "unknown"}]"
 
           logger.info(log_message)
-          response.headers["X-Runtime"] = "#{sprintf("%.0f", seconds * 1000)}ms"
+          response.headers["X-Runtime"] = "%.0f" % ms
         else
           perform_action_without_benchmark
         end
       end
 
       def view_runtime
-        "View: %.0f" % (@view_runtime * 1000)
+        "View: %.0f" % @view_runtime
       end
 
       def active_record_runtime
         db_runtime = ActiveRecord::Base.connection.reset_runtime
         db_runtime += @db_rt_before_render if @db_rt_before_render
         db_runtime += @db_rt_after_render if @db_rt_after_render
-        "DB: %.0f" % (db_runtime * 1000)
+        "DB: %.0f" % db_runtime
       end
   end
 end
diff --git a/actionpack/lib/action_controller/request_profiler.rb b/actionpack/lib/action_controller/request_profiler.rb
index 70bb77e7ac..80cd55334f 100644
--- a/actionpack/lib/action_controller/request_profiler.rb
+++ b/actionpack/lib/action_controller/request_profiler.rb
@@ -20,7 +20,7 @@ module ActionController
         @quiet = true
         print '  '
 
-        result = Benchmark.realtime do
+        ms = Benchmark.ms do
           n.times do |i|
             run(profiling)
             print_progress(i)
@@ -28,7 +28,7 @@ module ActionController
         end
 
         puts
-        result
+        ms
       ensure
         @quiet = false
       end
@@ -88,7 +88,7 @@ module ActionController
       puts 'Warming up once'
 
       elapsed = warmup(sandbox)
-      puts '%.2f sec, %d requests, %d req/sec' % [elapsed, sandbox.request_count, sandbox.request_count / elapsed]
+      puts '%.0f ms, %d requests, %d req/sec' % [elapsed, sandbox.request_count, 1000 * sandbox.request_count / elapsed]
       puts "\n#{options[:benchmark] ? 'Benchmarking' : 'Profiling'} #{options[:n]}x"
 
       options[:benchmark] ? benchmark(sandbox) : profile(sandbox)
@@ -106,13 +106,13 @@ module ActionController
 
     def benchmark(sandbox, profiling = false)
       sandbox.request_count = 0
-      elapsed = sandbox.benchmark(options[:n], profiling).to_f
+      elapsed = sandbox.benchmark(options[:n], profiling)
       count = sandbox.request_count.to_i
-      puts '%.2f sec, %d requests, %d req/sec' % [elapsed, count, count / elapsed]
+      puts '%.0f ms, %d requests, %d req/sec' % [elapsed, count, 1000 * count / elapsed]
     end
 
     def warmup(sandbox)
-      Benchmark.realtime { sandbox.run(false) }
+      Benchmark.ms { sandbox.run(false) }
     end
 
     def default_options
diff --git a/actionpack/lib/action_view/helpers/benchmark_helper.rb b/actionpack/lib/action_view/helpers/benchmark_helper.rb
index bd72cda700..372d24a22e 100644
--- a/actionpack/lib/action_view/helpers/benchmark_helper.rb
+++ b/actionpack/lib/action_view/helpers/benchmark_helper.rb
@@ -22,12 +22,12 @@ module ActionView
       # (:debug, :info, :warn, :error); the default value is :info.
       def benchmark(message = "Benchmarking", level = :info)
         if controller.logger
-          seconds = Benchmark.realtime { yield }
-          controller.logger.send(level, "#{message} (#{'%.1f' % (seconds * 1000)}ms)")
+          ms = Benchmark.ms { yield }
+          controller.logger.send(level, '%s (%.1fms)' % [message, ms])
         else
           yield
         end
       end
     end
   end
-end
\ No newline at end of file
+end
diff --git a/activerecord/lib/active_record/base.rb b/activerecord/lib/active_record/base.rb
index 5d614442c3..a23518b357 100755
--- a/activerecord/lib/active_record/base.rb
+++ b/activerecord/lib/active_record/base.rb
@@ -1417,8 +1417,8 @@ module ActiveRecord #:nodoc:
       def benchmark(title, log_level = Logger::DEBUG, use_silence = true)
         if logger && logger.level <= log_level
           result = nil
-          seconds = Benchmark.realtime { result = use_silence ? silence { yield } : yield }
-          logger.add(log_level, "#{title} (#{'%.1f' % (seconds * 1000)}ms)")
+          ms = Benchmark.ms { result = use_silence ? silence { yield } : yield }
+          logger.add(log_level, '%s (%.1fms)' % [title, ms])
           result
         else
           yield
diff --git a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
index cab77fc031..bfafcfb3ab 100755
--- a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
+++ b/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb
@@ -160,9 +160,9 @@ module ActiveRecord
         @open_transactions -= 1
       end
 
-      def log_info(sql, name, seconds)
+      def log_info(sql, name, ms)
         if @logger && @logger.debug?
-          name = "#{name.nil? ? "SQL" : name} (#{sprintf("%.1f", seconds * 1000)}ms)"
+          name = '%s (%.1fms)' % [name || 'SQL', ms]
           @logger.debug(format_log_entry(name, sql.squeeze(' ')))
         end
       end
@@ -171,9 +171,9 @@ module ActiveRecord
         def log(sql, name)
           if block_given?
             result = nil
-            seconds = Benchmark.realtime { result = yield }
-            @runtime += seconds
-            log_info(sql, name, seconds)
+            ms = Benchmark.ms { result = yield }
+            @runtime += ms
+            log_info(sql, name, ms)
             result
           else
             log_info(sql, name, 0)
diff --git a/activeresource/lib/active_resource/connection.rb b/activeresource/lib/active_resource/connection.rb
index 273fee3286..85103b53c5 100644
--- a/activeresource/lib/active_resource/connection.rb
+++ b/activeresource/lib/active_resource/connection.rb
@@ -146,8 +146,8 @@ module ActiveResource
       def request(method, path, *arguments)
         logger.info "#{method.to_s.upcase} #{site.scheme}://#{site.host}:#{site.port}#{path}" if logger
         result = nil
-        time = Benchmark.realtime { result = http.send(method, path, *arguments) }
-        logger.info "--> %d %s (%d %.2fs)" % [result.code, result.message, result.body ? result.body.length : 0, time] if logger
+        ms = Benchmark.ms { result = http.send(method, path, *arguments) }
+        logger.info "--> %d %s (%d %.0fms)" % [result.code, result.message, result.body ? result.body.length : 0, ms] if logger
         handle_response(result)
       rescue Timeout::Error => e
         raise TimeoutError.new(e.message)
diff --git a/activesupport/CHANGELOG b/activesupport/CHANGELOG
index 0e796d802c..a74c645981 100644
--- a/activesupport/CHANGELOG
+++ b/activesupport/CHANGELOG
@@ -1,5 +1,7 @@
 *2.3.0 [Edge]*
 
+* Add Benchmark.ms convenience method to benchmark realtime in milliseconds.  [Jeremy Kemper]
+
 * Multibyte: add multibyte-safe Chars#ord rather than falling back to String#ord.  #1483 [Jason Cheow]
 
 * I18n support for Array#to_sentence. Introduces support.array.words_connector, .two_words_connector, and .last_word_connector translation keys.  #1397 [Akira Matsuda]
diff --git a/activesupport/lib/active_support/cache.rb b/activesupport/lib/active_support/cache.rb
index 10281d60eb..6a6c861458 100644
--- a/activesupport/lib/active_support/cache.rb
+++ b/activesupport/lib/active_support/cache.rb
@@ -143,13 +143,13 @@ module ActiveSupport
           log("miss", key, options)
 
           value = nil
-          seconds = Benchmark.realtime { value = yield }
+          ms = Benchmark.ms { value = yield }
 
           @logger_off = true
           write(key, value, options)
           @logger_off = false
 
-          log("write (will save #{'%.2f' % (seconds * 1000)}ms)", key, nil)
+          log('write (will save %.2fms)' % ms, key, nil)
 
           value
         end
diff --git a/activesupport/lib/active_support/core_ext/benchmark.rb b/activesupport/lib/active_support/core_ext/benchmark.rb
index 79ba165e3a..ae57b152e8 100644
--- a/activesupport/lib/active_support/core_ext/benchmark.rb
+++ b/activesupport/lib/active_support/core_ext/benchmark.rb
@@ -1,12 +1,19 @@
 require 'benchmark'
 
 class << Benchmark
-  remove_method :realtime
+  # Earlier Ruby had a slower implementation.
+  if RUBY_VERSION < '1.8.7'
+    remove_method :realtime
 
-  def realtime
-    r0 = Time.now
-    yield
-    r1 = Time.now
-    r1.to_f - r0.to_f
+    def realtime
+      r0 = Time.now
+      yield
+      r1 = Time.now
+      r1.to_f - r0.to_f
+    end
+  end
+
+  def ms
+    1000 * realtime { yield }
   end
 end