Skip to content
This repository

Dalli / memcached slowness in Rails 3.2 project after upgrade #236

Closed
KensoDev opened this Issue July 09, 2012 · 22 comments

5 participants

Avi Tzurel Mike Perham the8472 Rutger Geelen Virgilio Pigliucci
Avi Tzurel

upfront warning, I am not 100% sure this is coming from Dalli but I wanted to post an issue because there's a good chance it is and I wanted to discuss possible solutions (if any)

We upgraded the Gogobot app 2 days ago to run on Rails 3.2.

The code base is exactly the same, other then the upgrade nothing obviously changed from the current version of the app.

The current version of the app is Rails 3.0.9 and we have been using Dalli for a long while now, on the current app and it's running super smooth with no problems at all.

The minute we released the new version, the app started to be very slow and the memcached section in NewRelic showed significant slowness from the current app version.

Here's a screenshot from the 3.2 version from NewRelic.

As you can see, memcached is taking 80ms per request.

Now, here's a screenshot from the current version of the app (rolled back to Rails 3.0.9)

memcached time is 22.1ms.

From looking into memcached stats, the number of gets and sets is similar, it's not like cache is working harder for any apparent reason.

Some Benchmarks (From Rails 3.2)

    system :004 > time = Benchmark.measure do
    system :005 >     10000.times do
    system :006 >       Rails.cache.write(user, user)
    system :007?>     end
    system :008?>   end
     =>  10.360000   0.340000  10.700000 ( 14.891436)

    system :013 > time = Benchmark.measure do
    system :014 >     10000.times do
    system :015 >       Rails.cache.read(user)
    system :016?>     end
    system :017?>   end
     =>  11.960000   0.560000  12.520000 ( 17.050014)

Benchmarks from rails 3.0.9

     system :010 > time = Benchmark.measure do 
    system :011 >     10000.times do
    system :012 >       Rails.cache.write(user, user)
    system :013?>     end
    system :014?>   end
     =>   7.950000   0.250000   8.200000 ( 12.282373)

    system :022 > time = Benchmark.measure do
    system :023 >     10000.times do
    system :024 >       Rails.cache.read(user)
    system :025?>     end
    system :026?>   end
     =>  10.790000   0.360000  11.150000 ( 16.375308)

Dalli version used on the 3.2 is the latest available, the 3.0 version uses 1.1.2.

During the upgrade, we obviously upgraded other gems to the newest version, let me know if the Gemfile.lock from the 2 versions would be helpful, I will post it here.

These were done on staging ENV, local memcached server, no requests but the benchmark one, so memcached was not working on anything other then the benchmark.

Thoughts?

Mike Perham
Owner

:dalli_store was completely rewritten for speed and efficiency for the 2.0 release. My testing showed it 25% faster than 1.1.x but that was just for the operations I tested. I know that the Dalli::Client performance did not regress for 2.0 but it's possible that dalli_store has an issue. Would it be possible for you to profile the Dalli operations in your staging environment and get call graph numbers for at least 2.0?

Avi Tzurel

I will profile around the write blocks and the read blocks and post the graphs here.

Avi Tzurel

Here's the profile, single cache write.

Thread ID: 3319920
Total Time: 0.004249217999998223
Sort by: total_time

  %total   %self     total      self      wait     child            calls    Name
--------------------------------------------------------------------------------
 100.00%   0.42%      0.00      0.00      0.00      0.00                1      Object#irb_binding
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write
                      0.00      0.00      0.00      0.00              1/1      <Module::Rails>#cache
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Object#irb_binding
  99.36%   0.27%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#write
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#instrument
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#expanded_key
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write
  89.00%   0.37%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#instrument
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write_entry
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#log
                      0.00      0.00      0.00      0.00              1/1      <Class::ActiveSupport::Cache::Store>#instrument
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#instrument
  79.30%   0.31%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#write_entry
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#set_with_newrelic_trace
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#escape
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write_entry
  77.66%   0.48%      0.00      0.00      0.00      0.00                1      Dalli::Client#set_with_newrelic_trace
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                      0.00      0.00      0.00      0.00              1/1      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.00      0.00      0.00      0.00             1/12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#set_with_newrelic_trace
  76.75%   0.94%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#set
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      0.00      0.00      0.00      0.00              2/2      Time#to_f
                      0.00      0.00      0.00      0.00              3/4      <Class::Time>#now
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
                      0.00      0.00      0.00      0.00              2/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/4      Dalli::Threadsafe#alive?
                      0.00      0.00      0.00      0.00              1/4      Logger::LogDevice#write
                      0.00      0.00      0.00      0.00              1/4      Dalli::Threadsafe#request
  57.28%   0.98%      0.00      0.00      0.00      0.00                4     *MonitorMixin#mon_synchronize
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#request
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_exit
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_enter
                      0.00      0.00      0.00      0.00              1/2      IO#write
                      0.00      0.00      0.00      0.00              2/2      Dalli::Server#alive?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
  56.94%   0.27%      0.00      0.00      0.00      0.00                1      Dalli::Client#set
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#perform
                      0.00      0.00      0.00      0.00              1/1      NilClass#to_i
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#set
  56.56%   0.44%      0.00      0.00      0.00      0.00                1      Dalli::Client#perform
                      0.00      0.00      0.00      0.00              1/1      Dalli::Threadsafe#request
                      0.00      0.00      0.00      0.00              1/1      Dalli::Ring#server_for_key
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#validate_key
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#ring
                      0.00      0.00      0.00      0.00              1/7      String#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#perform
  53.64%   0.15%      0.00      0.00      0.00      0.00                1      Dalli::Threadsafe#request
                      0.00      0.00      0.00      0.00              1/4      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      MonitorMixin#mon_synchronize
  52.29%   0.32%      0.00      0.00      0.00      0.00                1      Dalli::Server#request
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#set
                      0.00      0.00      0.00      0.00              1/2      Dalli::Threadsafe#alive?
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#verify_state
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#request
  50.57%   0.55%      0.00      0.00      0.00      0.00                1      Dalli::Server#set
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#serialize
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#generic_response
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#write
                      0.00      0.00      0.00      0.00              2/2      Dalli::Server#multi?
                      0.00      0.00      0.00      0.00              1/1      Array#pack
                      0.00      0.00      0.00      0.00              3/7      String#bytesize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#set
  41.59%   0.55%      0.00      0.00      0.00      0.00                1      Dalli::Server#serialize
                      0.00      0.00      0.00      0.00              1/1      <Module::Marshal>#dump
                      0.00      0.00      0.00      0.00              1/1      Fixnum#|
                      0.00      0.00      0.00      0.00              1/7      String#bytesize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#serialize
  40.86%  13.89%      0.00      0.00      0.00      0.00                1      <Module::Marshal>#dump
                      0.00      0.00      0.00      0.00          283/289      Kernel#respond_to_missing?
                      0.00      0.00      0.00      0.00              7/7      Time#_dump
                      0.00      0.00      0.00      0.00              2/3      ActiveRecord::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TimeWithZone#marshal_dump
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TimeWithZone#respond_to?
                      0.00      0.00      0.00      0.00              1/1      Date#marshal_dump
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00            6/289      Kernel#respond_to?
                      0.00      0.00      0.00      0.00          283/289      <Module::Marshal>#dump
  11.86%  11.86%      0.00      0.00      0.00      0.00              289      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write
  10.09%   1.19%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#expanded_key
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Integration#cache_key
                      0.00      0.00      0.00      0.00              1/3      ActiveRecord::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00              1/7      String#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#instrument
   8.95%   0.58%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#log
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#debug
                      0.00      0.00      0.00      0.00              3/3      ActiveSupport::Cache::DalliStore#logger
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#method_missing
                      0.00      0.00      0.00      0.00              1/1      Hash#blank?
                      0.00      0.00      0.00      0.00              1/5      Symbol#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              7/7      <Module::Marshal>#dump
   8.44%   1.53%      0.00      0.00      0.00      0.00                7      Time#_dump
                      0.00      0.00      0.00      0.00              7/7      Time#_dump_without_zone
                      0.00      0.00      0.00      0.00              7/8      Kernel#dup
                      0.00      0.00      0.00      0.00              7/7      Kernel#instance_variable_set
                      0.00      0.00      0.00      0.00              7/7      Time#zone
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/3      ActiveSupport::Cache::DalliStore#expanded_key
                      0.00      0.00      0.00      0.00              2/3      <Module::Marshal>#dump
   8.14%   1.76%      0.00      0.00      0.00      0.00                3      ActiveRecord::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00              3/3      ActiveModel::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00              3/3      ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
                      0.00      0.00      0.00      0.00             3/12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
   7.79%   0.70%      0.00      0.00      0.00      0.00                2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.00      0.00      0.00      0.00              1/2      Array#each
                      0.00      0.00      0.00      0.00              2/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#pop_flag!
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#push_flag!
                      0.00      0.00      0.00      0.00              1/1      Float#-
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   7.18%   0.41%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      0.00      0.00      0.00      0.00              1/1      Array#map
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      0.00      0.00      0.00      0.00              1/1      Kernel#Array
                      0.00      0.00      0.00      0.00              1/1      Array#shift
                      0.00      0.00      0.00      0.00              1/1      Array#unshift
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#log
   6.80%   0.38%      0.00      0.00      0.00      0.00                1      ActiveSupport::TaggedLogging#debug
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#add
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#expanded_key
   6.65%   1.85%      0.00      0.00      0.00      0.00                1      ActiveRecord::Integration#cache_key
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Base#[]
                      0.00      0.00      0.00      0.00              1/1      Time#to_formatted_s
                      0.00      0.00      0.00      0.00              1/1      #<Module:0x00000005de4590>#__temp__
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Persistence#new_record?
                      0.00      0.00      0.00      0.00              1/1      ActiveModel::Naming#model_name
                      0.00      0.00      0.00      0.00              1/2      ActiveSupport::TimeWithZone#utc
                      0.00      0.00      0.00      0.00              1/1      Fixnum#to_s
                      0.00      0.00      0.00      0.00             1/12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#debug
   6.42%   0.40%      0.00      0.00      0.00      0.00                1      ActiveSupport::TaggedLogging#add
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::BufferedLogger#add
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#tags_text
                      0.00      0.00      0.00      0.00              1/1      NilClass#to_s
                      0.00      0.00      0.00      0.00              1/1      Kernel#block_given?
                      0.00      0.00      0.00      0.00              1/6      NilClass#nil?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#set
   6.30%   0.40%      0.00      0.00      0.00      0.00                1      Dalli::Server#generic_response
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#read
                      0.00      0.00      0.00      0.00              1/1      String#unpack
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              3/3      ActiveRecord::AttributeMethods#respond_to?
   5.85%   1.18%      0.00      0.00      0.00      0.00                3      ActiveModel::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods#match_attribute_method?
                      0.00      0.00      0.00      0.00              5/8      Kernel#respond_to?
                      0.00      0.00      0.00      0.00              2/5      Symbol#to_s
                      0.00      0.00      0.00      0.00              2/6      NilClass#nil?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#generic_response
   5.68%   0.26%      0.00      0.00      0.00      0.00                1      Dalli::Server#read
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server::KSocket#readfull
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#read
   5.42%   0.60%      0.00      0.00      0.00      0.00                1      Dalli::Server::KSocket#readfull
                      0.00      0.00      0.00      0.00              2/2      Kernel#loop
                      0.00      0.00      0.00      0.00              1/1      <Class::IO>#select
                      0.00      0.00      0.00      0.00              1/1      <Class::SystemCallError>#===
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   4.89%   0.21%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#add
   4.78%   0.19%      0.00      0.00      0.00      0.00                1      ActiveSupport::BufferedLogger#add
                      0.00      0.00      0.00      0.00              1/1      Logger#add
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::BufferedLogger#add
   4.59%   0.50%      0.00      0.00      0.00      0.00                1      Logger#add
                      0.00      0.00      0.00      0.00              1/1      Logger::LogDevice#write
                      0.00      0.00      0.00      0.00              1/4      <Class::Time>#now
                      0.00      0.00      0.00      0.00              1/1      Logger#format_message
                      0.00      0.00      0.00      0.00              1/1      Logger#format_severity
                      0.00      0.00      0.00      0.00              2/4      Kernel#nil?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Dalli::Server::KSocket#readfull
   4.23%   0.47%      0.00      0.00      0.00      0.00                2      Kernel#loop
                      0.00      0.00      0.00      0.00              2/2      IO#read_nonblock
                      0.00      0.00      0.00      0.00              3/7      String#bytesize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   3.98%   0.46%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.00      0.00      0.00      0.00              1/1      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::TransactionSampler#notice_push_scope
                      0.00      0.00      0.00      0.00              1/3      Class#new
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.00      0.00      0.00      0.00              1/2      Array#empty?
                      0.00      0.00      0.00      0.00              1/1      Array#push
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Kernel#loop
   3.61%   2.56%      0.00      0.00      0.00      0.00                2      IO#read_nonblock
                      0.00      0.00      0.00      0.00              1/1      SystemCallError#initialize
                      0.00      0.00      0.00      0.00              1/1      Exception#set_backtrace
                      0.00      0.00      0.00      0.00              1/1      Exception#backtrace
                      0.00      0.00      0.00      0.00              1/1      Exception#exception
                      0.00      0.00      0.00      0.00              1/4      <Class::BasicObject>#allocate
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              7/7      Time#_dump
   3.60%   2.29%      0.00      0.00      0.00      0.00                7      Time#_dump_without_zone
                      0.00      0.00      0.00      0.00            14/15      Fixnum#divmod
                      0.00      0.00      0.00      0.00            14/15      Fixnum#<=>
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   3.48%   0.19%      0.00      0.00      0.00      0.00                1      Array#map
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   3.43%   0.32%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Array#map
   3.29%   0.21%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.00      0.00      0.00      0.00              1/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   2.99%   0.16%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods#respond_to?
   2.88%   1.15%      0.00      0.00      0.00      0.00                2      ActiveModel::AttributeMethods#match_attribute_method?
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
                      0.00      0.00      0.00      0.00              2/2      ActiveRecord::AttributeMethods#attribute_method?
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher::AttributeMethodMatch#attr_name
                      0.00      0.00      0.00      0.00             2/12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
   2.83%   0.20%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.00      0.00      0.00      0.00              1/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Logger#add
   2.69%   0.21%      0.00      0.00      0.00      0.00                1      Logger::LogDevice#write
                      0.00      0.00      0.00      0.00              1/4      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/8      ActiveSupport::Cache::DalliStore#escape
                      0.00      0.00      0.00      0.00              7/8      Time#_dump
   2.54%   0.96%      0.00      0.00      0.00      0.00                8      Kernel#dup
                      0.00      0.00      0.00      0.00              8/8      Kernel#initialize_dup
                      0.00      0.00      0.00      0.00             7/11      <Class::Time>#allocate
                      0.00      0.00      0.00      0.00              1/1      <Class::String>#allocate
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      Dalli::Server#request
                      0.00      0.00      0.00      0.00              1/2      Dalli::Ring#server_for_key
   2.48%   0.30%      0.00      0.00      0.00      0.00                2      Dalli::Threadsafe#alive?
                      0.00      0.00      0.00      0.00              2/4      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
   2.45%   0.23%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.00      0.00      0.00      0.00              1/2      Hash#[]
                      0.00      0.00      0.00      0.00              1/3      Class#new
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
   2.42%   0.33%      0.00      0.00      0.00      0.00                2      Hash#[]
                      0.00      0.00      0.00      0.00              2/2      NewRelic::MetricSpec#eql?
                      0.00      0.00      0.00      0.00              2/2      NewRelic::MetricSpec#hash
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/8      ActiveSupport::TimeWithZone#respond_to?
                      0.00      0.00      0.00      0.00              1/8      Time#to_formatted_s
                      0.00      0.00      0.00      0.00              1/8      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.00      0.00      0.00      0.00              5/8      ActiveModel::AttributeMethods#respond_to?
   2.37%   1.88%      0.00      0.00      0.00      0.00                8      Kernel#respond_to?
                      0.00      0.00      0.00      0.00            6/289      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
   2.33%   0.34%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.00      0.00      0.00      0.00              1/2      Hash#[]
                      0.00      0.00      0.00      0.00              1/3      Class#new
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Integration#cache_key
   2.15%   0.29%      0.00      0.00      0.00      0.00                1      ActiveRecord::Base#[]
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::AttributeMethods::Read#read_attribute
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_synchronize
   2.06%   0.93%      0.00      0.00      0.00      0.00                4      MonitorMixin#mon_exit
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_check_owner
                      0.00      0.00      0.00      0.00              3/3      Mutex#unlock
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::Transactions#push_scope
   1.95%   0.44%      0.00      0.00      0.00      0.00                1      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.00      0.00      0.00      0.00              1/1      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.00      0.00      0.00      0.00              1/1      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Rubinius>#enabled?
                      0.00      0.00      0.00      0.00              1/1      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Ruby19>#enabled?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Client#perform
   1.87%   0.28%      0.00      0.00      0.00      0.00                1      Dalli::Ring#server_for_key
                      0.00      0.00      0.00      0.00              1/2      Dalli::Threadsafe#alive?
                      0.00      0.00      0.00      0.00              1/1      Array#first
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Base#[]
   1.86%   0.35%      0.00      0.00      0.00      0.00                1      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
                      0.00      0.00      0.00      0.00             1/12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/3      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.00      0.00      0.00      0.00              1/3      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.00      0.00      0.00      0.00              1/3      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
   1.63%   0.46%      0.00      0.00      0.00      0.00                3      Class#new
                      0.00      0.00      0.00      0.00              2/2      NewRelic::MetricSpec#initialize
                      0.00      0.00      0.00      0.00              3/4      <Class::BasicObject>#allocate
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::ScopeStackElement#initialize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_synchronize
   1.62%   0.98%      0.00      0.00      0.00      0.00                4      MonitorMixin#mon_enter
                      0.00      0.00      0.00      0.00             7/22      <Class::Thread>#current
                      0.00      0.00      0.00      0.00              3/3      Mutex#lock
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::Integration#cache_key
   1.58%   0.28%      0.00      0.00      0.00      0.00                1      Time#to_formatted_s
                      0.00      0.00      0.00      0.00              1/1      Time#strftime
                      0.00      0.00      0.00      0.00              1/8      Kernel#respond_to?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      0.00      0.00      0.00      0.00              2/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
                      0.00      0.00      0.00      0.00              1/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
   1.55%   0.56%      0.00      0.00      0.00      0.00                4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.00      0.00      0.00      0.00              4/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      MonitorMixin#mon_synchronize
                      0.00      0.00      0.00      0.00              1/2      Dalli::Server#write
   1.53%   1.53%      0.00      0.00      0.00      0.00                2      IO#write
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/4      Logger#add
                      0.00      0.00      0.00      0.00              3/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   1.50%   0.45%      0.00      0.00      0.00      0.00                4      <Class::Time>#now
                      0.00      0.00      0.00      0.00              4/4      Time#initialize
                      0.00      0.00      0.00      0.00             4/11      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.45%   0.57%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::TransactionSampler#notice_pop_scope
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.00      0.00      0.00      0.00              1/1      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#capture
                      0.00      0.00      0.00      0.00              1/1      Array#pop
                      0.00      0.00      0.00      0.00              1/2      Array#empty?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveRecord::AttributeMethods::Read#read_attribute
   1.43%   0.65%      0.00      0.00      0.00      0.00                1      ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
                      0.00      0.00      0.00      0.00              2/2      ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
                      0.00      0.00      0.00      0.00              1/1      Module#method_defined?
                      0.00      0.00      0.00      0.00              1/1      #<Module:0x000000078a6130>#__temp__
                      0.00      0.00      0.00      0.00              1/1      Hash#has_key?
                      0.00      0.00      0.00      0.00              1/5      Symbol#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             1/22      <Class::ActiveSupport::Cache::Store>#instrument
                      0.00      0.00      0.00      0.00             1/22      NewRelic::Agent#is_execution_traced?
                      0.00      0.00      0.00      0.00             1/22      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.00      0.00      0.00      0.00             1/22      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.00      0.00      0.00      0.00             2/22      Dalli::Server#multi?
                      0.00      0.00      0.00      0.00             1/22      ActiveSupport::TaggedLogging#current_tags
                      0.00      0.00      0.00      0.00             2/22      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.00      0.00      0.00      0.00             2/22      NewRelic::Agent::TransactionSampler#builder
                      0.00      0.00      0.00      0.00             4/22      MonitorMixin#mon_check_owner
                      0.00      0.00      0.00      0.00             7/22      MonitorMixin#mon_enter
   1.43%   1.43%      0.00      0.00      0.00      0.00               22      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#write_entry
   1.32%   0.36%      0.00      0.00      0.00      0.00                1      ActiveSupport::Cache::DalliStore#escape
                      0.00      0.00      0.00      0.00              1/8      Kernel#dup
                      0.00      0.00      0.00      0.00              1/1      String#gsub
                      0.00      0.00      0.00      0.00              1/1      String#encoding_aware?
                      0.00      0.00      0.00      0.00              1/1      String#force_encoding
                      0.00      0.00      0.00      0.00              1/7      String#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   1.09%   0.37%      0.00      0.00      0.00      0.00                2      Time#to_f
                      0.00      0.00      0.00      0.00              2/2      Numeric#quo
                      0.00      0.00      0.00      0.00              2/2      Rational#to_f
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#set
   1.07%   0.29%      0.00      0.00      0.00      0.00                1      Dalli::Server#write
                      0.00      0.00      0.00      0.00              1/2      IO#write
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              8/8      Kernel#dup
   1.06%   0.59%      0.00      0.00      0.00      0.00                8      Kernel#initialize_dup
                      0.00      0.00      0.00      0.00              7/7      Time#initialize_copy
                      0.00      0.00      0.00      0.00              1/1      String#initialize_copy
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Hash#[]
   1.05%   0.45%      0.00      0.00      0.00      0.00                2      NewRelic::MetricSpec#eql?
                      0.00      0.00      0.00      0.00             4/12      Kernel#class
                      0.00      0.00      0.00      0.00              4/7      String#to_s
                      0.00      0.00      0.00      0.00              2/2      String#eql?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Hash#[]
   1.04%   0.49%      0.00      0.00      0.00      0.00                2      NewRelic::MetricSpec#hash
                      0.00      0.00      0.00      0.00              4/4      String#hash
                      0.00      0.00      0.00      0.00              2/2      Fixnum#^
                      0.00      0.00      0.00      0.00              2/4      Kernel#nil?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
   0.99%   0.53%      0.00      0.00      0.00      0.00                4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
                      0.00      0.00      0.00      0.00              4/4      NewRelic::Agent#agent
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Time#to_formatted_s
   0.99%   0.47%      0.00      0.00      0.00      0.00                1      Time#strftime
                      0.00      0.00      0.00      0.00              2/2      Fixnum#*
                      0.00      0.00      0.00      0.00             1/15      Fixnum#divmod
                      0.00      0.00      0.00      0.00             1/15      Fixnum#<=>
                      0.00      0.00      0.00      0.00              1/1      Bignum#<=>
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods#match_attribute_method?
   0.98%   0.50%      0.00      0.00      0.00      0.00                2      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
                      0.00      0.00      0.00      0.00              4/4      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matchers_cache
                      0.00      0.00      0.00      0.00              2/2      Hash#key?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#add
   0.96%   0.27%      0.00      0.00      0.00      0.00                1      ActiveSupport::TaggedLogging#tags_text
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#current_tags
                      0.00      0.00      0.00      0.00              1/1      Enumerable#any?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      MonitorMixin#mon_exit
   0.87%   0.58%      0.00      0.00      0.00      0.00                4      MonitorMixin#mon_check_owner
                      0.00      0.00      0.00      0.00             4/22      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             1/15      Time#strftime
                      0.00      0.00      0.00      0.00            14/15      Time#_dump_without_zone
   0.81%   0.81%      0.00      0.00      0.00      0.00               15      Fixnum#divmod
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      Enumerable#any?
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   0.81%   0.29%      0.00      0.00      0.00      0.00                2      Array#each
                      0.00      0.00      0.00      0.00              2/2      NewRelic::MethodTraceStats#record_data_point
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.78%   0.21%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#traced?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             1/12      Dalli::Client#set_with_newrelic_trace
                      0.00      0.00      0.00      0.00             1/12      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.00      0.00      0.00      0.00             1/12      ActiveRecord::Integration#cache_key
                      0.00      0.00      0.00      0.00             2/12      ActiveModel::AttributeMethods#match_attribute_method?
                      0.00      0.00      0.00      0.00             3/12      ActiveRecord::AttributeMethods#respond_to?
                      0.00      0.00      0.00      0.00             4/12      NewRelic::MetricSpec#eql?
   0.78%   0.78%      0.00      0.00      0.00      0.00               12      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
   0.77%   0.32%      0.00      0.00      0.00      0.00                1      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.00      0.00      0.00      0.00              1/8      Kernel#respond_to?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             4/11      <Class::Time>#now
                      0.00      0.00      0.00      0.00             7/11      Kernel#dup
   0.77%   0.77%      0.00      0.00      0.00      0.00               11      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             1/10      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.00      0.00      0.00      0.00             1/10      NewRelic::Agent#is_execution_traced?
                      0.00      0.00      0.00      0.00             1/10      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.00      0.00      0.00      0.00             1/10      <Class::ActiveSupport::Cache::Store>#instrument
                      0.00      0.00      0.00      0.00             2/10      Dalli::Server#multi?
                      0.00      0.00      0.00      0.00             2/10      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.00      0.00      0.00      0.00             2/10      NewRelic::Agent::TransactionSampler#builder
   0.76%   0.76%      0.00      0.00      0.00      0.00               10      Thread#[]
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Class#new
   0.74%   0.42%      0.00      0.00      0.00      0.00                2      NewRelic::MetricSpec#initialize
                      0.00      0.00      0.00      0.00              4/4      String#[]
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00             1/15      Time#strftime
                      0.00      0.00      0.00      0.00            14/15      Time#_dump_without_zone
   0.72%   0.72%      0.00      0.00      0.00      0.00               15      Fixnum#<=>
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              3/3      ActiveSupport::Cache::DalliStore#log
   0.71%   0.44%      0.00      0.00      0.00      0.00                3      ActiveSupport::Cache::DalliStore#logger
                      0.00      0.00      0.00      0.00              3/3      <Module::Dalli>#logger
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      <Class::Time>#now
   0.70%   0.45%      0.00      0.00      0.00      0.00                4      Time#initialize
                      0.00      0.00      0.00      0.00              4/4      Fixnum#+
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              7/7      Time#_dump
   0.69%   0.69%      0.00      0.00      0.00      0.00                7      Kernel#instance_variable_set
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::Cache::DalliStore#log
   0.67%   0.23%      0.00      0.00      0.00      0.00                1      ActiveSupport::TaggedLogging#method_missing
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::BufferedLogger#debug?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::StatsEngine::Transactions#push_scope
   0.66%   0.30%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::TransactionSampler#notice_push_scope
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::TransactionSampler#builder
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::TransactionSampler#notice_pop_scope
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::TransactionSampler#notice_push_scope
   0.62%   0.31%      0.00      0.00      0.00      0.00                2      NewRelic::Agent::TransactionSampler#builder
                      0.00      0.00      0.00      0.00             2/10      Thread#[]
                      0.00      0.00      0.00      0.00             2/22      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      IO#read_nonblock
   0.60%   0.41%      0.00      0.00      0.00      0.00                1      SystemCallError#initialize
                      0.00      0.00      0.00      0.00              1/1      Exception#initialize
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      <Module::Marshal>#dump
   0.60%   0.36%      0.00      0.00      0.00      0.00                1      ActiveSupport::TimeWithZone#marshal_dump
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TimeWithZone#time
                      0.00      0.00      0.00      0.00              1/2      ActiveSupport::TimeWithZone#utc
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.59%   0.32%      0.00      0.00      0.00      0.00                2      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
                      0.00      0.00      0.00      0.00              2/2      Hash#[]=
                      0.00      0.00      0.00      0.00              2/6      NilClass#nil?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
   0.56%   0.16%      0.00      0.00      0.00      0.00                1      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#traced?
                      0.00      0.00      0.00      0.00              1/1      NewRelic::Agent#is_execution_traced?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              7/7      Time#_dump
   0.56%   0.56%      0.00      0.00      0.00      0.00                7      Time#zone
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::Transactions#push_scope
   0.55%   0.29%      0.00      0.00      0.00      0.00                2      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.00      0.00      0.00      0.00             2/10      Thread#[]
                      0.00      0.00      0.00      0.00             2/22      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Logger#add
   0.54%   0.20%      0.00      0.00      0.00      0.00                1      Logger#format_message
                      0.00      0.00      0.00      0.00              1/1      Logger::SimpleFormatter#call
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Dalli::Server#set
   0.53%   0.30%      0.00      0.00      0.00      0.00                2      Dalli::Server#multi?
                      0.00      0.00      0.00      0.00             2/10      Thread#[]
                      0.00      0.00      0.00      0.00             2/22      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      Array#each
   0.52%   0.52%      0.00      0.00      0.00      0.00                2      NewRelic::MethodTraceStats#record_data_point
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              2/2      ActiveModel::AttributeMethods#match_attribute_method?
   0.50%   0.33%      0.00      0.00      0.00      0.00                2      ActiveRecord::AttributeMethods#attribute_method?
                      0.00      0.00      0.00      0.00              2/2      Hash#include?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server::KSocket#readfull
   0.47%   0.47%      0.00      0.00      0.00      0.00                1      <Class::IO>#select
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              4/4      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
   0.46%   0.46%      0.00      0.00      0.00      0.00                4      NewRelic::Agent#agent
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/5      ActiveSupport::TimeWithZone#respond_to?
                      0.00      0.00      0.00      0.00              1/5      ActiveSupport::Cache::DalliStore#log
                      0.00      0.00      0.00      0.00              1/5      ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
                      0.00      0.00      0.00      0.00              2/5      ActiveModel::AttributeMethods#respond_to?
   0.46%   0.46%      0.00      0.00      0.00      0.00                5      Symbol#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#tags_text
   0.46%   0.24%      0.00      0.00      0.00      0.00                1      ActiveSupport::TaggedLogging#current_tags
                      0.00      0.00      0.00      0.00             1/22      <Class::Thread>#current
                      0.00      0.00      0.00      0.00              1/1      Kernel#hash
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/7      ActiveSupport::Cache::DalliStore#escape
                      0.00      0.00      0.00      0.00              1/7      Dalli::Client#perform
                      0.00      0.00      0.00      0.00              1/7      ActiveSupport::Cache::DalliStore#expanded_key
                      0.00      0.00      0.00      0.00              4/7      NewRelic::MetricSpec#eql?
   0.45%   0.45%      0.00      0.00      0.00      0.00                7      String#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
   0.44%   0.26%      0.00      0.00      0.00      0.00                1      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Rubinius>#enabled?
                      0.00      0.00      0.00      0.00              1/1      NewRelic::LanguageSupport#using_engine?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TaggedLogging#method_missing
   0.43%   0.24%      0.00      0.00      0.00      0.00                1      ActiveSupport::BufferedLogger#debug?
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::BufferedLogger#level
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/1      <Module::Marshal>#dump
   0.42%   0.24%      0.00      0.00      0.00      0.00                1      ActiveSupport::TimeWithZone#respond_to?
                      0.00      0.00      0.00      0.00              1/8      Kernel#respond_to?
                      0.00      0.00      0.00      0.00              1/5      Symbol#to_s
------------------------------------------------------------------------------
Mike Perham
Owner

You'll need to profile a lot more calls to get an statistically accurate profile with timings that help me:

profile do
   10_000.times do
      dalli.write('xyz', 123)
   end
end
Avi Tzurel

NP

Will have that profile A.S.A.P

Avi Tzurel

There you go
Profiling 10K times writing a user object into cache


system :008 > result = RubyProf.profile do
system :009 >     10000.times do
system :010 >       Rails.cache.write(user, user)
system :011?>     end
system :012?>   end
 => #<RubyProf::Profile:0x00000008020230> 
system :013 > printer = RubyProf::GraphPrinter.new(result)
 => #<RubyProf::GraphPrinter:0x00000009a8f878 @result=#<RubyProf::Profile:0x00000008020230>, @output=nil> 
system :014 > printer.print(STDOUT, {})
Thread ID: 3319920
Total Time: 42.401282603000006
Sort by: total_time

  %total   %self     total      self      wait     child            calls    Name
--------------------------------------------------------------------------------
 100.00%   0.00%     42.40      0.00      0.00     42.40                1      Object#irb_binding
                     42.40      0.03      0.00     42.37              1/1      Integer#times
--------------------------------------------------------------------------------
                     42.40      0.03      0.00     42.37              1/1      Object#irb_binding
 100.00%   0.08%     42.40      0.03      0.00     42.37                1      Integer#times
                     42.34      0.13      0.00     42.21      10000/10000      ActiveSupport::Cache::DalliStore#write
                      0.03      0.03      0.00      0.00      10000/10000      <Module::Rails>#cache
--------------------------------------------------------------------------------
                     42.34      0.13      0.00     42.21      10000/10000      Integer#times
  99.86%   0.30%     42.34      0.13      0.00     42.21            10000      ActiveSupport::Cache::DalliStore#write
                     40.19      0.09      0.00     40.11      10000/10000      ActiveSupport::Cache::DalliStore#instrument
                      2.02      0.06      0.00      1.96      10000/10000      ActiveSupport::Cache::DalliStore#expanded_key
--------------------------------------------------------------------------------
                     40.19      0.09      0.00     40.11      10000/10000      ActiveSupport::Cache::DalliStore#write
  94.80%   0.20%     40.19      0.09      0.00     40.11            10000      ActiveSupport::Cache::DalliStore#instrument
                     37.40      0.07      0.00     37.32      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
                      2.57      0.18      0.00      2.39      10000/10000      ActiveSupport::Cache::DalliStore#log
                      0.14      0.10      0.00      0.04      10000/10000      <Class::ActiveSupport::Cache::Store>#instrument
--------------------------------------------------------------------------------
                     37.40      0.07      0.00     37.32      10000/10000      ActiveSupport::Cache::DalliStore#instrument
  88.19%   0.17%     37.40      0.07      0.00     37.32            10000      ActiveSupport::Cache::DalliStore#write_entry
                     36.89      0.14      0.00     36.75      10000/10000      Dalli::Client#set_with_newrelic_trace
                      0.43      0.10      0.00      0.33      10000/10000      ActiveSupport::Cache::DalliStore#escape
--------------------------------------------------------------------------------
                     36.89      0.14      0.00     36.75      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
  87.00%   0.33%     36.89      0.14      0.00     36.75            10000      Dalli::Client#set_with_newrelic_trace
                     36.64      0.36      0.00     36.29      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                      0.09      0.05      0.00      0.04      10000/10000      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/119996      Kernel#class
--------------------------------------------------------------------------------
                     36.64      0.36      0.00     36.29      10000/10000      Dalli::Client#set_with_newrelic_trace
  86.42%   0.84%     36.64      0.36      0.00     36.29            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                     29.67      0.17      0.00     29.50      10000/10000      Dalli::Client#set
                      2.75      0.29      0.00      2.46      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      1.44      0.04      0.00      1.40      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      1.19      0.05      0.00      1.14      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      0.52      0.23      0.00      0.28      30000/40000      <Class::Time>#now
                      0.29      0.10      0.00      0.19      20000/20000      Time#to_f
                      0.24      0.10      0.00      0.14      20000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
                      0.18      0.04      0.00      0.14      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
--------------------------------------------------------------------------------
                     29.67      0.17      0.00     29.50      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
  69.96%   0.40%     29.67      0.17      0.00     29.50            10000      Dalli::Client#set
                     29.48      0.11      0.00     29.37      10000/10000      Dalli::Client#perform
                      0.02      0.02      0.00      0.00      10000/10000      NilClass#to_i
--------------------------------------------------------------------------------
                      0.54      0.09      0.00      0.45      20000/40000      Dalli::Threadsafe#alive?
                      0.65      0.17      0.00      0.48      10000/40000      Logger::LogDevice#write
                     28.41      0.16      0.00     28.26      10000/40000      Dalli::Threadsafe#request
  69.81%   0.99%     29.60      0.42      0.00     29.18            40000     *MonitorMixin#mon_synchronize
                     27.84      0.08      0.00     27.76      10000/10000      Dalli::Server#request
                      0.77      0.44      0.00      0.33      40000/40000      MonitorMixin#mon_exit
                      0.60      0.42      0.00      0.18      40000/40000      MonitorMixin#mon_enter
                      0.11      0.11      0.00      0.00      10000/20000      IO#write
                      0.05      0.05      0.00      0.00      20000/20000      Dalli::Server#alive?
--------------------------------------------------------------------------------
                     29.48      0.11      0.00     29.37      10000/10000      Dalli::Client#set
  69.52%   0.27%     29.48      0.11      0.00     29.37            10000      Dalli::Client#perform
                     28.45      0.03      0.00     28.41      10000/10000      Dalli::Threadsafe#request
                      0.65      0.06      0.00      0.59      10000/10000      Dalli::Ring#server_for_key
                      0.14      0.14      0.00      0.00      10000/70005      String#to_s
                      0.10      0.06      0.00      0.04      10000/10000      Dalli::Client#validate_key
                      0.03      0.03      0.00      0.00      10000/10000      Dalli::Client#ring
--------------------------------------------------------------------------------
                     28.45      0.03      0.00     28.41      10000/10000      Dalli::Client#perform
  67.09%   0.08%     28.45      0.03      0.00     28.41            10000      Dalli::Threadsafe#request
                     28.41      0.16      0.00     28.26      10000/40000      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                     27.84      0.08      0.00     27.76      10000/10000      MonitorMixin#mon_synchronize
  65.66%   0.20%     27.84      0.08      0.00     27.76            10000      Dalli::Server#request
                     27.38      0.22      0.00     27.16      10000/10000      Dalli::Server#set
                      0.31      0.03      0.00      0.28      10000/20000      Dalli::Threadsafe#alive?
                      0.06      0.05      0.00      0.02      10000/10000      Dalli::Server#verify_state
--------------------------------------------------------------------------------
                     27.38      0.22      0.00     27.16      10000/10000      Dalli::Server#request
  64.58%   0.52%     27.38      0.22      0.00     27.16            10000      Dalli::Server#set
                     22.18      0.16      0.00     22.01      10000/10000      Dalli::Server#serialize
                      4.06      0.12      0.00      3.94      10000/10000      Dalli::Server#generic_response
                      0.60      0.08      0.00      0.52      10000/10000      Dalli::Server#write
                      0.17      0.09      0.00      0.08      20000/20000      Dalli::Server#multi?
                      0.11      0.11      0.00      0.00      10000/10000      Array#pack
                      0.05      0.05      0.00      0.00      30000/67614      String#bytesize
--------------------------------------------------------------------------------
                     22.18      0.16      0.00     22.01      10000/10000      Dalli::Server#set
  52.31%   0.39%     22.18      0.16      0.00     22.01            10000      Dalli::Server#serialize
                     21.98      9.64      0.00     12.34      10000/10000      <Module::Marshal>#dump
                      0.02      0.02      0.00      0.00      10000/67614      String#bytesize
                      0.02      0.02      0.00      0.00      10000/10000      Fixnum#|
--------------------------------------------------------------------------------
                     21.98      9.64      0.00     12.34      10000/10000      Dalli::Server#serialize
  51.83%  22.74%     21.98      9.64      0.00     12.34            10000      <Module::Marshal>#dump
                      6.01      6.01      0.00      0.00  2830000/2890001      Kernel#respond_to_missing?
                      4.33      0.88      0.00      3.45      70000/70000      Time#_dump
                      1.70      0.18      0.00      1.52      20000/30000      ActiveRecord::AttributeMethods#respond_to?
                      0.16      0.12      0.00      0.04      10000/10000      ActiveSupport::TimeWithZone#respond_to?
                      0.11      0.05      0.00      0.06      10000/10000      ActiveSupport::TimeWithZone#marshal_dump
                      0.02      0.02      0.00      0.00      10000/10000      Date#marshal_dump
--------------------------------------------------------------------------------
                      0.17      0.17      0.00      0.00    60001/2890001      Kernel#respond_to?
                      6.01      6.01      0.00      0.00  2830000/2890001      <Module::Marshal>#dump
  14.57%  14.57%      6.18      6.18      0.00      0.00          2890001      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      4.33      0.88      0.00      3.45      70000/70000      <Module::Marshal>#dump
  10.22%   2.08%      4.33      0.88      0.00      3.45            70000      Time#_dump
                      1.76      0.98      0.00      0.78      70000/70000      Time#_dump_without_zone
                      0.90      0.32      0.00      0.58      70000/80009      Kernel#dup
                      0.45      0.45      0.00      0.00      70000/70000      Kernel#instance_variable_set
                      0.34      0.34      0.00      0.00      70000/70001      Time#zone
--------------------------------------------------------------------------------
                      4.06      0.12      0.00      3.94      10000/10000      Dalli::Server#set
   9.57%   0.29%      4.06      0.12      0.00      3.94            10000      Dalli::Server#generic_response
                      3.90      0.19      0.00      3.71      10000/10000      Dalli::Server#read
                      0.03      0.03      0.00      0.00      10000/10000      String#unpack
--------------------------------------------------------------------------------
                      3.90      0.19      0.00      3.71      10000/10000      Dalli::Server#generic_response
   9.20%   0.45%      3.90      0.19      0.00      3.71            10000      Dalli::Server#read
                      3.71      0.12      0.00      3.59      10000/10000      Dalli::Server::KSocket#readfull
--------------------------------------------------------------------------------
                      3.71      0.12      0.00      3.59      10000/10000      Dalli::Server#read
   8.75%   0.29%      3.71      0.12      0.00      3.59            10000      Dalli::Server::KSocket#readfull
                      3.49      0.29      0.00      3.20      17614/17614      Kernel#loop
                      0.08      0.08      0.00      0.00        7614/7614      <Class::IO>#select
                      0.02      0.02      0.00      0.00        7614/7614      <Class::SystemCallError>#===
--------------------------------------------------------------------------------
                      3.49      0.29      0.00      3.20      17614/17614      Dalli::Server::KSocket#readfull
   8.24%   0.69%      3.49      0.29      0.00      3.20            17614      Kernel#loop
                      3.15      3.00      0.00      0.15      17614/17614      IO#read_nonblock
                      0.05      0.05      0.00      0.00      27614/67614      String#bytesize
--------------------------------------------------------------------------------
                      3.15      3.00      0.00      0.15      17614/17614      Kernel#loop
   7.43%   7.07%      3.15      3.00      0.00      0.15            17614      IO#read_nonblock
                      0.09      0.06      0.00      0.03        7614/7614      SystemCallError#initialize
                      0.02      0.02      0.00      0.00        7614/7614      Exception#set_backtrace
                      0.02      0.02      0.00      0.00       7614/37619      <Class::BasicObject>#allocate
                      0.01      0.01      0.00      0.00        7614/7614      Exception#backtrace
                      0.01      0.01      0.00      0.00        7614/7614      Exception#exception
--------------------------------------------------------------------------------
                      2.75      0.29      0.00      2.46      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   6.49%   0.68%      2.75      0.29      0.00      2.46            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      1.32      0.04      0.00      1.28      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      1.09      0.10      0.00      0.99      10000/10000      Array#map
                      0.02      0.02      0.00      0.00      10000/10000      Array#shift
                      0.02      0.02      0.00      0.00      10000/10000      Array#unshift
                      0.02      0.02      0.00      0.00      10000/10000      Kernel#Array
--------------------------------------------------------------------------------
                      2.57      0.18      0.00      2.39      10000/10000      ActiveSupport::Cache::DalliStore#instrument
   6.07%   0.43%      2.57      0.18      0.00      2.39            10000      ActiveSupport::Cache::DalliStore#log
                      2.01      0.10      0.00      1.91      10000/10000      ActiveSupport::TaggedLogging#debug
                      0.24      0.10      0.00      0.14      30000/30000      ActiveSupport::Cache::DalliStore#logger
                      0.10      0.04      0.00      0.06      10000/10000      ActiveSupport::TaggedLogging#method_missing
                      0.02      0.02      0.00      0.00      10000/50001      Symbol#to_s
                      0.02      0.02      0.00      0.00      10000/10000      Hash#blank?
--------------------------------------------------------------------------------
                      1.14      0.08      0.00      1.06      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      1.40      0.25      0.00      1.15      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
   5.99%   0.78%      2.54      0.33      0.00      2.21            20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
                      0.88      0.19      0.00      0.69      10000/10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.63      0.19      0.00      0.44      10000/10000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.37      0.06      0.00      0.31      10000/20012      Array#each
                      0.26      0.07      0.00      0.18      20000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.03      0.03      0.00      0.00      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#pop_flag!
                      0.03      0.03      0.00      0.00      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#push_flag!
                      0.02      0.02      0.00      0.00      10000/10000      Float#-
--------------------------------------------------------------------------------
                      2.02      0.06      0.00      1.96      10000/10000      ActiveSupport::Cache::DalliStore#write
   4.76%   0.13%      2.02      0.06      0.00      1.96            10000      ActiveSupport::Cache::DalliStore#expanded_key
                      1.65      0.21      0.00      1.44      10000/10000      ActiveRecord::Integration#cache_key
                      0.29      0.10      0.00      0.19      10000/30000      ActiveRecord::AttributeMethods#respond_to?
                      0.02      0.02      0.00      0.00      10000/70005      String#to_s
--------------------------------------------------------------------------------
                      2.01      0.10      0.00      1.91      10000/10000      ActiveSupport::Cache::DalliStore#log
   4.74%   0.23%      2.01      0.10      0.00      1.91            10000      ActiveSupport::TaggedLogging#debug
                      1.91      0.16      0.00      1.75      10000/10000      ActiveSupport::TaggedLogging#add
--------------------------------------------------------------------------------
                      0.29      0.10      0.00      0.19      10000/30000      ActiveSupport::Cache::DalliStore#expanded_key
                      1.70      0.18      0.00      1.52      20000/30000      <Module::Marshal>#dump
   4.70%   0.66%      1.99      0.28      0.00      1.71            30000      ActiveRecord::AttributeMethods#respond_to?
                      1.51      0.44      0.00      1.08      30000/30000      ActiveModel::AttributeMethods#respond_to?
                      0.15      0.15      0.00      0.00      30000/30000      ActiveRecord::AttributeMethods::ClassMethods#attribute_methods_generated?
                      0.05      0.05      0.00      0.00     30000/119996      Kernel#class
--------------------------------------------------------------------------------
                      1.91      0.16      0.00      1.75      10000/10000      ActiveSupport::TaggedLogging#debug
   4.51%   0.38%      1.91      0.16      0.00      1.75            10000      ActiveSupport::TaggedLogging#add
                      1.39      0.04      0.00      1.35      10000/10000      ActiveSupport::BufferedLogger#add
                      0.31      0.05      0.00      0.25      10000/10000      ActiveSupport::TaggedLogging#tags_text
                      0.02      0.02      0.00      0.00      10000/10000      NilClass#to_s
                      0.02      0.02      0.00      0.00      10000/60000      NilClass#nil?
                      0.02      0.02      0.00      0.00      10000/10014      Kernel#block_given?
--------------------------------------------------------------------------------
                      1.76      0.98      0.00      0.78      70000/70000      Time#_dump
   4.15%   2.31%      1.76      0.98      0.00      0.78            70000      Time#_dump_without_zone
                      0.48      0.48      0.00      0.00    140000/150000      Fixnum#divmod
                      0.30      0.30      0.00      0.00    140000/150000      Fixnum#<=>
--------------------------------------------------------------------------------
                      1.65      0.21      0.00      1.44      10000/10000      ActiveSupport::Cache::DalliStore#expanded_key
   3.90%   0.50%      1.65      0.21      0.00      1.44            10000      ActiveRecord::Integration#cache_key
                      0.62      0.13      0.00      0.49      10000/10000      Time#to_formatted_s
                      0.49      0.04      0.00      0.46      10000/10000      ActiveRecord::Base#[]
                      0.09      0.09      0.00      0.00      10000/10000      ActiveModel::Naming#model_name
                      0.09      0.07      0.00      0.02      10000/10000      #<Module:0x00000005cfaaf8>#__temp__
                      0.08      0.08      0.00      0.00     10000/119996      Kernel#class
                      0.03      0.03      0.00      0.00      10000/20000      ActiveSupport::TimeWithZone#utc
                      0.03      0.03      0.00      0.00      10000/10000      ActiveRecord::Persistence#new_record?
                      0.02      0.02      0.00      0.00      10000/10000      Fixnum#to_s
--------------------------------------------------------------------------------
                      1.51      0.44      0.00      1.08      30000/30000      ActiveRecord::AttributeMethods#respond_to?
   3.57%   1.03%      1.51      0.44      0.00      1.08            30000      ActiveModel::AttributeMethods#respond_to?
                      0.72      0.24      0.00      0.48      20000/20000      ActiveModel::AttributeMethods#match_attribute_method?
                      0.27      0.20      0.00      0.07      50000/80002      Kernel#respond_to?
                      0.04      0.04      0.00      0.00      20000/50001      Symbol#to_s
                      0.04      0.04      0.00      0.00      20000/60000      NilClass#nil?
--------------------------------------------------------------------------------
                      1.44      0.04      0.00      1.40      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   3.39%   0.09%      1.44      0.04      0.00      1.40            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      1.40      0.25      0.00      1.15      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      1.39      0.04      0.00      1.35      10000/10000      ActiveSupport::TaggedLogging#add
   3.28%   0.09%      1.39      0.04      0.00      1.35            10000      ActiveSupport::BufferedLogger#add
                      1.35      0.13      0.00      1.23      10000/10000      Logger#add
--------------------------------------------------------------------------------
                      1.35      0.13      0.00      1.23      10000/10000      ActiveSupport::BufferedLogger#add
   3.19%   0.30%      1.35      0.13      0.00      1.23            10000      Logger#add
                      0.69      0.04      0.00      0.65      10000/10000      Logger::LogDevice#write
                      0.24      0.10      0.00      0.13      10000/10000      Logger#format_message
                      0.17      0.04      0.00      0.14      10000/40000      <Class::Time>#now
                      0.09      0.09      0.00      0.00      10000/10000      Logger#format_severity
                      0.04      0.04      0.00      0.00      20000/40003      Kernel#nil?
--------------------------------------------------------------------------------
                      1.32      0.04      0.00      1.28      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   3.11%   0.08%      1.32      0.04      0.00      1.28            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      1.28      0.05      0.00      1.24      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
--------------------------------------------------------------------------------
                      1.28      0.05      0.00      1.24      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
   3.02%   0.11%      1.28      0.05      0.00      1.24            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      1.08      0.10      0.00      0.98      10000/10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.16      0.04      0.00      0.12      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      0.59      0.10      0.00      0.49      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.65      0.04      0.00      0.61      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
   2.92%   0.34%      1.24      0.14      0.00      1.10            20000      Hash#[]
                      0.72      0.46      0.00      0.26      20000/20002      NewRelic::MetricSpec#hash
                      0.38      0.15      0.00      0.23      19998/19998      NewRelic::MetricSpec#eql?
--------------------------------------------------------------------------------
                      1.19      0.05      0.00      1.14      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   2.81%   0.12%      1.19      0.05      0.00      1.14            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      1.14      0.08      0.00      1.06      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/80009      ActiveModel::Name#initialize
                      0.00      0.00      0.00      0.00          1/80009      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          3/80009      ActiveSupport::Inflector#apply_inflections
                      0.00      0.00      0.00      0.00          4/80009      ActiveSupport::Inflector#underscore
                      0.23      0.10      0.00      0.13      10000/80009      ActiveSupport::Cache::DalliStore#escape
                      0.90      0.32      0.00      0.58      70000/80009      Time#_dump
   2.66%   1.00%      1.13      0.42      0.00      0.70            80009      Kernel#dup
                      0.42      0.21      0.00      0.21      80009/80009      Kernel#initialize_dup
                      0.21      0.21      0.00      0.00     70000/110000      <Class::Time>#allocate
                      0.08      0.08      0.00      0.00      10009/10010      <Class::String>#allocate
--------------------------------------------------------------------------------
                      1.09      0.10      0.00      0.99      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   2.57%   0.24%      1.09      0.10      0.00      0.99            10000      Array#map
                      0.99      0.04      0.00      0.94      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
--------------------------------------------------------------------------------
                      1.08      0.10      0.00      0.98      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
   2.55%   0.24%      1.08      0.10      0.00      0.98            10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.65      0.04      0.00      0.61      10000/20000      Hash#[]
                      0.17      0.04      0.00      0.12      10001/30006      Class#new
                      0.14      0.10      0.00      0.04      10000/10000      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.03      0.03      0.00      0.00      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats::SynchronizedHash#[]=
--------------------------------------------------------------------------------
                      0.99      0.04      0.00      0.94      10000/10000      Array#map
   2.32%   0.10%      0.99      0.04      0.00      0.94            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.84      0.06      0.00      0.79      10000/10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.10      0.04      0.00      0.06      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      0.31      0.03      0.00      0.28      10000/20000      Dalli::Server#request
                      0.57      0.03      0.00      0.54      10000/20000      Dalli::Ring#server_for_key
   2.09%   0.16%      0.88      0.07      0.00      0.82            20000      Dalli::Threadsafe#alive?
                      0.54      0.09      0.00      0.45      20000/40000      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      0.88      0.19      0.00      0.69      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   2.08%   0.44%      0.88      0.19      0.00      0.69            10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.30      0.07      0.00      0.23      10000/10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.16      0.10      0.00      0.06      10000/30006      Class#new
                      0.11      0.04      0.00      0.08      10000/10000      NewRelic::Agent::TransactionSampler#notice_push_scope
                      0.08      0.04      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.02      0.02      0.00      0.00      10000/10000      Array#push
                      0.02      0.02      0.00      0.00      10000/20001      Array#empty?
--------------------------------------------------------------------------------
                      0.84      0.06      0.00      0.79      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
   1.99%   0.13%      0.84      0.06      0.00      0.79            10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.59      0.10      0.00      0.49      10000/20000      Hash#[]
                      0.17      0.04      0.00      0.13      10001/30006      Class#new
                      0.03      0.03      0.00      0.00      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats::SynchronizedHash#[]=
--------------------------------------------------------------------------------
                      0.77      0.44      0.00      0.33      40000/40000      MonitorMixin#mon_synchronize
   1.82%   1.04%      0.77      0.44      0.00      0.33            40000      MonitorMixin#mon_exit
                      0.27      0.14      0.00      0.13      40000/40000      MonitorMixin#mon_check_owner
                      0.06      0.06      0.00      0.00      30000/30002      Mutex#unlock
--------------------------------------------------------------------------------
                      0.72      0.24      0.00      0.48      20000/20000      ActiveModel::AttributeMethods#respond_to?
   1.71%   0.57%      0.72      0.24      0.00      0.48            20000      ActiveModel::AttributeMethods#match_attribute_method?
                      0.27      0.12      0.00      0.15      20000/20002      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
                      0.14      0.10      0.00      0.04      20000/20000      ActiveRecord::AttributeMethods#attribute_method?
                      0.04      0.04      0.00      0.00      20000/20000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher::AttributeMethodMatch#attr_name
                      0.04      0.04      0.00      0.00     20000/119996      Kernel#class
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          2/20002      Hash#[]=
                      0.72      0.46      0.00      0.26      20000/20002      Hash#[]
   1.70%   1.08%      0.72      0.46      0.00      0.26            20002      NewRelic::MetricSpec#hash
                      0.19      0.19      0.00      0.00      40004/40004      String#hash
                      0.03      0.03      0.00      0.00      20002/20002      Fixnum#^
                      0.03      0.03      0.00      0.00      20002/40003      Kernel#nil?
--------------------------------------------------------------------------------
                      0.69      0.04      0.00      0.65      10000/10000      Logger#add
   1.64%   0.10%      0.69      0.04      0.00      0.65            10000      Logger::LogDevice#write
                      0.65      0.17      0.00      0.48      10000/40000      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      0.17      0.04      0.00      0.14      10000/40000      Logger#add
                      0.52      0.23      0.00      0.28      30000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   1.63%   0.64%      0.69      0.27      0.00      0.42            40000      <Class::Time>#now
                      0.27      0.20      0.00      0.07      40000/40000      Time#initialize
                      0.15      0.15      0.00      0.00     40000/110000      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.65      0.06      0.00      0.59      10000/10000      Dalli::Client#perform
   1.54%   0.14%      0.65      0.06      0.00      0.59            10000      Dalli::Ring#server_for_key
                      0.57      0.03      0.00      0.54      10000/20000      Dalli::Threadsafe#alive?
                      0.02      0.02      0.00      0.00      10000/10000      Array#first
--------------------------------------------------------------------------------
                      0.63      0.19      0.00      0.44      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.50%   0.45%      0.63      0.19      0.00      0.44            10000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.17      0.09      0.00      0.08      10000/10000      NewRelic::Agent::TransactionSampler#notice_pop_scope
                      0.14      0.10      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.08      0.08      0.00      0.00      10000/10000      Array#pop
                      0.03      0.03      0.00      0.00      10000/10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#capture
                      0.02      0.02      0.00      0.00      10000/20001      Array#empty?
--------------------------------------------------------------------------------
                      0.11      0.11      0.00      0.00      10000/20000      MonitorMixin#mon_synchronize
                      0.52      0.40      0.12      0.00      10000/20000      Dalli::Server#write
   1.49%   1.21%      0.63      0.51      0.12      0.00            20000      IO#write
--------------------------------------------------------------------------------
                      0.62      0.13      0.00      0.49      10000/10000      ActiveRecord::Integration#cache_key
   1.46%   0.30%      0.62      0.13      0.00      0.49            10000      Time#to_formatted_s
                      0.38      0.22      0.00      0.16      10000/10000      Time#strftime
                      0.11      0.03      0.00      0.08      10000/80002      Kernel#respond_to?
--------------------------------------------------------------------------------
                      0.60      0.42      0.00      0.18      40000/40000      MonitorMixin#mon_synchronize
   1.41%   0.99%      0.60      0.42      0.00      0.18            40000      MonitorMixin#mon_enter
                      0.12      0.12      0.00      0.00     70000/220001      <Class::Thread>#current
                      0.06      0.06      0.00      0.00      30000/30002      Mutex#lock
--------------------------------------------------------------------------------
                      0.60      0.08      0.00      0.52      10000/10000      Dalli::Server#set
   1.41%   0.18%      0.60      0.08      0.00      0.52            10000      Dalli::Server#write
                      0.52      0.40      0.12      0.00      10000/20000      IO#write
--------------------------------------------------------------------------------
                      0.10      0.04      0.00      0.06      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.16      0.04      0.00      0.12      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      0.26      0.07      0.00      0.18      20000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.21%   0.35%      0.51      0.15      0.00      0.36            40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.36      0.20      0.00      0.17      40000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/30006      Time#in_time_zone
                      0.00      0.00      0.00      0.00          1/30006      TZInfo::DataTimezoneInfo#period_for_utc
                      0.00      0.00      0.00      0.00          1/30006      <Class::TZInfo::TimeOrDateTime>#wrap
                      0.00      0.00      0.00      0.00          1/30006      ActiveModel::Naming#model_name
                      0.16      0.10      0.00      0.06      10000/30006      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.17      0.04      0.00      0.13      10001/30006      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.17      0.04      0.00      0.12      10001/30006      NewRelic::Agent::StatsEngine::MetricStats#get_stats
   1.18%   0.43%      0.50      0.18      0.00      0.32            30006      Class#new
                      0.21      0.13      0.00      0.08      20000/20000      NewRelic::MetricSpec#initialize
                      0.06      0.06      0.00      0.00      30005/37619      <Class::BasicObject>#allocate
                      0.04      0.04      0.00      0.00      10000/10000      NewRelic::Agent::StatsEngine::ScopeStackElement#initialize
                      0.00      0.00      0.00      0.00              1/1      ActiveModel::Name#initialize
                      0.00      0.00      0.00      0.00              2/2      NewRelic::StatsBase#initialize
                      0.00      0.00      0.00      0.00              1/1      TZInfo::TimeOrDateTime#initialize
                      0.00      0.00      0.00      0.00              1/1      TZInfo::TimezonePeriod#initialize
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TimeWithZone#initialize
                      0.00      0.00      0.00      0.00          1/10010      <Class::String>#allocate
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00     10000/150000      Time#strftime
                      0.48      0.48      0.00      0.00    140000/150000      Time#_dump_without_zone
   1.17%   1.17%      0.50      0.50      0.00      0.00           150000      Fixnum#divmod
--------------------------------------------------------------------------------
                      0.49      0.04      0.00      0.46      10000/10000      ActiveRecord::Integration#cache_key
   1.17%   0.08%      0.49      0.04      0.00      0.46            10000      ActiveRecord::Base#[]
                      0.46      0.10      0.00      0.35      10000/10000      ActiveRecord::AttributeMethods::Read#read_attribute
--------------------------------------------------------------------------------
                      0.46      0.10      0.00      0.35      10000/10000      ActiveRecord::Base#[]
   1.08%   0.25%      0.46      0.10      0.00      0.35            10000      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.34      0.12      0.00      0.21      10000/10000      ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
                      0.02      0.02      0.00      0.00     10000/119996      Kernel#class
--------------------------------------------------------------------------------
                      0.45      0.45      0.00      0.00      70000/70000      Time#_dump
   1.07%   1.07%      0.45      0.45      0.00      0.00            70000      Kernel#instance_variable_set
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/80002      Object#acts_like?
                      0.00      0.00      0.00      0.00          1/80002      Array#each
                      0.02      0.02      0.00      0.00      10000/80002      ActiveSupport::TimeWithZone#respond_to?
                      0.05      0.03      0.00      0.02      10000/80002      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.11      0.03      0.00      0.08      10000/80002      Time#to_formatted_s
                      0.27      0.20      0.00      0.07      50000/80002      ActiveModel::AttributeMethods#respond_to?
   1.06%   0.66%      0.45      0.28      0.00      0.17            80002      Kernel#respond_to?
                      0.17      0.17      0.00      0.00    60001/2890001      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/220001      <Class::Time>#zone
                      0.02      0.02      0.00      0.00     10000/220001      <Class::ActiveSupport::Cache::Store>#instrument
                      0.02      0.02      0.00      0.00     10000/220001      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/220001      NewRelic::Agent#is_execution_traced?
                      0.02      0.02      0.00      0.00     10000/220001      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.02      0.02      0.00      0.00     10000/220001      ActiveSupport::TaggedLogging#current_tags
                      0.03      0.03      0.00      0.00     20000/220001      NewRelic::Agent::TransactionSampler#builder
                      0.04      0.04      0.00      0.00     20000/220001      Dalli::Server#multi?
                      0.04      0.04      0.00      0.00     20000/220001      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.12      0.12      0.00      0.00     70000/220001      MonitorMixin#mon_enter
                      0.13      0.13      0.00      0.00     40000/220001      MonitorMixin#mon_check_owner
   1.05%   1.05%      0.45      0.45      0.00      0.00           220001      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/20012      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          2/20012      Enumerable#partition
                      0.00      0.00      0.00      0.00          3/20012      Enumerable#detect
                      0.00      0.00      0.00      0.00          3/20012      ActiveSupport::Inflector#apply_inflections
                      0.08      0.08      0.00      0.00      10003/20012      Enumerable#any?
                      0.37      0.06      0.00      0.31      10000/20012      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.05%   0.33%      0.45      0.14      0.00      0.31            20012      Array#each
                      0.31      0.31      0.00      0.00      20000/20000      NewRelic::MethodTraceStats#record_data_point
                      0.00      0.00      0.00      0.00          115/133      String#gsub!
                      0.00      0.00      0.00      0.00            20/20      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#plain?
                      0.00      0.00      0.00      0.00            19/19      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#match
                      0.00      0.00      0.00      0.00          1/80002      Kernel#respond_to?
--------------------------------------------------------------------------------
                      0.43      0.10      0.00      0.33      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
   1.02%   0.23%      0.43      0.10      0.00      0.33            10000      ActiveSupport::Cache::DalliStore#escape
                      0.23      0.10      0.00      0.13      10000/80009      Kernel#dup
                      0.04      0.04      0.00      0.00      10000/10002      String#gsub
                      0.03      0.03      0.00      0.00      10000/10000      String#force_encoding
                      0.03      0.03      0.00      0.00      10000/10000      String#encoding_aware?
                      0.02      0.02      0.00      0.00      10000/70005      String#to_s
--------------------------------------------------------------------------------
                      0.42      0.21      0.00      0.21      80009/80009      Kernel#dup
   0.98%   0.49%      0.42      0.21      0.00      0.21            80009      Kernel#initialize_dup
                      0.19      0.19      0.00      0.00      70000/70000      Time#initialize_copy
                      0.02      0.02      0.00      0.00      10009/10009      String#initialize_copy
--------------------------------------------------------------------------------
                      0.38      0.22      0.00      0.16      10000/10000      Time#to_formatted_s
   0.91%   0.52%      0.38      0.22      0.00      0.16            10000      Time#strftime
                      0.10      0.10      0.00      0.00      20000/20000      Fixnum#*
                      0.02      0.02      0.00      0.00     10000/150000      Fixnum#divmod
                      0.02      0.02      0.00      0.00     10000/150000      Fixnum#<=>
                      0.02      0.02      0.00      0.00      10000/10000      Bignum#<=>
--------------------------------------------------------------------------------
                      0.38      0.15      0.00      0.23      19998/19998      Hash#[]
   0.89%   0.34%      0.38      0.15      0.00      0.23            19998      NewRelic::MetricSpec#eql?
                      0.13      0.13      0.00      0.00      39996/70005      String#to_s
                      0.07      0.07      0.00      0.00     39996/119996      Kernel#class
                      0.04      0.04      0.00      0.00      19998/19998      String#eql?
--------------------------------------------------------------------------------
                      0.36      0.20      0.00      0.17      40000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
   0.86%   0.47%      0.36      0.20      0.00      0.17            40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
                      0.17      0.17      0.00      0.00      40000/40000      NewRelic::Agent#agent
--------------------------------------------------------------------------------
                      0.15      0.15      0.00      0.00     40000/110000      <Class::Time>#now
                      0.21      0.21      0.00      0.00     70000/110000      Kernel#dup
   0.84%   0.84%      0.36      0.36      0.00      0.00           110000      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.34      0.12      0.00      0.21      10000/10000      ActiveRecord::AttributeMethods::Read#read_attribute
   0.79%   0.29%      0.34      0.12      0.00      0.21            10000      ActiveRecord::AttributeMethods::Read::ClassMethods#type_cast_attribute
                      0.08      0.08      0.00      0.00      10000/10000      Hash#has_key?
                      0.05      0.05      0.00      0.00      20000/20000      ActiveRecord::AttributeMethods::ClassMethods#generated_external_attribute_methods
                      0.03      0.03      0.00      0.00      10000/10000      #<Module:0x000000079b0aa8>#__temp__
                      0.03      0.03      0.00      0.00      10000/10000      Module#method_defined?
                      0.02      0.02      0.00      0.00      10000/50001      Symbol#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/70001      TZInfo::TimeOrDateTime#initialize
                      0.34      0.34      0.00      0.00      70000/70001      Time#_dump
   0.79%   0.79%      0.34      0.34      0.00      0.00            70001      Time#zone
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00     10000/150000      Time#strftime
                      0.30      0.30      0.00      0.00    140000/150000      Time#_dump_without_zone
   0.76%   0.76%      0.32      0.32      0.00      0.00           150000      Fixnum#<=>
--------------------------------------------------------------------------------
                      0.31      0.05      0.00      0.25      10000/10000      ActiveSupport::TaggedLogging#add
   0.72%   0.13%      0.31      0.05      0.00      0.25            10000      ActiveSupport::TaggedLogging#tags_text
                      0.17      0.09      0.00      0.08      10000/10003      Enumerable#any?
                      0.08      0.05      0.00      0.04      10000/10000      ActiveSupport::TaggedLogging#current_tags
--------------------------------------------------------------------------------
                      0.31      0.31      0.00      0.00      20000/20000      Array#each
   0.72%   0.72%      0.31      0.31      0.00      0.00            20000      NewRelic::MethodTraceStats#record_data_point
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/70005      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          1/70005      ActiveSupport::Inflector#demodulize
                      0.00      0.00      0.00      0.00          3/70005      ActiveSupport::Inflector#apply_inflections
                      0.00      0.00      0.00      0.00          4/70005      ActiveSupport::Inflector#underscore
                      0.02      0.02      0.00      0.00      10000/70005      ActiveSupport::Cache::DalliStore#escape
                      0.02      0.02      0.00      0.00      10000/70005      ActiveSupport::Cache::DalliStore#expanded_key
                      0.13      0.13      0.00      0.00      39996/70005      NewRelic::MetricSpec#eql?
                      0.14      0.14      0.00      0.00      10000/70005      Dalli::Client#perform
   0.72%   0.72%      0.30      0.30      0.00      0.00            70005      String#to_s
--------------------------------------------------------------------------------
                      0.30      0.07      0.00      0.23      10000/10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
   0.71%   0.17%      0.30      0.07      0.00      0.23            10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.09      0.05      0.00      0.04      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Rubinius>#enabled?
                      0.08      0.03      0.00      0.05      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.06      0.04      0.00      0.02      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Ruby19>#enabled?
--------------------------------------------------------------------------------
                      0.29      0.10      0.00      0.19      20000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.69%   0.23%      0.29      0.10      0.00      0.19            20000      Time#to_f
                      0.10      0.06      0.00      0.05      20000/20000      Numeric#quo
                      0.09      0.05      0.00      0.04      20000/20000      Rational#to_f
--------------------------------------------------------------------------------
                      0.27      0.14      0.00      0.13      40000/40000      MonitorMixin#mon_exit
   0.64%   0.33%      0.27      0.14      0.00      0.13            40000      MonitorMixin#mon_check_owner
                      0.13      0.13      0.00      0.00     40000/220001      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          2/20002      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
                      0.27      0.12      0.00      0.15      20000/20002      ActiveModel::AttributeMethods#match_attribute_method?
   0.64%   0.29%      0.27      0.12      0.00      0.15            20002     *ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
                      0.10      0.10      0.00      0.00      40000/40000      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matchers_cache
                      0.04      0.04      0.00      0.00      20000/20000      Hash#key?
                      0.00      0.00      0.00      0.00              2/3      Enumerable#detect
                      0.00      0.00      0.00      0.00              2/2      Enumerable#partition
                      0.00      0.00      0.00      0.00              2/2      Array#flatten
                      0.00      0.00      0.00      0.00          2/20005      Hash#[]=
                      0.00      0.00      0.00      0.00              2/2      Symbol#to_proc
                      0.00      0.00      0.00      0.00              2/2      Array#reverse
                      0.00      0.00      0.00      0.00          2/20002      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matcher
--------------------------------------------------------------------------------
                      0.27      0.20      0.00      0.07      40000/40000      <Class::Time>#now
   0.64%   0.47%      0.27      0.20      0.00      0.07            40000      Time#initialize
                      0.07      0.07      0.00      0.00      40000/40000      Fixnum#+
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00     10000/119996      Dalli::Client#set_with_newrelic_trace
                      0.02      0.02      0.00      0.00     10000/119996      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.04      0.04      0.00      0.00     20000/119996      ActiveModel::AttributeMethods#match_attribute_method?
                      0.05      0.05      0.00      0.00     30000/119996      ActiveRecord::AttributeMethods#respond_to?
                      0.07      0.07      0.00      0.00     39996/119996      NewRelic::MetricSpec#eql?
                      0.08      0.08      0.00      0.00     10000/119996      ActiveRecord::Integration#cache_key
   0.64%   0.64%      0.27      0.27      0.00      0.00           119996      Kernel#class
--------------------------------------------------------------------------------
                      0.24      0.10      0.00      0.14      20000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.58%   0.24%      0.24      0.10      0.00      0.14            20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
                      0.11      0.11      0.00      0.00      20000/20005      Hash#[]=
                      0.03      0.03      0.00      0.00      20000/60000      NilClass#nil?
--------------------------------------------------------------------------------
                      0.24      0.10      0.00      0.14      30000/30000      ActiveSupport::Cache::DalliStore#log
   0.57%   0.24%      0.24      0.10      0.00      0.14            30000      ActiveSupport::Cache::DalliStore#logger
                      0.14      0.14      0.00      0.00      30000/30000      <Module::Dalli>#logger
--------------------------------------------------------------------------------
                      0.24      0.10      0.00      0.13      10000/10000      Logger#add
   0.56%   0.25%      0.24      0.10      0.00      0.13            10000      Logger#format_message
                      0.13      0.11      0.00      0.02      10000/10000      Logger::SimpleFormatter#call
--------------------------------------------------------------------------------
                      0.08      0.04      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.14      0.10      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
   0.53%   0.35%      0.22      0.15      0.00      0.08            20000      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.04      0.04      0.00      0.00     20000/100001      Thread#[]
                      0.04      0.04      0.00      0.00     20000/220001      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.21      0.13      0.00      0.08      20000/20000      Class#new
   0.50%   0.30%      0.21      0.13      0.00      0.08            20000      NewRelic::MetricSpec#initialize
                      0.08      0.08      0.00      0.00      40000/40000      String#[]
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/100001      <Class::Time>#zone
                      0.02      0.02      0.00      0.00     10000/100001      NewRelic::Agent#is_execution_traced?
                      0.02      0.02      0.00      0.00     10000/100001      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.02      0.02      0.00      0.00     10000/100001      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/100001      <Class::ActiveSupport::Cache::Store>#instrument
                      0.04      0.04      0.00      0.00     20000/100001      NewRelic::Agent::TransactionSampler#builder
                      0.04      0.04      0.00      0.00     20000/100001      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.04      0.04      0.00      0.00     20000/100001      Dalli::Server#multi?
   0.46%   0.46%      0.20      0.20      0.00      0.00           100001      Thread#[]
--------------------------------------------------------------------------------
                      0.19      0.19      0.00      0.00      40004/40004      NewRelic::MetricSpec#hash
   0.45%   0.45%      0.19      0.19      0.00      0.00            40004      String#hash
--------------------------------------------------------------------------------
                      0.19      0.19      0.00      0.00      70000/70000      Kernel#initialize_dup
   0.44%   0.44%      0.19      0.19      0.00      0.00            70000      Time#initialize_copy
--------------------------------------------------------------------------------
                      0.18      0.04      0.00      0.14      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.43%   0.10%      0.18      0.04      0.00      0.14            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
                      0.14      0.03      0.00      0.10      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#traced?
--------------------------------------------------------------------------------
                      0.17      0.09      0.00      0.08      10000/10000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
   0.41%   0.22%      0.17      0.09      0.00      0.08            10000      NewRelic::Agent::TransactionSampler#notice_pop_scope
                      0.08      0.04      0.00      0.04      10000/20000      NewRelic::Agent::TransactionSampler#builder
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          3/10003      ActiveSupport::Inflector#apply_inflections
                      0.17      0.09      0.00      0.08      10000/10003      ActiveSupport::TaggedLogging#tags_text
   0.40%   0.21%      0.17      0.09      0.00      0.08            10003      Enumerable#any?
                      0.08      0.08      0.00      0.00      10003/20012      Array#each
--------------------------------------------------------------------------------
                      0.17      0.17      0.00      0.00      40000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
   0.39%   0.39%      0.17      0.17      0.00      0.00            40000      NewRelic::Agent#agent
--------------------------------------------------------------------------------
                      0.17      0.09      0.00      0.08      20000/20000      Dalli::Server#set
   0.39%   0.21%      0.17      0.09      0.00      0.08            20000      Dalli::Server#multi?
                      0.04 
Mike Perham
Owner

First thing I noticed: marshalling of the value is taking >50% of the total time.

                     21.98      9.64      0.00     12.34      10000/10000      Dalli::Server#serialize
  51.83%  22.74%     21.98      9.64      0.00     12.34            10000      <Module::Marshal>#dump
                      6.01      6.01      0.00      0.00  2830000/2890001      Kernel#respond_to_missing?
                      4.33      0.88      0.00      3.45      70000/70000      Time#_dump
                      1.70      0.18      0.00      1.52      20000/30000      ActiveRecord::AttributeMethods#respond_to?
                      0.16      0.12      0.00      0.04      10000/10000      ActiveSupport::TimeWithZone#respond_to?
                      0.11      0.05      0.00      0.06      10000/10000      ActiveSupport::TimeWithZone#marshal_dump
                      0.02      0.02      0.00      0.00      10000/10000      Date#marshal_dump
Mike Perham
Owner

Everything else looks about normal. Can you get the same profile with Dalli 1.1 so we can compare total time and profiles?

Avi Tzurel
Avi Tzurel

Here's the profile from the Rails 3.0.9 version


system :006 > result = RubyProf.profile do
system :007 >     10000.times do
system :008 >       Rails.cache.write(user, user)
system :009?>     end
system :010?>   end
 => #<RubyProf::Profile:0x00000007858390> 
system :011 > printer = RubyProf::GraphPrinter.new(result)
 => #<RubyProf::GraphPrinter:0x0000000812ffb8 @result=#<RubyProf::Profile:0x00000007858390>, @output=nil> 
system :012 > printer.print(STDOUT, {})
Thread ID: 3319920
Total Time: 42.516394178
Sort by: total_time

  %total   %self     total      self      wait     child            calls    Name
--------------------------------------------------------------------------------
 100.00%   0.00%     42.52      0.00      0.00     42.52                1      Object#irb_binding
                     42.52      0.04      0.00     42.48              1/1      Integer#times
--------------------------------------------------------------------------------
                     42.52      0.04      0.00     42.48              1/1      Object#irb_binding
 100.00%   0.08%     42.52      0.04      0.00     42.48                1      Integer#times
                     42.45      0.05      0.00     42.40      10000/10000      ActiveSupport::Cache::DalliStore#write_with_tags
                      0.03      0.03      0.00      0.00      10000/10000      <Module::Rails>#cache
--------------------------------------------------------------------------------
                     42.45      0.05      0.00     42.40      10000/10000      Integer#times
  99.85%   0.12%     42.45      0.05      0.00     42.40            10000      ActiveSupport::Cache::DalliStore#write_with_tags
                     42.40      0.12      0.00     42.28      10000/10000      <Module::ActiveSupport::Notifications>#instrument
--------------------------------------------------------------------------------
                     42.40      0.12      0.00     42.28      10000/10000      ActiveSupport::Cache::DalliStore#write_with_tags
  99.73%   0.29%     42.40      0.12      0.00     42.28            10000      <Module::ActiveSupport::Notifications>#instrument
                     42.22      0.06      0.00     42.16      10000/10000      ActiveSupport::Cache::Store#write
                      0.02      0.02      0.00      0.00      10000/10001      Hash#delete
                      0.02      0.02      0.00      0.00      10000/40005      Kernel#nil?
                      0.02      0.02      0.00      0.00      10000/10006      Kernel#block_given?
                      0.00      0.00      0.00      0.00              1/2      Hash#default
--------------------------------------------------------------------------------
                     42.22      0.06      0.00     42.16      10000/10000      <Module::ActiveSupport::Notifications>#instrument
  99.29%   0.13%     42.22      0.06      0.00     42.16            10000      ActiveSupport::Cache::Store#write
                     41.94      0.12      0.00     41.82      10000/10000      ActiveSupport::Cache::Store#instrument
                      0.22      0.05      0.00      0.17      10000/10000      ActiveSupport::Cache::Store#merged_options
--------------------------------------------------------------------------------
                     41.94      0.12      0.00     41.82      10000/10000      ActiveSupport::Cache::Store#write
  98.64%   0.29%     41.94      0.12      0.00     41.82            10000      ActiveSupport::Cache::Store#instrument
                     37.30      0.06      0.00     37.24      10000/10000      ActiveSupport::Cache::DalliStore::LocalCacheWithRaw#write_entry
                      3.51      0.08      0.00      3.43      10000/10000      ActiveSupport::Cache::Store#namespaced_key
                      0.71      0.16      0.00      0.55      10000/40010      Class#new
                      0.19      0.16      0.00      0.04      10000/10000      ActiveSupport::Cache::Store#log
                      0.08      0.04      0.00      0.04      10000/10000      <Class::ActiveSupport::Cache::Store>#instrument
                      0.02      0.02      0.00      0.00     10000/129998      Kernel#class
--------------------------------------------------------------------------------
                     37.30      0.06      0.00     37.24      10000/10000      ActiveSupport::Cache::Store#instrument
  87.73%   0.14%     37.30      0.06      0.00     37.24            10000      ActiveSupport::Cache::DalliStore::LocalCacheWithRaw#write_entry
                     37.24      0.06      0.00     37.19      10000/10000      ActiveSupport::Cache::Strategy::LocalCache#write_entry
--------------------------------------------------------------------------------
                     37.24      0.06      0.00     37.19      10000/10000      ActiveSupport::Cache::DalliStore::LocalCacheWithRaw#write_entry
  87.60%   0.13%     37.24      0.06      0.00     37.19            10000      ActiveSupport::Cache::Strategy::LocalCache#write_entry
                     37.07      0.10      0.00     36.97      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
                      0.12      0.05      0.00      0.07      10000/10000      ActiveSupport::Cache::Strategy::LocalCache#local_cache
--------------------------------------------------------------------------------
                     37.07      0.10      0.00     36.97      10000/10000      ActiveSupport::Cache::Strategy::LocalCache#write_entry
  87.19%   0.23%     37.07      0.10      0.00     36.97            10000      ActiveSupport::Cache::DalliStore#write_entry
                     36.64      0.08      0.00     36.56      10000/10000      Dalli::Client#set_with_newrelic_trace
                      0.32      0.10      0.00      0.22      10000/10000      ActiveSupport::Cache::DalliStore#escape_key
                      0.02      0.02      0.00      0.00      10000/10000      NilClass#to_i
--------------------------------------------------------------------------------
                     36.64      0.08      0.00     36.56      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
  86.17%   0.18%     36.64      0.08      0.00     36.56            10000      Dalli::Client#set_with_newrelic_trace
                     36.45      0.24      0.00     36.21      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                      0.09      0.05      0.00      0.04      10000/10000      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/129998      Kernel#class
--------------------------------------------------------------------------------
                     36.45      0.24      0.00     36.21      10000/10000      Dalli::Client#set_with_newrelic_trace
  85.73%   0.57%     36.45      0.24      0.00     36.21            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
                     29.89      0.07      0.00     29.82      10000/10000      Dalli::Client#set
                      2.24      0.11      0.00      2.13      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      1.26      0.04      0.00      1.22      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      1.14      0.05      0.00      1.09      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      0.72      0.22      0.00      0.50      20000/30000      Time#to_f
                      0.47      0.18      0.00      0.29      30000/40000      <Class::Time>#now
                      0.25      0.17      0.00      0.08      20000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
                      0.25      0.04      0.00      0.20      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
--------------------------------------------------------------------------------
                     29.89      0.07      0.00     29.82      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
  70.30%   0.16%     29.89      0.07      0.00     29.82            10000      Dalli::Client#set
                     29.77      0.13      0.00     29.64      10000/10000      Dalli::Client#perform
                      0.05      0.03      0.00      0.02      10000/10000      Hash#==
--------------------------------------------------------------------------------
                     29.77      0.13      0.00     29.64      10000/10000      Dalli::Client#set
  70.02%   0.30%     29.77      0.13      0.00     29.64            10000      Dalli::Client#perform
                     28.35      0.04      0.00     28.31      10000/10000      Dalli::Threadsafe#request
                      0.95      0.12      0.00      0.82      10000/10000      Dalli::Ring#server_for_key
                      0.26      0.18      0.00      0.08      10000/10000      Dalli::Client#validate_key
                      0.04      0.04      0.00      0.00      10000/10000      Dalli::Client#key_with_namespace
                      0.03      0.03      0.00      0.00      10000/10000      Dalli::Client#ring
                      0.02      0.02      0.00      0.00      10000/70032      String#to_s
--------------------------------------------------------------------------------
                      0.71      0.15      0.00      0.56      20000/30000      Dalli::Threadsafe#alive?
                     28.31      0.15      0.00     28.16      10000/30000      Dalli::Threadsafe#request
  68.27%   0.72%     29.03      0.30      0.00     28.72            30000     *MonitorMixin#mon_synchronize
                     27.74      0.06      0.00     27.68      10000/10000      Dalli::Server#request
                      0.61      0.29      0.00      0.32      30000/30000      MonitorMixin#mon_exit
                      0.51      0.32      0.00      0.19      30000/30000      MonitorMixin#mon_enter
                      0.05      0.05      0.00      0.00      20000/20000      Dalli::Server#alive?
--------------------------------------------------------------------------------
                     28.35      0.04      0.00     28.31      10000/10000      Dalli::Client#perform
  66.68%   0.08%     28.35      0.04      0.00     28.31            10000      Dalli::Threadsafe#request
                     28.31      0.15      0.00     28.16      10000/30000      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                     27.74      0.06      0.00     27.68      10000/10000      MonitorMixin#mon_synchronize
  65.25%   0.15%     27.74      0.06      0.00     27.68            10000      Dalli::Server#request
                     27.31      0.16      0.00     27.15      10000/10000      Dalli::Server#set
                      0.37      0.09      0.00      0.28      10000/20000      Dalli::Threadsafe#alive?
--------------------------------------------------------------------------------
                     27.31      0.16      0.00     27.15      10000/10000      Dalli::Server#request
  64.23%   0.38%     27.31      0.16      0.00     27.15            10000      Dalli::Server#set
                     24.38      0.16      0.00     24.22      10000/10000      Dalli::Server#serialize
                      1.62      0.18      0.00      1.44      10000/10001      Dalli::Server#generic_response
                      0.68      0.05      0.00      0.64      10000/10001      Dalli::Server#write
                      0.23      0.09      0.00      0.14      20000/20000      Dalli::Server#multi?
                      0.12      0.12      0.00      0.00      10000/10001      Array#pack
                      0.11      0.11      0.00      0.00      30000/60004      String#bytesize
--------------------------------------------------------------------------------
                     24.38      0.16      0.00     24.22      10000/10000      Dalli::Server#set
  57.34%   0.39%     24.38      0.16      0.00     24.22            10000      Dalli::Server#serialize
                     24.18      8.77      0.00     15.41      10000/10000      <Module::Marshal>#dump
                      0.02      0.02      0.00      0.00      10000/60004      String#bytesize
                      0.02      0.02      0.00      0.00      10000/10000      Fixnum#|
--------------------------------------------------------------------------------
                     24.18      8.77      0.00     15.41      10000/10000      Dalli::Server#serialize
  56.87%  20.63%     24.18      8.77      0.00     15.41            10000      <Module::Marshal>#dump
                      5.44      5.44      0.00      0.00  2730000/2820000      Kernel#respond_to_missing?
                      4.82      0.78      0.00      4.04      70000/70000      Time#_dump
                      4.79      0.30      0.00      4.49      20000/40000      ActiveRecord::AttributeMethods#respond_to?
                      0.17      0.05      0.00      0.12      10000/10000      ActiveSupport::TimeWithZone#marshal_dump
                      0.16      0.06      0.00      0.10      10000/10000      ActiveSupport::TimeWithZone#respond_to?
                      0.02      0.02      0.00      0.00      10000/10000      Date#marshal_dump
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00    10000/2820000      Hash#==
                      0.21      0.21      0.00      0.00    80000/2820000      Kernel#respond_to?
                      5.44      5.44      0.00      0.00  2730000/2820000      <Module::Marshal>#dump
  13.34%  13.34%      5.67      5.67      0.00      0.00          2820000      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.22      0.09      0.00      0.13      10000/40000      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.29      0.16      0.00      0.13      10000/40000      ActiveSupport::Cache::Store#expanded_key
                      4.79      0.30      0.00      4.49      20000/40000      <Module::Marshal>#dump
  12.47%   1.29%      5.30      0.55      0.00      4.75            40000      ActiveRecord::AttributeMethods#respond_to?
                      4.51      0.46      0.00      4.04      40000/40000      ActiveModel::AttributeMethods#respond_to?
                      0.17      0.17      0.00      0.00      40000/40000      ActiveModel::AttributeMethods::ClassMethods#attribute_methods_generated?
                      0.07      0.07      0.00      0.00     40000/129998      Kernel#class
--------------------------------------------------------------------------------
                      4.82      0.78      0.00      4.04      70000/70000      <Module::Marshal>#dump
  11.33%   1.82%      4.82      0.78      0.00      4.04            70000      Time#_dump
                      2.21      1.62      0.00      0.59      70000/70000      Time#_dump_without_zone
                      0.97      0.32      0.00      0.65      70000/70007      Kernel#dup
                      0.58      0.58      0.00      0.00      70000/70000      Kernel#instance_variable_set
                      0.27      0.27      0.00      0.00      70000/70001      Time#zone
--------------------------------------------------------------------------------
                      4.51      0.46      0.00      4.04      40000/40000      ActiveRecord::AttributeMethods#respond_to?
  10.60%   1.09%      4.51      0.46      0.00      4.04            40000      ActiveModel::AttributeMethods#respond_to?
                      3.48      0.11      0.00      3.37      20000/20000      ActiveModel::AttributeMethods#match_attribute_method?
                      0.52      0.41      0.00      0.11     80000/130002      Kernel#respond_to?
                      0.04      0.04      0.00      0.00      20000/70001      Symbol#to_s
--------------------------------------------------------------------------------
                      3.51      0.08      0.00      3.43      10000/10000      ActiveSupport::Cache::Store#instrument
   8.26%   0.20%      3.51      0.08      0.00      3.43            10000      ActiveSupport::Cache::Store#namespaced_key
                      3.40      0.07      0.00      3.34      10000/10000      ActiveSupport::Cache::Store#expanded_key
                      0.02      0.02      0.00      0.00      10000/10006      Kernel#is_a?
--------------------------------------------------------------------------------
                      3.48      0.11      0.00      3.37      20000/20000      ActiveModel::AttributeMethods#respond_to?
   8.18%   0.25%      3.48      0.11      0.00      3.37            20000      ActiveModel::AttributeMethods#match_attribute_method?
                      3.02      0.74      0.00      2.28      20000/30006      Array#each
                      0.32      0.13      0.00      0.19      20000/20000      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matchers
                      0.04      0.04      0.00      0.00     20000/129998      Kernel#class
--------------------------------------------------------------------------------
                      3.40      0.07      0.00      3.34      10000/10000      ActiveSupport::Cache::Store#namespaced_key
   8.00%   0.16%      3.40      0.07      0.00      3.34            10000      ActiveSupport::Cache::Store#expanded_key
                      3.03      0.13      0.00      2.90      10000/10000      ActiveRecord::Base#cache_key
                      0.29      0.16      0.00      0.13      10000/40000      ActiveRecord::AttributeMethods#respond_to?
                      0.02      0.02      0.00      0.00      10000/70032      String#to_s
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/30006      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          1/30006      Enumerable#any?
                      0.00      0.00      0.00      0.00          1/30006      Mutex#synchronize
                      0.00      0.00      0.00      0.00          1/30006      Dalli::Ring#threadsafe!
                      0.00      0.00      0.00      0.00          2/30006      ActiveSupport::Inflector#pluralize
                      0.36      0.06      0.00      0.30      10000/30006      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
                      3.02      0.74      0.00      2.28      20000/30006      ActiveModel::AttributeMethods#match_attribute_method?
   7.96%   1.90%      3.39      0.81      0.00      2.58            30006      Array#each
                      2.09      0.86      0.00      1.23    180000/180000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#match
                      0.30      0.30      0.00      0.00      20000/20000      NewRelic::MethodTraceStats#record_data_point
                      0.15      0.10      0.00      0.04      20000/20000      ActiveRecord::AttributeMethods#attribute_method?
                      0.04      0.04      0.00      0.00      20000/20000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher::AttributeMethodMatch#attr_name
                      0.00      0.00      0.00      0.00            76/88      String#gsub!
                      0.00      0.00      0.00      0.00              1/1      Kernel#extend
                      0.00      0.00      0.00      0.00          1/10002      IO#write
--------------------------------------------------------------------------------
                      3.03      0.13      0.00      2.90      10000/10000      ActiveSupport::Cache::Store#expanded_key
   7.12%   0.31%      3.03      0.13      0.00      2.90            10000      ActiveRecord::Base#cache_key
                      2.10      0.08      0.00      2.01      10000/10000      ActiveSupport::TimeWithZone#to_s
                      0.56      0.04      0.00      0.53      10000/10000      ActiveRecord::Base#[]
                      0.08      0.08      0.00      0.00     10000/129998      Kernel#class
                      0.08      0.06      0.00      0.02      10000/10000      #<Module:0x0000000761f498>#_id
                      0.03      0.03      0.00      0.00      10000/10000      ActiveModel::Naming#model_name
                      0.03      0.03      0.00      0.00      10000/10000      ActiveRecord::Persistence#new_record?
                      0.02      0.02      0.00      0.00      10000/10001      Fixnum#to_s
--------------------------------------------------------------------------------
                      1.09      0.14      0.00      0.95      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      1.22      0.19      0.00      1.03      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
   5.42%   0.78%      2.30      0.33      0.00      1.97            20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
                      0.83      0.13      0.00      0.70      10000/10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.52      0.13      0.00      0.38      10000/10000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.36      0.06      0.00      0.30      10000/30006      Array#each
                      0.20      0.07      0.00      0.12      20000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.03      0.03      0.00      0.00      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#pop_flag!
                      0.03      0.03      0.00      0.00      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#push_flag!
                      0.02      0.02      0.00      0.00      10000/10000      Float#-
--------------------------------------------------------------------------------
                      2.24      0.11      0.00      2.13      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   5.27%   0.26%      2.24      0.11      0.00      2.13            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
                      1.15      0.04      0.00      1.11      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      0.92      0.04      0.00      0.88      10000/10001      Array#map
                      0.02      0.02      0.00      0.00      10000/10000      Array#unshift
                      0.02      0.02      0.00      0.00      10000/10000      Array#shift
                      0.02      0.02      0.00      0.00      10000/10001      Kernel#Array
--------------------------------------------------------------------------------
                      2.21      1.62      0.00      0.59      70000/70000      Time#_dump
   5.21%   3.82%      2.21      1.62      0.00      0.59            70000      Time#_dump_without_zone
                      0.30      0.30      0.00      0.00    140000/150000      Fixnum#<=>
                      0.29      0.29      0.00      0.00    140000/150000      Fixnum#divmod
--------------------------------------------------------------------------------
                      2.10      0.08      0.00      2.01      10000/10000      ActiveRecord::Base#cache_key
   4.93%   0.20%      2.10      0.08      0.00      2.01            10000      ActiveSupport::TimeWithZone#to_s
                      1.81      0.10      0.00      1.70      10000/10000      ActiveSupport::TimeWithZone#strftime
                      0.12      0.04      0.00      0.08     10000/130002      Kernel#respond_to?
                      0.08      0.08      0.00      0.00      10000/10002      Symbol#==
--------------------------------------------------------------------------------
                      2.09      0.86      0.00      1.23    180000/180000      Array#each
   4.92%   2.03%      2.09      0.86      0.00      1.23           180000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#match
                      0.77      0.77      0.00      0.00    180000/180000      Regexp#match
                      0.21      0.13      0.00      0.08      20000/20000      <Class::ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher::AttributeMethodMatch>#new
                      0.14      0.09      0.00      0.05      20000/20000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#method_missing_target
                      0.11      0.11      0.00      0.00      20000/20000      MatchData#[]
--------------------------------------------------------------------------------
                      1.81      0.10      0.00      1.70      10000/10000      ActiveSupport::TimeWithZone#to_s
   4.25%   0.25%      1.81      0.10      0.00      1.70            10000      ActiveSupport::TimeWithZone#strftime
                      0.70      0.70      0.00      0.00      20000/30003      String#gsub
                      0.58      0.06      0.00      0.52      10000/10000      ActiveSupport::TimeWithZone#formatted_offset
                      0.20      0.10      0.00      0.10      10000/10000      Time#strftime
                      0.19      0.06      0.00      0.14      10000/10000      ActiveSupport::TimeWithZone#zone
                      0.03      0.03      0.00      0.00      10000/20000      ActiveSupport::TimeWithZone#time
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/10001      Dalli::Server#version
                      1.62      0.18      0.00      1.44      10000/10001      Dalli::Server#set
   3.81%   0.42%      1.62      0.18      0.00      1.44            10001      Dalli::Server#generic_response
                      1.34      0.04      0.00      1.30      10002/10002      Dalli::Server#read
                      0.10      0.10      0.00      0.00      10002/10002      String#unpack
                      0.00      0.00      0.00      0.00              2/2      <Class::Range>#allocate
                      0.00      0.00      0.00      0.00          2/40003      String#[]
--------------------------------------------------------------------------------
                      1.34      0.04      0.00      1.30      10002/10002      Dalli::Server#generic_response
   3.16%   0.10%      1.34      0.04      0.00      1.30            10002      Dalli::Server#read
                      1.30      0.07      0.00      1.23      10002/10002      Dalli::Server::KSocket#readfull
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/40010      MonitorMixin#mon_initialize
                      0.00      0.00      0.00      0.00          1/40010      Dalli::Threadsafe#init_threadsafe
                      0.00      0.00      0.00      0.00          1/40010      Time#in_time_zone
                      0.00      0.00      0.00      0.00          1/40010      TZInfo::DataTimezoneInfo#period_for_utc
                      0.00      0.00      0.00      0.00          1/40010      <Class::TZInfo::TimeOrDateTime>#wrap
                      0.00      0.00      0.00      0.00          1/40010      Array#map
                      0.00      0.00      0.00      0.00          1/40010      Dalli::Client#ring
                      0.00      0.00      0.00      0.00          1/40010      ActiveModel::Naming#model_name
                      0.16      0.10      0.00      0.06      10000/40010      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.23      0.04      0.00      0.19      10001/40010      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.23      0.04      0.00      0.19      10001/40010      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.71      0.16      0.00      0.55      10000/40010      ActiveSupport::Cache::Store#instrument
   3.15%   0.81%      1.34      0.34      0.00      0.99            40010     *Class#new
                      0.53      0.12      0.00      0.41      10000/10000      ActiveSupport::Cache::Entry#initialize
                      0.28      0.19      0.00      0.09      20000/20000      NewRelic::MetricSpec#initialize
                      0.14      0.14      0.00      0.00      40008/40009      <Class::BasicObject>#allocate
                      0.04      0.04      0.00      0.00      10000/10000      NewRelic::Agent::StatsEngine::ScopeStackElement#initialize
                      0.00      0.00      0.00      0.00              1/1      ActiveModel::Name#initialize
                      0.00      0.00      0.00      0.00              1/1      Dalli::Ring#initialize
                      0.00      0.00      0.00      0.00              2/2      NewRelic::StatsBase#initialize
                      0.00      0.00      0.00      0.00              1/1      Dalli::Server#initialize
                      0.00      0.00      0.00      0.00              1/1      MonitorMixin#initialize
                      0.00      0.00      0.00      0.00              1/1      TZInfo::TimeOrDateTime#initialize
                      0.00      0.00      0.00      0.00              1/1      TZInfo::TimezonePeriod#initialize
                      0.00      0.00      0.00      0.00              1/1      ActiveSupport::TimeWithZone#initialize
                      0.00      0.00      0.00      0.00              1/1      <Class::Mutex>#allocate
                      0.00      0.00      0.00      0.00              1/8      <Class::String>#allocate
                      0.00      0.00      0.00      0.00              1/1      Mutex#initialize
--------------------------------------------------------------------------------
                      1.30      0.07      0.00      1.23      10002/10002      Dalli::Server#read
   3.06%   0.15%      1.30      0.07      0.00      1.23            10002      Dalli::Server::KSocket#readfull
                      1.23      0.09      0.00      1.14      10002/10002      Kernel#loop
--------------------------------------------------------------------------------
                      1.26      0.04      0.00      1.22      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   2.96%   0.09%      1.26      0.04      0.00      1.22            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_footer
                      1.22      0.19      0.00      1.03      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      1.23      0.09      0.00      1.14      10002/10002      Dalli::Server::KSocket#readfull
   2.90%   0.21%      1.23      0.09      0.00      1.14            10002      Kernel#loop
                      1.11      1.10      0.01      0.00      10002/10002      IO#sysread
                      0.04      0.04      0.00      0.00      20004/60004      String#bytesize
--------------------------------------------------------------------------------
                      1.15      0.04      0.00      1.11      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   2.70%   0.09%      1.15      0.04      0.00      1.11            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
                      1.11      0.11      0.00      1.01      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
--------------------------------------------------------------------------------
                      1.14      0.05      0.00      1.09      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   2.67%   0.12%      1.14      0.05      0.00      1.09            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped_header
                      1.09      0.14      0.00      0.95      10000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
--------------------------------------------------------------------------------
                      0.37      0.09      0.00      0.28      10000/20000      Dalli::Server#request
                      0.75      0.03      0.00      0.71      10000/20000      Dalli::Ring#server_for_key
   2.63%   0.30%      1.12      0.13      0.00      0.99            20000      Dalli::Threadsafe#alive?
                      0.71      0.15      0.00      0.56      20000/30000      MonitorMixin#mon_synchronize
--------------------------------------------------------------------------------
                      1.11      0.11      0.00      1.01      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#main_stat
   2.62%   0.25%      1.11      0.11      0.00      1.01            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      0.91      0.22      0.00      0.69      10000/10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.10      0.04      0.00      0.06      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      1.11      1.10      0.01      0.00      10002/10002      Kernel#loop
   2.61%   2.59%      1.11      1.10      0.01      0.00            10002      IO#sysread
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/70007      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          2/70007      ActiveSupport::Inflector#pluralize
                      0.00      0.00      0.00      0.00          4/70007      ActiveSupport::Inflector#underscore
                      0.97      0.32      0.00      0.65      70000/70007      Time#_dump
   2.29%   0.76%      0.97      0.32      0.00      0.65            70007      Kernel#dup
                      0.44      0.19      0.00      0.25      70007/80009      Kernel#initialize_dup
                      0.21      0.21      0.00      0.00     70000/110000      <Class::Time>#allocate
                      0.00      0.00      0.00      0.00              7/8      <Class::String>#allocate
--------------------------------------------------------------------------------
                      0.95      0.12      0.00      0.82      10000/10000      Dalli::Client#perform
   2.23%   0.29%      0.95      0.12      0.00      0.82            10000      Dalli::Ring#server_for_key
                      0.75      0.03      0.00      0.71      10000/20000      Dalli::Threadsafe#alive?
                      0.08      0.08      0.00      0.00      10000/10000      Array#first
--------------------------------------------------------------------------------
                      0.21      0.11      0.00      0.10      10000/30000      ActiveSupport::Cache::Entry#initialize
                      0.72      0.22      0.00      0.50      20000/30000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   2.18%   0.77%      0.93      0.33      0.00      0.60            30000      Time#to_f
                      0.38      0.20      0.00      0.18      30000/30000      Rational#to_f
                      0.22      0.14      0.00      0.07      30000/30000      Numeric#quo
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/10001      Dalli::Client#ring
                      0.92      0.04      0.00      0.88      10000/10001      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_metric_stats
   2.17%   0.10%      0.92      0.04      0.00      0.88            10001      Array#map
                      0.88      0.04      0.00      0.83      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.00      0.00      0.00      0.00          1/40010      Class#new
--------------------------------------------------------------------------------
                      0.91      0.22      0.00      0.69      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
   2.14%   0.52%      0.91      0.22      0.00      0.69            10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.35      0.04      0.00      0.31      10000/20000      Hash#[]
                      0.23      0.04      0.00      0.19      10001/40010      Class#new
                      0.08      0.04      0.00      0.04      10000/10000      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.03      0.03      0.00      0.00      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats::SynchronizedHash#[]=
--------------------------------------------------------------------------------
                      0.88      0.04      0.00      0.83      10000/10000      Array#map
   2.06%   0.10%      0.88      0.04      0.00      0.83            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.68      0.06      0.00      0.62      10000/10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.16      0.04      0.00      0.12      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/130002      <Module::Dalli>#rails_logger
                      0.00      0.00      0.00      0.00         1/130002      Object#acts_like?
                      0.02      0.02      0.00      0.00     10000/130002      Dalli::Client#validate_key
                      0.05      0.03      0.00      0.02     10000/130002      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.08      0.08      0.00      0.00     10000/130002      ActiveSupport::Cache::DalliStore#escape_key
                      0.08      0.08      0.00      0.00     10000/130002      ActiveSupport::TimeWithZone#respond_to?
                      0.12      0.04      0.00      0.08     10000/130002      ActiveSupport::TimeWithZone#to_s
                      0.52      0.41      0.00      0.11     80000/130002      ActiveModel::AttributeMethods#respond_to?
   2.06%   1.56%      0.88      0.66      0.00      0.21           130002      Kernel#respond_to?
                      0.21      0.21      0.00      0.00    80000/2820000      Kernel#respond_to_missing?
--------------------------------------------------------------------------------
                      0.83      0.13      0.00      0.70      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.94%   0.30%      0.83      0.13      0.00      0.70            10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
                      0.30      0.07      0.00      0.23      10000/10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.16      0.10      0.00      0.06      10000/40010      Class#new
                      0.12      0.04      0.00      0.08      10000/10000      NewRelic::Agent::TransactionSampler#notice_push_scope
                      0.08      0.04      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.02      0.02      0.00      0.00      10000/10000      Array#push
                      0.02      0.02      0.00      0.00      10000/20001      Array#empty?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          2/30003      ActiveSupport::Inflector#humanize
                      0.00      0.00      0.00      0.00          1/30003      ActiveSupport::Inflector#demodulize
                      0.09      0.09      0.00      0.00      10000/30003      ActiveSupport::Cache::DalliStore#escape_key
                      0.70      0.70      0.00      0.00      20000/30003      ActiveSupport::TimeWithZone#strftime
   1.86%   1.86%      0.79      0.79      0.00      0.00            30003      String#gsub
--------------------------------------------------------------------------------
                      0.77      0.77      0.00      0.00    180000/180000      ActiveModel::AttributeMethods::ClassMethods::AttributeMethodMatcher#match
   1.82%   1.82%      0.77      0.77      0.00      0.00           180000      Regexp#match
--------------------------------------------------------------------------------
                      0.35      0.04      0.00      0.31      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#get_stats
                      0.36      0.04      0.00      0.32      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
   1.67%   0.20%      0.71      0.08      0.00      0.63            20000      Hash#[]
                      0.32      0.15      0.00      0.18      19998/19998      NewRelic::MetricSpec#eql?
                      0.30      0.16      0.00      0.15      20000/20002      NewRelic::MetricSpec#hash
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/10001      Dalli::Server#version
                      0.68      0.05      0.00      0.64      10000/10001      Dalli::Server#set
   1.61%   0.11%      0.68      0.05      0.00      0.64            10001      Dalli::Server#write
                      0.64      0.57      0.07      0.00      10001/10002      IO#write
--------------------------------------------------------------------------------
                      0.68      0.06      0.00      0.62      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
   1.59%   0.13%      0.68      0.06      0.00      0.62            10000      NewRelic::Agent::StatsEngine::MetricStats#get_stats_no_scope
                      0.36      0.04      0.00      0.32      10000/20000      Hash#[]
                      0.23      0.04      0.00      0.19      10001/40010      Class#new
                      0.03      0.03      0.00      0.00      10000/20000      NewRelic::Agent::StatsEngine::MetricStats#stats_hash
                      0.00      0.00      0.00      0.00              1/2      NewRelic::Agent::StatsEngine::MetricStats::SynchronizedHash#[]=
--------------------------------------------------------------------------------
                      0.17      0.10      0.00      0.08      10000/40000      ActiveSupport::Cache::Entry#initialize
                      0.47      0.18      0.00      0.29      30000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   1.52%   0.64%      0.64      0.27      0.00      0.37            40000      <Class::Time>#now
                      0.28      0.20      0.00      0.08      40000/40000      Time#initialize
                      0.09      0.09      0.00      0.00     40000/110000      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/10002      Array#each
                      0.64      0.57      0.07      0.00      10001/10002      Dalli::Server#write
   1.50%   1.34%      0.64      0.57      0.07      0.00            10002      IO#write
--------------------------------------------------------------------------------
                      0.61      0.29      0.00      0.32      30000/30000      MonitorMixin#mon_synchronize
   1.43%   0.67%      0.61      0.29      0.00      0.32            30000      MonitorMixin#mon_exit
                      0.28      0.11      0.00      0.17      30000/30000      MonitorMixin#mon_check_owner
                      0.04      0.04      0.00      0.00      20000/20003      Mutex#unlock
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/190005      ActiveSupport::BufferedLogger#clear_buffer
                      0.00      0.00      0.00      0.00         1/190005      <Class::Time>#zone
                      0.00      0.00      0.00      0.00         3/190005      ActiveSupport::BufferedLogger#buffer
                      0.02      0.02      0.00      0.00     10000/190005      NewRelic::Agent#is_execution_traced?
                      0.02      0.02      0.00      0.00     10000/190005      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/190005      ActiveSupport::Cache::Strategy::LocalCache#local_cache
                      0.02      0.02      0.00      0.00     10000/190005      <Class::ActiveSupport::Cache::Store>#instrument
                      0.02      0.02      0.00      0.00     10000/190005      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.04      0.04      0.00      0.00     20000/190005      NewRelic::Agent::TransactionSampler#builder
                      0.04      0.04      0.00      0.00     20000/190005      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.10      0.10      0.00      0.00     20000/190005      Dalli::Server#multi?
                      0.15      0.15      0.00      0.00     50000/190005      MonitorMixin#mon_enter
                      0.17      0.17      0.00      0.00     30000/190005      MonitorMixin#mon_check_owner
   1.37%   1.37%      0.58      0.58      0.00      0.00           190005      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.58      0.06      0.00      0.52      10000/10000      ActiveSupport::TimeWithZone#strftime
   1.37%   0.14%      0.58      0.06      0.00      0.52            10000      ActiveSupport::TimeWithZone#formatted_offset
                      0.39      0.29      0.00      0.10      10000/10000      <Class::ActiveSupport::TimeZone>#seconds_to_utc_offset
                      0.10      0.04      0.00      0.05      10000/10000      ActiveSupport::TimeWithZone#utc_offset
                      0.03      0.03      0.00      0.00      10000/10000      ActiveSupport::TimeWithZone#utc?
--------------------------------------------------------------------------------
                      0.58      0.58      0.00      0.00      70000/70000      Time#_dump
   1.36%   1.36%      0.58      0.58      0.00      0.00            70000      Kernel#instance_variable_set
--------------------------------------------------------------------------------
                      0.56      0.04      0.00      0.53      10000/10000      ActiveRecord::Base#cache_key
   1.33%   0.08%      0.56      0.04      0.00      0.53            10000      ActiveRecord::Base#[]
                      0.53      0.12      0.00      0.41      10000/10000      ActiveRecord::AttributeMethods::Read#read_attribute
--------------------------------------------------------------------------------
                      0.53      0.12      0.00      0.41      10000/10000      Class#new
   1.25%   0.27%      0.53      0.12      0.00      0.41            10000      ActiveSupport::Cache::Entry#initialize
                      0.21      0.11      0.00      0.10      10000/30000      Time#to_f
                      0.17      0.10      0.00      0.08      10000/40000      <Class::Time>#now
                      0.04      0.04      0.00      0.00      10000/10000      ActiveSupport::Cache::Entry#should_compress?
--------------------------------------------------------------------------------
                      0.53      0.12      0.00      0.41      10000/10000      ActiveRecord::Base#[]
   1.24%   0.28%      0.53      0.12      0.00      0.41            10000      ActiveRecord::AttributeMethods::Read#read_attribute
                      0.22      0.09      0.00      0.13      10000/40000      ActiveRecord::AttributeMethods#respond_to?
                      0.10      0.10      0.00      0.00      10000/10000      #<Module:0x0000000761f498>#_updated_at
                      0.06      0.06      0.00      0.00      30000/70001      Symbol#to_s
                      0.02      0.02      0.00      0.00      10000/10000      Hash#has_key?
--------------------------------------------------------------------------------
                      0.52      0.13      0.00      0.38      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.21%   0.31%      0.52      0.13      0.00      0.38            10000      NewRelic::Agent::StatsEngine::Transactions#pop_scope
                      0.17      0.09      0.00      0.08      10000/10000      NewRelic::Agent::TransactionSampler#notice_pop_scope
                      0.09      0.09      0.00      0.00      10000/10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#capture
                      0.08      0.04      0.00      0.04      10000/20000      NewRelic::Agent::StatsEngine::Transactions#scope_stack
                      0.02      0.02      0.00      0.00      10000/10000      Array#pop
                      0.02      0.02      0.00      0.00      10000/20001      Array#empty?
--------------------------------------------------------------------------------
                      0.51      0.32      0.00      0.19      30000/30000      MonitorMixin#mon_synchronize
   1.20%   0.76%      0.51      0.32      0.00      0.19            30000      MonitorMixin#mon_enter
                      0.15      0.15      0.00      0.00     50000/190005      <Class::Thread>#current
                      0.04      0.04      0.00      0.00      20000/20003      Mutex#lock
--------------------------------------------------------------------------------
                      0.05      0.03      0.00      0.02      10002/80009      Hash#merge
                      0.44      0.19      0.00      0.25      70007/80009      Kernel#dup
   1.14%   0.50%      0.48      0.21      0.00      0.27            80009      Kernel#initialize_dup
                      0.25      0.25      0.00      0.00      70000/70000      Time#initialize_copy
                      0.02      0.02      0.00      0.00      10002/10002      Hash#initialize_copy
                      0.00      0.00      0.00      0.00              7/7      String#initialize_copy
--------------------------------------------------------------------------------
                      0.10      0.04      0.00      0.06      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_scoped
                      0.16      0.04      0.00      0.12      10000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#get_stats_unscoped
                      0.20      0.07      0.00      0.12      20000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#log_errors
   1.06%   0.34%      0.45      0.15      0.00      0.31            40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
                      0.31      0.20      0.00      0.11      40000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
--------------------------------------------------------------------------------
                      0.39      0.29      0.00      0.10      10000/10000      ActiveSupport::TimeWithZone#formatted_offset
   0.92%   0.69%      0.39      0.29      0.00      0.10            10000      <Class::ActiveSupport::TimeZone>#seconds_to_utc_offset
                      0.06      0.06      0.00      0.00      10000/10000      String#%
                      0.03      0.03      0.00      0.00      20000/20000      Fixnum#abs
--------------------------------------------------------------------------------
                      0.38      0.20      0.00      0.18      30000/30000      Time#to_f
   0.90%   0.48%      0.38      0.20      0.00      0.18            30000      Rational#to_f
                      0.18      0.18      0.00      0.00      30000/30000      Fixnum#fdiv
--------------------------------------------------------------------------------
                      0.32      0.15      0.00      0.18      19998/19998      Hash#[]
   0.76%   0.34%      0.32      0.15      0.00      0.18            19998      NewRelic::MetricSpec#eql?
                      0.07      0.07      0.00      0.00      39996/70032      String#to_s
                      0.07      0.07      0.00      0.00     39996/129998      Kernel#class
                      0.04      0.04      0.00      0.00      19998/19998      String#eql?
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00     10000/150000      Time#strftime
                      0.30      0.30      0.00      0.00    140000/150000      Time#_dump_without_zone
   0.75%   0.75%      0.32      0.32      0.00      0.00           150000      Fixnum#<=>
--------------------------------------------------------------------------------
                      0.32      0.13      0.00      0.19      20000/20000      ActiveModel::AttributeMethods#match_attribute_method?
   0.75%   0.30%      0.32      0.13      0.00      0.19            20000      ActiveModel::AttributeMethods::ClassMethods#attribute_method_matchers
                      0.19      0.07      0.00      0.11      20000/20000      Class#read_inheritable_attribute
--------------------------------------------------------------------------------
                      0.32      0.10      0.00      0.22      10000/10000      ActiveSupport::Cache::DalliStore#write_entry
   0.75%   0.23%      0.32      0.10      0.00      0.22            10000      ActiveSupport::Cache::DalliStore#escape_key
                      0.09      0.09      0.00      0.00      10000/30003      String#gsub
                      0.08      0.08      0.00      0.00     10000/130002      Kernel#respond_to?
                      0.03      0.03      0.00      0.00      10000/10000      String#force_encoding
                      0.02      0.02      0.00      0.00      10000/70032      String#to_s
--------------------------------------------------------------------------------
                      0.09      0.09      0.00      0.00     40000/110000      <Class::Time>#now
                      0.21      0.21      0.00      0.00     70000/110000      Kernel#dup
   0.73%   0.73%      0.31      0.31      0.00      0.00           110000      <Class::Time>#allocate
--------------------------------------------------------------------------------
                      0.02      0.02      0.00      0.00     10000/150000      Time#strftime
                      0.29      0.29      0.00      0.00    140000/150000      Time#_dump_without_zone
   0.73%   0.73%      0.31      0.31      0.00      0.00           150000      Fixnum#divmod
--------------------------------------------------------------------------------
                      0.31      0.20      0.00      0.11      40000/40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#stat_engine
   0.72%   0.47%      0.31      0.20      0.00      0.11            40000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#agent_instance
                      0.11      0.11      0.00      0.00      40000/40000      NewRelic::Agent#agent
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          2/20002      Hash#[]=
                      0.30      0.16      0.00      0.15      20000/20002      Hash#[]
   0.72%   0.37%      0.30      0.16      0.00      0.15            20002      NewRelic::MetricSpec#hash
                      0.08      0.08      0.00      0.00      40004/40004      String#hash
                      0.04      0.04      0.00      0.00      20002/40005      Kernel#nil?
                      0.04      0.04      0.00      0.00      20002/20002      Fixnum#^
--------------------------------------------------------------------------------
                      0.30      0.30      0.00      0.00      20000/20000      Array#each
   0.71%   0.71%      0.30      0.30      0.00      0.00            20000      NewRelic::MethodTraceStats#record_data_point
--------------------------------------------------------------------------------
                      0.30      0.07      0.00      0.23      10000/10000      NewRelic::Agent::StatsEngine::Transactions#push_scope
   0.70%   0.17%      0.30      0.07      0.00      0.23            10000      <Module::NewRelic::Agent::StatsEngine::GCProfiler>#init
                      0.08      0.05      0.00      0.04      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Rubinius>#enabled?
                      0.08      0.03      0.00      0.05      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::RailsBench>#enabled?
                      0.06      0.04      0.00      0.02      10000/10000      <Class::NewRelic::Agent::StatsEngine::GCProfiler::Ruby19>#enabled?
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/129998      ActiveRecord::Base#column_for_attribute
                      0.00      0.00      0.00      0.00         1/129998      ActiveRecord::ConnectionAdapters::Column#type_cast
                      0.02      0.02      0.00      0.00     10000/129998      Dalli::Client#set_with_newrelic_trace
                      0.02      0.02      0.00      0.00     10000/129998      ActiveSupport::Cache::Store#instrument
                      0.04      0.04      0.00      0.00     20000/129998      ActiveModel::AttributeMethods#match_attribute_method?
                      0.07      0.07      0.00      0.00     39996/129998      NewRelic::MetricSpec#eql?
                      0.07      0.07      0.00      0.00     40000/129998      ActiveRecord::AttributeMethods#respond_to?
                      0.08      0.08      0.00      0.00     10000/129998      ActiveRecord::Base#cache_key
   0.70%   0.70%      0.30      0.30      0.00      0.00           129998      Kernel#class
--------------------------------------------------------------------------------
                      0.28      0.11      0.00      0.17      30000/30000      MonitorMixin#mon_exit
   0.66%   0.25%      0.28      0.11      0.00      0.17            30000      MonitorMixin#mon_check_owner
                      0.17      0.17      0.00      0.00     30000/190005      <Class::Thread>#current
--------------------------------------------------------------------------------
                      0.28      0.19      0.00      0.09      20000/20000      Class#new
   0.65%   0.45%      0.28      0.19      0.00      0.09            20000      NewRelic::MetricSpec#initialize
                      0.09      0.09      0.00      0.00      40000/40003      String#[]
--------------------------------------------------------------------------------
                      0.28      0.20      0.00      0.08      40000/40000      <Class::Time>#now
   0.65%   0.47%      0.28      0.20      0.00      0.08            40000      Time#initialize
                      0.08      0.08      0.00      0.00      40000/40000      Fixnum#+
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00          1/70001      TZInfo::TimeOrDateTime#initialize
                      0.27      0.27      0.00      0.00      70000/70001      Time#_dump
   0.65%   0.65%      0.27      0.27      0.00      0.00            70001      Time#zone
--------------------------------------------------------------------------------
                      0.26      0.18      0.00      0.08      10000/10000      Dalli::Client#perform
   0.62%   0.42%      0.26      0.18      0.00      0.08            10000      Dalli::Client#validate_key
                      0.03      0.03      0.00      0.00      10000/10000      String#strip
                      0.02      0.02      0.00      0.00     10000/130002      Kernel#respond_to?
                      0.02      0.02      0.00      0.00      10000/40005      Kernel#nil?
                      0.02      0.02      0.00      0.00      10000/10000      String#ascii_only?
--------------------------------------------------------------------------------
                      0.25      0.25      0.00      0.00      70000/70000      Kernel#initialize_dup
   0.59%   0.59%      0.25      0.25      0.00      0.00            70000      Time#initialize_copy
--------------------------------------------------------------------------------
                      0.25      0.17      0.00      0.08      20000/20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.58%   0.39%      0.25      0.17      0.00      0.08            20000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#set_if_nil
                      0.05      0.05      0.00      0.00      20000/20006      Hash#[]=
                      0.03      0.03      0.00      0.00      20000/30000      NilClass#nil?
--------------------------------------------------------------------------------
                      0.25      0.04      0.00      0.20      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_execution_scoped
   0.58%   0.11%      0.25      0.04      0.00      0.20            10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#trace_disabled?
                      0.20      0.10      0.00      0.11      10000/10000      NewRelic::Agent::MethodTracer::InstanceMethods::TraceExecutionScoped#traced?
--------------------------------------------------------------------------------
                      0.23      0.09      0.00      0.14      20000/20000      Dalli::Server#set
   0.54%   0.21%      0.23      0.09      0.00      0.14            20000      Dalli::Server#multi?
                      0.10      0.10      0.00      0.00     20000/190005      <Class::Thread>#current
                      0.04      0.04      0.00      0.00     20000/110001      Thread#[]
--------------------------------------------------------------------------------
                      0.22      0.05      0.00      0.17      10000/10000      ActiveSupport::Cache::Store#write
   0.52%   0.11%      0.22      0.05      0.00      0.17            10000      ActiveSupport::Cache::Store#merged_options
                      0.17      0.05      0.00      0.13      10000/10002      Hash#merge
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00         1/110001      <Class::Time>#zone
                      0.02      0.02      0.00      0.00     10000/110001      NewRelic::Agent#is_execution_traced?
                      0.02      0.02      0.00      0.00     10000/110001      <Class::NewRelic::Agent::Instrumentation::MetricFrame>#recording_web_transaction?
                      0.02      0.02      0.00      0.00     10000/110001      NewRelic::Agent::StatsEngine::Transactions#scope_name
                      0.02      0.02      0.00      0.00     10000/110001      ActiveSupport::Cache::Strategy::LocalCache#loc
Mike Perham
Owner

Marshalling takes 57% of the time in 3.0.9, even worse than 3.2.

Both the 3.2 and 3.0.9 versions take 42 seconds. Can you reproduce the slowdown? Your NR graphs show a 4x slowdown but the profile doesn't reflect that.

Avi Tzurel

I'll try to reproduce using the Profiling, you can see the slowness in the benchmark as well.

Mike Perham
Owner

Any news?

Avi Tzurel

No, not yet unfortunately.
I plan on spending Monday figuring this out, will get back with news then.

the8472

Have you tried something like this?

  # development.rb
  store = ActiveSupport::Cache.lookup_store(:dalli_store, :expires_in => 1.minute)
  store.send(:extend, ActiveSupport::Cache::Strategy::LocalCache)

  config.cache_store = store
  config.middleware.use(store.middleware)

It only doesn't cache nil-results, so those would still hit the memcached on repeated negative lookups, but it should still provide some improvement assuming you have repeated lookups within the same request.

Edit: The config.middleware.use probably isn't necessary if the object gets extended before being passed into the configuration.

Rutger Geelen

KensoDev,
same issue here. Were you able to solve it?

Rtger

the8472

As I said above, the dalli's active support store isn't implemented "properly" (as in inheriting from the ActiveSupport::Cache::Store base class) and does not provide a thread-local cache, which means redundant read/write requests will hit the network connection every time and require (un)marshaling on every lookup.

With a thread-local storage the actual objects are cached in memory for the duration of a request, meaning repeated lookups are more akin to hitting a hashmap rather than network request + unmarshaling.

This can have a huge performance impact compared to the other activesupport stores, depending on your usage patterns.

Mike Perham
Owner

Send me a PR to pull in LocalCache.

Virgilio Pigliucci
  • 1 here. Since deploying Dalli ( Rails 3.2.8 ) over memcache-client newrelic shows a 2X time increase ( especially on get_multi ).
the8472

Another performance issue:

cache = ActiveSupport::Cache.lookup_store(:dalli_store)

Benchmark.ms{10000.times{cache.fetch("b1"){"bar"}}} # 3587.053924
Benchmark.ms{10000.times{cache.fetch("b2"){"baz"}}} # 3715.264835

Benchmark.ms{10000.times{cache.fetch("b3"){nil}}} # 8313.579682


cache = ActiveSupport::Cache.lookup_store(:memory_store)

Benchmark.ms{10000.times{cache.fetch("b4"){nil}}} # 321.031518 
Benchmark.ms{10000.times{cache.fetch("b5"){"baz"}}} # 369.558517 

Something in the code must be treating nil as a cache miss instead of checking the presence of (any) data in the cache.

Mike Perham
Owner

An issue with get_multi was recently fixed in 2.4.0. nil cannot be stored as a value as that represents a cache miss. I'm adding LocalCache now.

Mike Perham mperham closed this in 4e49838 November 12, 2012
the8472

nil cannot be stored as a value as that represents a cache miss. I'm adding LocalCache now.

It could be wrapped with a placeholder/unwrapped on fetch. Caching nils is important for i18n where negative hits need to be stored too as they might trigger fallbacks/full evaluation of the whole i18n lookup chain.

Basically:

Rails.cache.fetch("some.key") do
   do_some_really_expensive_lookup_that_might_be_nil()
end

If nil is seen as a cache miss then this lookup will happen every time and therefore degrade performance

The other cache stores don't have that issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.