Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

performance issue #71

Closed
forresty opened this issue Jan 23, 2015 · 4 comments
Closed

performance issue #71

forresty opened this issue Jan 23, 2015 · 4 comments

Comments

@forresty
Copy link

there seems to be pretty heavy performance issue (~3x difference)

without makara:

$ http_load -parallel 30 -seconds 30 urls.txt 
5238 fetches, 30 max parallel, 2.55437e+07 bytes, in 30 seconds
4876.62 mean bytes/connection
174.6 fetches/sec, 851458 bytes/sec
msecs/connect: 0.0776838 mean, 3.995 max, 0.03 min
msecs/first-response: 170.548 mean, 3399.14 max, 28.019 min
HTTP response codes:
  code 200 -- 5238

with makara:

$ http_load -parallel 30 -seconds 30 urls.txt 
1387 fetches, 30 max parallel, 6.79761e+06 bytes, in 30 seconds
4900.95 mean bytes/connection
46.2333 fetches/sec, 226587 bytes/sec
msecs/connect: 0.100772 mean, 4.028 max, 0.034 min
msecs/first-response: 641.824 mean, 5868.17 max, 119.309 min
HTTP response codes:
  code 200 -- 1387

my set of relevant gems are:

cat Gemfile.lock | egrep 'grape|newrelic|unicorn|makara' | grep '(' | grep -v '~'
    grape (0.10.2)
    grape-entity (0.4.4)
    makara (0.3.0.rc3)
    newrelic-grape (1.4.1)
    newrelic_rpm (3.8.1.221)
    unicorn (4.8.3)

with stackprof I found that a lot of the time/CPU spent on Delegator#method_missing

$ stackprof tmp/stackprof-cpu-12824-1422006619.dump --limit 10
==================================
  Mode: cpu(1000)
  Samples: 108 (5.26% miss rate)
  GC: 13 (12.04%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       205 (189.8%)          35  (32.4%)     Delegator#method_missing
        10   (9.3%)          10   (9.3%)     block in Delegator#method_missing
         3   (2.8%)           3   (2.8%)     ActiveRecord::AttributeMethods::Dirty#original_raw_attributes
         2   (1.9%)           2   (1.9%)     ActiveRecord::AttributeMethods::ClassMethods#method_defined_within?
         2   (1.9%)           2   (1.9%)     ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter#configure_connection
        10   (9.3%)           2   (1.9%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
         2   (1.9%)           2   (1.9%)     #<Module:0x007f90b7ec98d0>.mechanism
         2   (1.9%)           2   (1.9%)     block in ActiveSupport::Dependencies::Loadable#require
         1   (0.9%)           1   (0.9%)     ActiveRecord::AttributeMethods#clone_attribute_value
         1   (0.9%)           1   (0.9%)     Set#include?
$ stackprof tmp/stackprof-cpu-12824-1422006619.dump --method 'Delegator#method_missing'
Delegator#method_missing (/home/forresty/.rbenv/versions/2.1.5/lib/ruby/2.1.0/delegate.rb:76)
  samples:    35 self (32.4%)  /    205 total (189.8%)
  callers:
     123  (   60.0%)  Makara::ConnectionWrapper#method_missing
      82  (   40.0%)  block in Makara::Proxy#method_missing
  callees (170 total):
      73  (   42.9%)  Makara::ConnectionWrapper#method_missing
      26  (   15.3%)  #<ActiveRecord::ConnectionAdapters::Mysql2Adapter:0x007f90bb66e3d0>.execute
      24  (   14.1%)  #<ActiveRecord::ConnectionAdapters::Mysql2Adapter:0x007f90bb62db78>.exec_query
      21  (   12.4%)  ActiveRecord::ConnectionAdapters::QueryCache#select_all
      10  (    5.9%)  block in Delegator#method_missing
       9  (    5.3%)  Makara::Proxy#method_missing
       4  (    2.4%)  ActiveRecord::ConnectionAdapters::DatabaseStatements#select_value
       2  (    1.2%)  ensure in Delegator#method_missing
       1  (    0.6%)  ActiveRecord::ConnectionAdapters::DatabaseStatements#cacheable_query
  code:
                                  |    76  |   def method_missing(m, *args, &block)
                                  |    77  |     r = true
                                  |    78  |     target = self.__getobj__ {r = false}
                                  |    79  |     begin
    1    (0.9%) /     1   (0.9%)  |    80  |       if r && target.respond_to?(m)
  192  (177.8%) /    34  (31.5%)  |    81  |         target.__send__(m, *args, &block)
                                  |    82  |       elsif ::Kernel.respond_to?(m, true)
                                  |    83  |         ::Kernel.instance_method(m).bind(self).(*args, &block)
                                  |    84  |       else
                                  |    85  |         super(m, *args, &block)
                                  |    86  |       end
                                  |    87  |     ensure
   12   (11.1%)                   |    88  |       $@.delete_if {|t| %r"\A#{Regexp.quote(__FILE__)}:(?:#{[__LINE__-7, __LINE__-5, __LINE__-3].join('|')}):"o =~ t} if $@
                                  |    89  |     end
block in Delegator#method_missing (/home/forresty/.rbenv/versions/2.1.5/lib/ruby/2.1.0/delegate.rb:88)
  samples:    10 self (9.3%)  /     10 total (9.3%)
  callers:
      10  (  100.0%)  Delegator#method_missing
  code:
   10    (9.3%) /    10   (9.3%)  |    88  |       $@.delete_if {|t| %r"\A#{Regexp.quote(__FILE__)}:(?:#{[__LINE__-7, __LINE__-5, __LINE__-3].join('|')}):"o =~ t} if $@
                                  |    89  |     end
ensure in Delegator#method_missing (/home/forresty/.rbenv/versions/2.1.5/lib/ruby/2.1.0/delegate.rb:79)
  samples:     1 self (0.9%)  /      2 total (1.9%)
  callers:
       2  (  100.0%)  Delegator#method_missing
  callees (1 total):
       1  (  100.0%)  block in Delegator#method_missing
  code:
                                  |    79  |     begin
                                  |    80  |       if r && target.respond_to?(m)
                                  |    81  |         target.__send__(m, *args, &block)
                                  |    82  |       elsif ::Kernel.respond_to?(m, true)
                                  |    83  |         ::Kernel.instance_method(m).bind(self).(*args, &block)
                                  |    84  |       else
                                  |    85  |         super(m, *args, &block)
                                  |    86  |       end
                                  |    87  |     ensure
    2    (1.9%) /     1   (0.9%)  |    88  |       $@.delete_if {|t| %r"\A#{Regexp.quote(__FILE__)}:(?:#{[__LINE__-7, __LINE__-5, __LINE__-3].join('|')}):"o =~ t} if $@
                                  |    89  |     end
block in Delegator#method_missing (/home/forresty/.rbenv/versions/2.1.5/lib/ruby/2.1.0/delegate.rb:88)
  samples:     1 self (0.9%)  /      1 total (0.9%)
  callers:
       1  (  100.0%)  ensure in Delegator#method_missing
  code:
    1    (0.9%) /     1   (0.9%)  |    88  |       $@.delete_if {|t| %r"\A#{Regexp.quote(__FILE__)}:(?:#{[__LINE__-7, __LINE__-5, __LINE__-3].join('|')}):"o =~ t} if $@
                                  |    89  |     end

Any ideas?
@forresty
Copy link
Author

FYI here is a normal stackprof output:

$ stackprof tmp/stackprof-cpu-13485-1422007173.dump --limit 10
==================================
  Mode: cpu(1000)
  Samples: 28 (17.65% miss rate)
  GC: 2 (7.14%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
         3  (10.7%)           2   (7.1%)     ActiveRecord::LazyAttributeHash#[]
         4  (14.3%)           2   (7.1%)     block in ActiveSupport::Dependencies::Loadable#require
         2   (7.1%)           2   (7.1%)     ThreadSafe::NonConcurrentCacheBackend#[]
         1   (3.6%)           1   (3.6%)     ActiveRecord::LazyAttributeHash#assign_default_value
         1   (3.6%)           1   (3.6%)     ActiveSupport::HashWithIndifferentAccess#update
         1   (3.6%)           1   (3.6%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
         1   (3.6%)           1   (3.6%)     block in ActiveRecord::Result#hash_rows
         1   (3.6%)           1   (3.6%)     ActiveRecord::Relation::Merger#filter_binds
         1   (3.6%)           1   (3.6%)     <module:Associations>
         2   (7.1%)           1   (3.6%)     <module:Associations>

@mnelson
Copy link
Contributor

mnelson commented Jan 23, 2015

Can you try pulling new_relic and see what the traces looks like?

@mnelson mnelson mentioned this issue Jan 23, 2015
Closed
@mnelson
Copy link
Contributor

mnelson commented Jan 23, 2015

Also, thank you. This is helpful. I'd love to track this down.

@forresty
Copy link
Author

Thanks, pulling newrelic and the performance now seems fine:

without makara:

$ http_load -parallel 10 -seconds 10 urls.txt 
1287 fetches, 10 max parallel, 9.26704e+06 bytes, in 10 seconds
7200.5 mean bytes/connection
128.7 fetches/sec, 926704 bytes/sec
msecs/connect: 0.0838073 mean, 0.31 max, 0.032 min
msecs/first-response: 77.298 mean, 1101 max, 22.64 min
HTTP response codes:
  code 200 -- 1287

with makara:

$ http_load -parallel 10 -seconds 10 urls.txt 
1295 fetches, 10 max parallel, 9.5496e+06 bytes, in 10 seconds
7374.21 mean bytes/connection
129.5 fetches/sec, 954959 bytes/sec
msecs/connect: 0.0919042 mean, 0.638 max, 0.031 min
msecs/first-response: 76.8999 mean, 1177.08 max, 20.856 min
HTTP response codes:
  code 200 -- 1295

full stackprof output:

$ stackprof tmp/stackprof-cpu-10023-1422039178.dump
==================================
  Mode: cpu(1000)
  Samples: 26 (0.00% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
         2   (7.7%)           2   (7.7%)     block in ActiveSupport::Dependencies::Loadable#require
         1   (3.8%)           1   (3.8%)     <module:Associations>
         1   (3.8%)           1   (3.8%)     singleton class
         2   (7.7%)           1   (3.8%)     singleton class
         1   (3.8%)           1   (3.8%)     block (2 levels) in Net::HTTPResponse::Inflater#inflate_adapter
         1   (3.8%)           1   (3.8%)     block in Net::HTTP#connect
         1   (3.8%)           1   (3.8%)     Net::HTTP#begin_transport
         1   (3.8%)           1   (3.8%)     ActiveSupport::HashWithIndifferentAccess#default
         1   (3.8%)           1   (3.8%)     #<Module:0x007ff0c263eee8>.set_name_cache
         1   (3.8%)           1   (3.8%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
         1   (3.8%)           1   (3.8%)     ActiveRecord::Scoping::ScopeRegistry#raise_invalid_scope_type!
         1   (3.8%)           1   (3.8%)     <module:Associations>
         1   (3.8%)           1   (3.8%)     ActiveSupport::JSON::Encoding::JSONGemEncoder::EscapedString#to_json
         2   (7.7%)           1   (3.8%)     ActiveRecord::Reflection::AssociationReflection#association_class
         1   (3.8%)           1   (3.8%)     ActiveModel::AttributeMethods::ClassMethods#define_proxy_call
         1   (3.8%)           1   (3.8%)     block in ActiveRecord::AttributeMethods::AttributeMethodCache#[]
         1   (3.8%)           1   (3.8%)     block in ActiveRecord::DynamicMatchers::Method.match
         1   (3.8%)           1   (3.8%)     block in ActiveRecord::AttributeMethods::AttributeMethodCache#[]
         1   (3.8%)           1   (3.8%)     <module:ActiveRecord>
         1   (3.8%)           1   (3.8%)     block in Arel::Visitors::Visitor.dispatch_cache
         1   (3.8%)           1   (3.8%)     ActiveRecord::QueryMethods#where!
         1   (3.8%)           1   (3.8%)     ThreadSafe::Cache#initialize
         2   (7.7%)           1   (3.8%)     ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter#configure_connection
         1   (3.8%)           1   (3.8%)     Set#include?
         4  (15.4%)           1   (3.8%)     Makara::Proxy#initialize
         1   (3.8%)           0   (0.0%)     Net::HTTP#do_start
        52 (200.0%)           0   (0.0%)     Grape::Middleware::Base#call
        26 (100.0%)           0   (0.0%)     #<Class:0x007ff0c3dd9008>#call
        26 (100.0%)           0   (0.0%)     #<Class:0x007ff0c3dd9620>#call
        26 (100.0%)           0   (0.0%)     #<Class:0x007ff0c3dd9620>#call

@mnelson mnelson closed this as completed Mar 23, 2015
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mnelson @forresty