diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index fcafebdb0..64b9a6970 100644 --- a/app/controllers/application_controller.rb +++ b/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' diff --git a/lib/active_record_instantiation_logs.rb b/lib/active_record_instantiation_logs.rb new file mode 100644 index 000000000..3702ec2d3 --- /dev/null +++ b/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 + diff --git a/lib/log_overrider.rb b/lib/log_overrider.rb index ea42eefdb..494f4c1df 100644 --- a/lib/log_overrider.rb +++ b/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