Instrumenting activerecord object instantiation to do some profiling

app/controllers/application_controller.rb

@@ -17,7 +17,6 @@ class ApplicationController < ActionController::Base
   before_filter :set_grammatical_gender
 
   inflection_method :grammatical_gender => :gender
-  #include Oink::InstanceTypeCounter
 
   def ensure_http_referer_is_set
     request.env['HTTP_REFERER'] ||= '/aspects'

lib/active_record_instantiation_logs.rb

@@ -0,0 +1,111 @@
+#This file ripped out of Oink at:
+# github.com/noahd1/oink
+# Thanks!
+  require 'benchmark'
+module Oink
+
+  def self.extended_active_record?
+    @oink_extended_active_record
+  end
+
+  def self.extended_active_record!
+    @oink_extended_active_record = true
+  end
+
+  module InstanceTypeCounter
+    def self.included(klass)
+      ActiveRecord::Base.send(:include, OinkInstanceTypeCounterInstanceMethods)
+    end
+
+    def before_report_active_record_count(instantiation_data)
+    end
+
+    def report_hash!
+      hash = self.report_hash
+      ActiveRecord::Base.reset_instance_type_count
+      hash
+    end
+    def report_hash
+      hash = ActiveRecord::Base.instantiated_hash.merge(
+        :total_ar_inst => ActiveRecord::Base.total_objects_instantiated,
+        :total_ar_ms => ActiveRecord::Base.instantiation_time)
+      before_report_active_record_count(hash)
+      hash
+    end
+
+    def report_instance_type_count
+      hash = self.hash
+      hash[:event] = 'instantiation_breakdown'
+      before_report_active_record_count(hash)
+      if logger
+        logger.info(hash)
+      end
+      ActiveRecord::Base.reset_instance_type_count
+    end
+  end
+
+  module OinkInstanceTypeCounterInstanceMethods
+
+    def self.included(klass)
+      klass.class_eval do
+
+        @@instantiated = {}
+        @@total = nil
+        @@time = 0.0
+
+        def self.reset_instance_type_count
+          @@time = 0.0
+          @@instantiated = {}
+          @@total = nil
+        end
+
+        def self.increment_instance_type_count(time)
+          @@instantiated[base_class.name] ||= 0
+          @@instantiated[base_class.name] += 1
+          @@time += time
+        end
+
+        def self.instantiated_hash
+          @@instantiated
+        end
+
+        def self.instantiation_time
+          @@time
+        end
+
+        def self.total_objects_instantiated
+          @@total ||= @@instantiated.values.sum
+        end
+
+        unless Oink.extended_active_record?
+          class << self
+            alias_method :instantiate_before_oink, :instantiate
+
+            def instantiate(*args, &block)
+              value = nil
+              time = Benchmark.realtime{
+                value = instantiate_before_oink(*args, &block)
+              }*1000
+              increment_instance_type_count(time)
+              value
+            end
+          end
+
+          alias_method :initialize_before_oink, :initialize
+
+          def initialize(*args, &block)
+            value = nil
+            time = Benchmark.realtime{
+              value = initialize_before_oink(*args, &block)
+            }*1000
+            self.class.increment_instance_type_count(time)
+            value
+          end
+
+          Oink.extended_active_record!
+        end
+      end
+    end
+  end
+end
+

lib/log_overrider.rb

@@ -30,6 +30,8 @@ module ActionDispatch
 end
 
 class ActionController::LogSubscriber
+  require 'lib/active_record_instantiation_logs'
+  include Oink::InstanceTypeCounter
   def start_processing(event)
     #noop
   end
@@ -46,15 +48,14 @@ class ActionController::LogSubscriber
                 :format => payload[:formats].first.to_s.upcase,
                 :ms => "%.0f" % event.duration,
                 :params => params.inspect}
-    log_hash.merge({
+    log_hash.merge!({
                 :gc_ms => GC.time/1000,
                 :gc_collections => GC.collections,
                 :gc_bytes=> GC.growth}) if GC.respond_to?(:enable_stats)
 
 
-    log_hash.merge({:params =>params.inspect}) unless params.empty?
     #log_hash << "additions='#{additions.join(" | ")}' " unless additions.blank?
-
+    log_hash.merge!(report_hash!)
 
     Rails.logger.info(log_hash)
   end