Fixed that benchmarking times for rendering included db runtimes #987 [skaes@web.de]

git-svn-id: http://svn-commit.rubyonrails.org/rails/trunk@1070 5ecf4fe2-1ee6-0310-87b1-e25e094e27de

2 files changed, 12 insertions, 4 deletions

diff --git a/actionpack/lib/action_controller/benchmarking.rb b/actionpack/lib/action_controller/benchmarking.rb
index e6ff65e150..6f4c248d70 100644
--- a/actionpack/lib/action_controller/benchmarking.rb
+++ b/actionpack/lib/action_controller/benchmarking.rb
@@ -19,7 +19,11 @@ module ActionController #:nodoc:
       if logger.nil?
         render_without_benchmark(template_name, status)
       else
+        db_runtime = ActiveRecord::Base.connection.reset_runtime
         @rendering_runtime = Benchmark::measure{ render_without_benchmark(template_name, status) }.real
+        @db_rt_before_render = db_runtime
+        @db_rt_after_render = ActiveRecord::Base.connection.reset_runtime
+        @rendering_runtime -= @db_rt_after_render
       end
     end    
 
@@ -28,7 +32,7 @@ module ActionController #:nodoc:
         perform_action_without_benchmark
       else
         runtime = [Benchmark::measure{ perform_action_without_benchmark }.real, 0.0001].max
-        log_message  = "Completed in #{sprintf("%4f", runtime)} (#{(1 / runtime).floor} reqs/sec)"
+        log_message  = "Completed in #{sprintf("%.5f", runtime)} (#{(1 / runtime).floor} reqs/sec)"
         log_message << rendering_runtime(runtime) if @rendering_runtime
         log_message << active_record_runtime(runtime) if Object.const_defined?("ActiveRecord") && ActiveRecord::Base.connected?
         logger.info(log_message)
@@ -37,13 +41,15 @@ module ActionController #:nodoc:
     
     private
       def rendering_runtime(runtime)
-        " | Rendering: #{sprintf("%f", @rendering_runtime)} (#{sprintf("%d", (@rendering_runtime / runtime) * 100)}%)"
+        " | Rendering: #{sprintf("%.5f", @rendering_runtime)} (#{sprintf("%d", (@rendering_runtime * 100) / runtime)}%)"
       end
 
       def active_record_runtime(runtime)
         db_runtime    = ActiveRecord::Base.connection.reset_runtime
-        db_percentage = (db_runtime / runtime) * 100
-        " | DB: #{sprintf("%f", db_runtime)} (#{sprintf("%d", db_percentage)}%)"
+        db_runtime    += @db_rt_before_render if @db_rt_before_render
+        db_runtime    += @db_rt_after_render if @db_rt_after_render
+        db_percentage = (db_runtime * 100) / runtime
+        " | DB: #{sprintf("%.5f", db_runtime)} (#{sprintf("%d", db_percentage)}%)"
       end
   end
 end
diff --git a/activerecord/CHANGELOG b/activerecord/CHANGELOG
index e11847d48d..593d1c806d 100644
--- a/activerecord/CHANGELOG
+++ b/activerecord/CHANGELOG
@@ -1,5 +1,7 @@
 *SVN*
 
+* Fixed that benchmarking times for rendering included db runtimes #987 [skaes@web.de]
+
 * Fixed boolean queries for t/f fields in PostgreSQL #995 [dave@cherryville.org]
 
 * Added that model.items.delete(child) will delete the child, not just set the foreign key to nil, if the child is dependent on the model #978 [bitsweat]