Add benchmarks

README.md

@@ -63,3 +63,25 @@ The IO format will write to anything that responds to the `#write` method.
 # config/environments/production.rb (or staging, etc)
 config.logger = ::ActiveSupport::TaggedLogging.new(::ActiveSupport::Logger.new(Timber::LogDevices::IO.new(STDOUT)))
 ```
+
+## Performance
+
+Timber was designed with an obsessive focus on performance and resource usage. In the `/benchmark` folder you'll find benchmarking tests.
+
+The following results were run on a bare metal server in order to achieve consistent and repeatable results.
+
+```
+Testing Rails request performance. 5000 requests per test.
+
+                  Real           Per request
+without Timber    4.41308498     0.00088262
+with Timber       4.47020912     0.00089404
+Difference       -0.05712414    -1.142e-05
+```
+
+The benchmark can be run yourself via:
+
+```console
+$ appraisal ruby benchmark/rails_request.rb
+```
+

benchmark/rails_request.rb

@@ -0,0 +1,36 @@
+#----------------------------------------------------------
+# This file demonstrates Rails performance with and without
+# the Timber library installed. Timber was designed with an
+# obsessive focus on performance and resource usage. The
+# below benchmarking test reveals this. A few notes:
+# 1. Both loggers are set to log to the same device.
+# 2. The log level is set to debug to maximize logging output.
+# 3. Timber is run last so that we can insert the probes after.
+#    This ensures Timber does not affect the environment at all.
+# ---------------------------------------------------------
+
+$:.unshift File.dirname(__FILE__)
+require "support/rails"
+require "benchmark"
+require "logger"
+
+ITERATIONS = 5_000
+PRECISION = 8
+test = Proc.new { ITERATIONS.times { Support::Rails.dispatch_rails_request("/") } }
+
+puts "\nTesting Rails request performance. #{ITERATIONS} requests per test.\n\n"
+puts "                  Real           Per request"
+
+without_timber = Benchmark.measure("without Timber", &test)
+without_timber_per = without_timber.real / ITERATIONS
+puts "#{without_timber.label}    #{without_timber.real.round(PRECISION)}     #{without_timber_per.round(PRECISION)}"
+
+# Install Timber
+Timber::Config.enabled = true
+Timber::Bootstrap.bootstrap!(RailsApp.config.app_middleware, ::Rails::Rack::Logger)
+
+with_timber = Benchmark.measure("with Timber", &test)
+with_timber_per = with_timber.real / ITERATIONS
+puts "#{with_timber.label}       #{with_timber.real.round(PRECISION)}     #{with_timber_per.round(PRECISION)}"
+
+puts "Difference       #{(without_timber.real - with_timber.real).round(PRECISION)}    #{(without_timber_per - with_timber_per).round(PRECISION)}"

benchmark/support/rails.rb

@@ -0,0 +1,71 @@
+require "rails"
+require "action_controller"
+require "timber"
+require "stringio"
+
+# Helper methods
+module Support
+  module Rails
+    def self.dispatch_rails_request(path)
+      application = ::Rails.application
+      env = application.respond_to?(:env_config) ? application.env_config.clone : application.env_defaults.clone
+      env["rack.request.cookie_hash"] = {}.with_indifferent_access
+      ::Rack::MockRequest.new(application).get(path, env)
+    end
+
+    def self.set_logger(log_dev)
+      logger = defined?(::ActiveSupport::Logger) ? ::ActiveSupport::Logger.new(log_dev) : ::Logger.new(log_dev)
+      ::Rails.logger = defined?(::ActiveSupport::TaggedLogging) ? ::ActiveSupport::TaggedLogging.new(logger) : logger
+      ::Rails.logger.level = ::Logger::DEBUG # log everything
+    end
+
+    def self.set_timber_logger
+      set_logger(Timber::LogDevices::IO.new(StringIO.new))
+    end
+  end
+end
+
+# Disable by default
+Timber::Config.enabled = false
+
+# Setup default rails logger with StringIO.
+# This ensures that the log data isn't output, but the level is sufficient
+# to be logged.
+Support::Rails.set_logger(StringIO.new)
+
+# Base rails app
+class RailsApp < Rails::Application
+  if ::Rails.version =~ /^3\./
+    config.secret_token = '1e05af2b349457936a41427e63450937'
+  else
+    config.secret_key_base = '1e05af2b349457936a41427e63450937'
+  end
+  config.active_support.deprecation = :stderr
+  config.eager_load = false
+end
+
+# Start the app to get initialization out of the way
+RailsApp.initialize!
+
+# Setup a controller
+class PagesController < ActionController::Base
+  layout nil
+
+  def index
+    # Similuate above average logging for a single action
+    25.times { Rails.logger.info("this is a test log message") }
+    render json: {}
+  end
+
+  def method_for_action(action_name)
+    action_name
+  end
+end
+
+# Some routes
+::RailsApp.routes.draw do
+  get '/' => 'pages#index'
+end
+
+# Dispatch a request to get the initial caching / loading out of the way
+Support::Rails.dispatch_rails_request("/")

lib/timber/context.rb

@@ -39,8 +39,8 @@ def _root_key
     def as_json_with_index(index)
       keys = _path.split(".")
       hash = as_json
-      target_hash = keys.inject(hash) do |acc, value|
-        acc[value] || raise("could not find key #{value.inspect} for #{hash}")
+      target_hash = keys.inject(hash) do |acc, key|
+        acc[key.to_sym] || raise("could not find key #{value.inspect} for #{hash}")
       end
       target_hash["_index"] = index
       hash

lib/timber/patterns/to_json.rb

@@ -1,20 +1,16 @@
 module Timber
   module Patterns
-    # Module to fall inline with Rail's craziness changing default object behavior.
+    # Module to fall inline with Rail's core object crazy changes.
     # If Rails is present, it will play nice. If not, it will work just fine.
     module ToJSON
+      # We explicitly do not do anything with the arguments as we do not need them.
+      # We avoid the unneccssary complexity.
       def as_json(*args)
-        @as_json ||= {}
-        @as_json[args] ||= begin
-          hash = json_payload # only call the function once incase it is not cached
-          hash = hash.respond_to?(:as_json) ? hash.as_json(*args) : hash
-          Macros::Compactor.compact(hash)
-        end
+        @as_json ||= Macros::Compactor.compact(json_payload)
       end
 
       def to_json(*args)
-        @to_json ||= {}
-        @to_json[args] ||= as_json(*args).to_json
+        @to_json ||= as_json.to_json
       end
 
       private

lib/timber/version.rb

@@ -1,3 +1,3 @@
 module Timber
-  VERSION = "0.0.1-beta1".freeze
+  VERSION = "1.0.0.beta1"
 end

spec/timber/patterns/to_json_spec.rb

@@ -19,7 +19,7 @@ def initialize(json_payload)
 
     context "with a value" do
       let(:hash) { {:test => 1} }
-      it { should eq({"test" => 1}) }
+      it { should eq({:test => 1}) }
     end
 
     context "with a nil value" do