diff --git a/README.md b/README.md index 8293711f..71e30c8f 100644 --- a/README.md +++ b/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 +``` + diff --git a/benchmark/rails_request.rb b/benchmark/rails_request.rb index e69de29b..fd628cc6 100644 --- a/benchmark/rails_request.rb +++ b/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)}" diff --git a/benchmark/support/rails.rb b/benchmark/support/rails.rb new file mode 100644 index 00000000..28f8d644 --- /dev/null +++ b/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("/") diff --git a/lib/timber/context.rb b/lib/timber/context.rb index ada323e2..4431d062 100644 --- a/lib/timber/context.rb +++ b/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 diff --git a/lib/timber/patterns/to_json.rb b/lib/timber/patterns/to_json.rb index ec955e86..67616b36 100644 --- a/lib/timber/patterns/to_json.rb +++ b/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 diff --git a/lib/timber/version.rb b/lib/timber/version.rb index cae95e75..5b84034e 100644 --- a/lib/timber/version.rb +++ b/lib/timber/version.rb @@ -1,3 +1,3 @@ module Timber - VERSION = "0.0.1-beta1".freeze + VERSION = "1.0.0.beta1" end diff --git a/spec/timber/patterns/to_json_spec.rb b/spec/timber/patterns/to_json_spec.rb index 000fccb0..1fc42ac8 100644 --- a/spec/timber/patterns/to_json_spec.rb +++ b/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