Skip to content

Instantly share code, notes, and snippets.

Show Gist options
  • Save krasnoukhov/a036bb7bc8c8416e9481 to your computer and use it in GitHub Desktop.
Save krasnoukhov/a036bb7bc8c8416e9481 to your computer and use it in GitHub Desktop.
Profiling memory leaky Sidekiq applications with Ruby 2.1

My largest Sidekiq application had a memory leak and I was able to find and fix it in just few hours spent on analyzing Ruby's heap. In this post I'll show my profiling setup.

As you might know Ruby 2.1 introduced a few great changes to ObjectSpace, so now it's much easier to find a line of code that is allocating too many objects. Here is great post explaining how it's working.

I was too lazy to set up some seeding and run it locally, so I checked that test suite passes when profiling is enabled and pushed debugging to production. Production environment also suited me better since my jobs data can't be fully random generated.

So, in order to profile your worker, add this to your Sidekiq configuration:

if ENV["PROFILE"]
  require "objspace"
  ObjectSpace.trace_object_allocations_start
  Sidekiq.logger.info "allocations tracing enabled"

  module Sidekiq
    module Middleware
      module Server
        class Profiler
          # Number of jobs to process before reporting
          JOBS = 100

          class << self
            mattr_accessor :counter
            self.counter = 0

            def synchronize(&block)
              @lock ||= Mutex.new
              @lock.synchronize(&block)
            end
          end

          def call(worker_instance, item, queue)
            begin
              yield
            ensure
              self.class.synchronize do
                self.class.counter += 1

                if self.class.counter % JOBS == 0
                  Sidekiq.logger.info "reporting allocations after #{self.class.counter} jobs"
                  GC.start
                  ObjectSpace.dump_all(output: File.open("heap.json", "w"))
                  Sidekiq.logger.info "heap saved to heap.json"
                end
              end
            end
          end
        end
      end
    end
  end

  Sidekiq.configure_server do |config|
    config.server_middleware do |chain|
      chain.add Sidekiq::Middleware::Server::Profiler
    end
  end
end

Adjust number of jobs you want your worker to process before you have heap dumped.
Run a sample worker: PROFILE=1 sidekiq -C config/sidekiq.yml and wait for jobs to be processed.

After you have heap.json, analyze it by running something like this:

cat heap.json |
    ruby -rjson -ne ' obj = JSON.parse($_).values_at("file","line","type"); puts obj.join(":") if obj.first ' |
    sort      |
    uniq -c   |
    sort -n   |
    tail -20

You'll see a list of objects of specific types that are allocated on specific lines, sorted by objects count, for example:

  460 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/dirty.rb:368:DATA
  460 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/fields.rb:388:DATA
  460 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/fields.rb:414:DATA
  460 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/fields.rb:436:DATA
  460 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/fields.rb:456:DATA
  472 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/concern.rb:115:ICLASS
  527 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/dependencies.rb:469:NODE
  529 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/class/attribute.rb:79:NODE
  573 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/array/wrap.rb:41:ARRAY
  606 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/dependencies.rb:469:ARRAY
  724 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/concern.rb:114:ICLASS
  844 /home/whatever/.rvm/gems/ruby-2.1.0/gems/journey-1.0.4/lib/journey/parser.rb:139:OBJECT
  861 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/dependencies.rb:469:DATA
 1147 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/dependencies.rb:469:STRING
 1165 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/extensions/module.rb:22:STRING
 1242 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/class/attribute.rb:74:ARRAY
 1281 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/class/attribute.rb:81:DATA
 2083 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/class/attribute.rb:74:NODE
 2429 /home/whatever/.rvm/gems/ruby-2.1.0/bundler/gems/mongoid-3.1.6/lib/mongoid/extensions/module.rb:22:DATA
 3325 /home/whatever/.rvm/gems/ruby-2.1.0/gems/activesupport-3.2.16/lib/active_support/core_ext/class/attribute.rb:74:DATA

Repeat this action after more jobs are processed. If you see a constantly growing objects count somewhere, this is probably your leak.

@tsyber1an
Copy link

🍰

@cmrd-senya
Copy link

For me heap.json was cut because File.close method wasn't called on the File object. Adding File.close fixed it.

@krtschmr
Copy link

  259 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/core_ext/class/attribute.rb:84:NODE
    270 /home/tim/.rvm/gems/ruby-2.1.6/gems/activemodel-4.2.5/lib/active_model/attribute_methods.rb:383:ARRAY
    270 /home/tim/.rvm/gems/ruby-2.1.6/gems/activemodel-4.2.5/lib/active_model/attribute_methods.rb:383:DATA
    270 /home/tim/.rvm/gems/ruby-2.1.6/gems/activemodel-4.2.5/lib/active_model/attribute_methods.rb:383:NODE
    288 /home/tim/.rvm/gems/ruby-2.1.6/gems/activerecord-4.2.5/lib/active_record/type/type_map.rb:35:DATA
    320 /home/tim/.rvm/gems/ruby-2.1.6/gems/activerecord-4.2.5/lib/active_record/type/type_map.rb:30:DATA
    320 /home/tim/.rvm/gems/ruby-2.1.6/gems/arel-6.0.3/lib/arel/visitors/visitor.rb:16:STRING
    338 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/dependencies.rb:457:STRING
    371 /home/tim/.rvm/gems/ruby-2.1.6/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:258:STRING
    371 /home/tim/.rvm/gems/ruby-2.1.6/gems/binding_of_caller-0.7.2/lib/binding_of_caller/mri2.rb:25:STRING
    385 /home/tim/.rvm/gems/ruby-2.1.6/gems/json-1.8.3/lib/json/common.rb:155:STRING
    469 /home/tim/.rvm/gems/ruby-2.1.6/gems/activerecord-4.2.5/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:238:OBJECT
    498 /home/tim/.rvm/gems/ruby-2.1.6/gems/better_errors-2.1.1/lib/better_errors/exception_extension.rb:6:DATA
    777 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/core_ext/class/attribute.rb:86:DATA
    968 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/dependencies.rb:274:ARRAY
   1505 /home/tim/.rvm/gems/ruby-2.1.6/gems/activerecord-4.2.5/lib/active_record/connection_adapters/mysql2_adapter.rb:57:STRING
   1979 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/dependencies.rb:274:NODE
   2122 /home/tim/.rvm/gems/ruby-2.1.6/gems/binding_of_caller-0.7.2/lib/binding_of_caller/mri2.rb:21:DATA
   2220 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/dependencies.rb:274:DATA
   3410 /home/tim/.rvm/gems/ruby-2.1.6/gems/activesupport-4.2.5/lib/active_support/dependencies.rb:274:STRING

but actually no idea how this might help me with optimizing my jobs.

@rohanmendon
Copy link

🍰

@DCrow
Copy link

DCrow commented Jul 11, 2018

You should change

  ObjectSpace.dump_all(output: File.open("heap.json", "w"))

to

  file = File.open("heap.json", "w")
  ObjectSpace.dump_all(output: file)
  flie.close

If you don't close the file, sometimes the end will be corrupted.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment