Gem object allocation

[sergey-alekseev]

According to http://blog.skylight.io/announcing-memory-traces/:

Allocating many objects can cause expensive garbage collection sweeps to become more frequent, slowing down the performance of your entire app.

However I found that skylight gem itself allocates a lot of objects. 75 times more than newrelic_rpm.

$ derailed bundle:objects

allocated memory by gem
-----------------------------------
  55716710  activesupport-4.1.11
  36911424  skylight-0.6.0
   9965675  mime-types-2.6.1
  ...

Are you going to reduce the amount of allocated objects or it's considered not a problem?

[halorgium]

Hi @sergey-alekseev, I actually ran into this also when I was looking at Skylight itself.
Can you confirm that derailed is not getting confused which gem is allocating the memory?
I noticed that any objects allocated during a require would be assigned to the skylight gem.

[sergey-alekseev]

I don't think derailed is getting confused. You could address this question to the gem's owner if you are in doubt.
To clarify: the output I provided is from my Rails app. The app has a lot of gems. You can see top 3 of them.

[halorgium]

@sergey-alekseev when i run derailed, i get reports of large allocations on a line where skylight is doing a require.

allocated memory by location
-----------------------------------
  38424112  /ruby/gems/2.2.0/gems/skylight-0.6.0/lib/skylight/probes.rb:81
   7094564  /ruby/gems/2.2.0/gems/activesupport-4.1.8/lib/active_support/dependencies.rb:247

retained memory by location
-----------------------------------
  16213911  /ruby/gems/2.2.0/gems/skylight-0.6.0/lib/skylight/probes.rb:81
   7094564  /ruby/gems/2.2.0/gems/activesupport-4.1.8/lib/active_support/dependencies.rb:247

Here is the line in the skylight gem. https://github.com/skylightio/skylight-ruby/blob/v0.6.0/lib/skylight/probes.rb#L81
It is also happening in active_support. https://github.com/rails/rails/blob/v4.1.8/activesupport/lib/active_support/dependencies.rb#L247

@schneems do you have any idea if this is mis-assigned or something?

[schneems]

That seems really high. @halorgium can you give me a gist with a Gemfile and a Gemfile.lock so I can try to reproduce the results?

[wagenet]

I just tried things out with a fresh Rails app: https://gist.github.com/wagenet/9d09e79b1cd73491c1c6.

Without Skylight:

Total allocated: 11529431 bytes (69456 objects)
Total retained:  4707976 bytes (10162 objects)

With Skylight:

Total allocated: 12593159 bytes (76139 objects)
Total retained:  5097052 bytes (11095 objects)

The top gems in terms of allocated memory are:

   7986282  sass-3.4.16
   1048414  skylight-0.6.1
    697534  tilt-1.4.1

@halorgium is out of town otherwise I'd pull him in on this for more clarification.

[schneems]

I just ran this under codetriage.com and don't even see skylight in my "top" list after adding "skylight" to the gemfile:

allocated memory by gem
-----------------------------------
   5704699  actionpack/lib
   3201880  activerecord/lib
   2398859  activesupport/lib
   1574349  actionview/lib
   1460372  codetriage/app
    300144  temple/lib
     32226  ruby-2.2.2/lib
     19511  rack-1.6.4
     18464  i18n-0.7.0
      6456  warden-1.2.3
      5520  arel-935796f4fd7d
      3373  omniauth-3c4b79504eb5
      2546  devise-3.5.1
      1432  railties/lib
       735  json-1.8.3
       432  thread_safe-0.3.5
       320  sprockets-rails-2.3.2
       224  fog-1.29.0
        80  sprockets-2.12.4

[lucasmazza]

noticed the same thing while running the derailed benchmarks, here is what I get on my application:

Measuring objects created by gems in groups [:default, "production"]
Total allocated: 38400472 bytes (256143 objects)
Total retained:  15116516 bytes (42717 objects)

allocated memory by gem
-----------------------------------
   8358784  skylight-0.8.0
   8072741  sass-3.4.17
   2738136  actionpack-4.2.3
   2541295  addressable-2.3.8

@schneems codetriage is running an old version of the skylight (0.1.8), and the probes.rb seems to be around since 0.6.2. With the latest skylight and derailed_benchmarks version with the codetriage app I get the following report.

$ bundle exec derailed bundle:objects
Measuring objects created by gems in groups [:default, "production"]
Total allocated: 50684430 bytes (357460 objects)
Total retained:  18894800 bytes (66039 objects)

allocated memory by gem
-----------------------------------
  29622493  skylight-0.8.0
   7294456  mime-types-2.6.1
   1988903  actionpack-4.2.3
   1482009  activesupport-4.2.3
   1161930  bundler-1.10.6
   1062599  devise-3.4.1
   1039028  mail-2.6.3

[wycats]

@lucasmazza @schneems The main thing that probes.rb does (new since the early days of 0.1.x) is that it hooks require. Is it possible that hooking require confuses derailed?

[schneems]

Maybe, we're doing some meta programming magic to hook into require: https://github.com/schneems/derailed_benchmarks/blob/master/lib/derailed_benchmarks/core_ext/kernel_require.rb

[schneems]

Just realized that require code I linked doesn't get called with bundle:objects only with bundle:mem I'm still not seeing the same behavior on codetriage with skylight 0.8 (although i'm running on rails master locally, don't think that matters)

2.2.3  ~/documents/projects/codetriage (master)
$ bundle list | grep skylight
  * skylight (0.8.0)
2.2.3  ~/documents/projects/codetriage (master)
$ bundle exec derailed bundle:mem | grep skylight
DEPRECATION WARNING: alias_method_chain is deprecated. Please, use Module#prepend instead. From module, you can access the original method using super. (called from <class:RouteSet> at /Users/richardschneeman/.gem/ruby/2.2.3/gems/devise-3.5.1/lib/devise/rails/routes.rb:27)
  skylight: 2.4648 MiB (Also required by: skylight/railtie)
    skylight/core: 2.3711 MiB
      skylight/native: 0.9336 MiB
      skylight/config: 0.3867 MiB
      skylight/util: 0.3164 MiB
2.2.3  ~/documents/projects/codetriage (master)
$ bundle exec derailed bundle:objects
Measuring objects created by gems in groups [:default, "production"]
DEPRECATION WARNING: alias_method_chain is deprecated. Please, use Module#prepend instead. From module, you can access the original method using super. (called from <class:RouteSet> at /Users/richardschneeman/.gem/ruby/2.2.3/gems/devise-3.5.1/lib/devise/rails/routes.rb:27)
Total allocated: 60877012 bytes (417687 objects)
Total retained:  22471047 bytes (78115 objects)

allocated memory by gem
-----------------------------------
  28948609  activesupport/lib
   7289724  mime-types-2.6.1
   3157155  mail-2.6.3
   2528371  actionpack/lib
   1287929  fog-core-1.30.0
   1175482  bundler-1.10.6
   1062092  excon-0.45.2
   1046841  devise-3.5.1
    926089  faraday-0.9.0
    876474  temple/lib
    829404  puma-2.11.0
    810381  actionmailer/lib
    802047  sass-3.2.19
    796270  resque-1.24.1
    729971  fog-1.29.0
    713746  ruby-2.2.3/lib
    674093  actionview/lib
    619081  dalli-2.7.0
    570510  httparty-0.11.0
    562350  erubis-2.7.0
    550573  oauth2-0.9.3
    542141  redis-namespace-1.3.0
    453307  redis-3.0.4
    410196  pg-0.18.2
    361970  kramdown-1.3.2
    354990  other
    270296  omniauth-oauth2-1.1.2
    247760  maildown-1.0.2
    215479  git_hub_bub-0.0.6
    204024  puma_auto_tune-08a727a1f16d
    189871  wicked-1.0.0
    171965  responders-2.1.0
    168354  omniauth-3c4b79504eb5
    165261  multi_json-1.11.2
    162620  slim-3.0.6
    150851  skylight-0.8.0

[wagenet]

So the actual code generating this information is ObjectSpace via the memory_profiler gem. When I run derailed bundle:objects against our Rails app, I get the following:

allocated memory by gem
-----------------------------------
  41178014  skylight

allocated memory by location
-----------------------------------
  41120969  .../skylight/lib/skylight/probes.rb:81

Where line 81 is: https://github.com/skylightio/skylight-ruby/blob/v0.8.0/lib/skylight/probes.rb#L81.

So basically the issue is just that technically, a bunch of the requires are taking place in Skylight itself, even though they were requested from elsewhere. Skylight isn't allocating this memory itself. Running derailed bundle:mem is much more accurate.

[wagenet]

It's worth noting that, if I take this line out, I end up with the following at the top:

allocated memory by location
-----------------------------------
  47937896  .../activesupport-4.2.3/lib/active_support/dependencies.rb:274

This then points to a place where Rails overwrites the require method. Basically, if anyone is overwriting require this benchmarking becomes inaccurate.

[wagenet]

To provide further detail, one can see the line where the "source file" is being obtained here: https://github.com/SamSaffron/memory_profiler/blob/master/lib/memory_profiler/reporter.rb#L93. memory_profiler is using ObjectSpace.allocation_sourcefile which returns the line at which the actual require happened. Again, since we're overwriting require it's pointing to the spot where we call the original require. However, this is not the spot that originates the require call.

[chancancode]

This appears to be a bug in Ruby, see https://bugs.ruby-lang.org/issues/11490

[chancancode]

Anyhow, I should also point out that all of these allocation/memory usage analysis are describing what happens at load-time (when your app boots). While this is a useful information to know, it doesn't actually directly affect your runtime performance and is completely different from what the blog post describes (and what Skylight tells you about).

[schneems]

@chancancode Thanks for the script and the bug report to Ruby. It does look like this is an issue with Ruby's ObjectSpace, maybe @SamSaffron has seen it before? These two methods bundle:mem and bundle:objects are designed to look for boot time memory. It's still a very relevant measure for cutting down overall memory use like was done with the mail gem and mime/types. I did whole talk about it 😉

It's still strange I wasn't able to see this behavior in codetriage.

[chancancode]

@schneems I think the top line (activesupport/lib) is still "wrong", it probably points to the AS dependencies line Peter mentioned?

There seems to be more to this bug, because both the Skylight patch and the Rails patch are most likely calling another Ruby-land implementation of require (Bundler or RubyGems?)

[wagenet]

In my personal experience, ObjectSpace only tracked the location from which the original Ruby require method is called. When you overwrite it, you're essentially moving the location of the original. I'm not sure if we should expect ObjectSpace to be able to track back to the original source. What if you changed the name of the method while you were at it or something else funny?

[chancancode]

@wagenet it's definitely designed to track the source of the allocations (so that you can fix them like Richard did) by taking a snapshot of the information at allocation time (which is why it's slow and you probably won't want to run it in production, I think objspace advise against that). It actually does this successfully most of the time if you look at the output part of my gist (especially if it's actually allocated in Ruby-land)

[wagenet]

After further investigation, I've determined that the blame falls on the file that calls the built-in require method. If you're not using Bundler, this will be rubygems/ext/kernel_require.rb. However, Bundler reverses this change, restoring the original require behavior. ActiveSupport also overrides this method, but it does so on Object calling super to get the original. In Skylight, we were overriding on Kernel which meant we took precedence over ActiveSupport. Without Skylight (or if Skylight is changed to override Object instead), ActiveSupport again takes the blame.

[wagenet]

@schneems I think this means that both memory_profiler and derailed are of limited use for tracking down allocation sources in the event that ActiveSupport is being used. /cc @SamSaffron

[wycats]

@wagenet memory_profiler seems pretty useful in general, and indeed, @schneems used it to find an actual issue in the first place!

Generally speaking, memory_profiler is used to track runtime allocations, which would not be subject to this problem. When tracking require-time performance, most of the allocations it's reporting are VM junk created to build up code structures in memory, so it can mostly be ignored.

@schneems originally used it to discover require-time garbage that was not associated with code structures, which is pretty useful!

The fact that the VM junk is incorrectly attributed to Skylight (or ActiveSupport, or Rubygems) is an issue, but so is counting VM junk in the first place, which makes derailed a power tool for people like @schneems who really know what they're looking for.

[wagenet]

I wasn't intending to imply that derailed and memory_profiler weren't useful overall, just that it the usefulness is limited in this specific situation. I didn't state that clearly enough.