Getting 2x boot times using bootsnap

[guilleiguaran]

Importing from rails/rails#29313

Not sure what can I be doing wrong but adding bootsnap to my app doubles the loading time:

Without bootsnap:

~/src/app[master] % time bin/rails runner "puts Rails.env"
development
bin/rails runner "puts Rails.env"  10.34s user 3.74s system 56% cpu 24.864 total

With bootsnap:

~/src/app[master] % time bin/rails runner "puts Rails.env"
development
bin/rails runner "puts Rails.env"  7.22s user 1.69s system 17% cpu 51.722 total

I've tested this a dozen times getting similar numbers every time.

[guilleiguaran]

The output from ruby -v and uname:

 ~/src/cookpad[master] % ruby -v
ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-darwin16]

~/src/cookpad[master] % uname -msr
Darwin 16.5.0 x86_64

[burke]

Weird, that's pretty close to what I'm running on, so it must be some other environmental factor.

If you're using the require "bootsnap/setup" form, could you temporarily replace it with:

require 'bootsnap'
Bootsnap.setup(
  cache_dir:            'tmp/cache',
  development_mode:     true,
  disable_trace:        false,
  load_path_cache:      false,
  autoload_paths_cache: false,
  compile_cache_iseq:   false,
  compile_cache_yaml:   false
)

This should disable all features, and should make your boot time consistently similar to the time without bootsnap.

Then try toggling on the load_path_cache and autoload_paths_cache features to see if they make boot faster or slower.

Then do the same for the compile_cache_iseq and compile_cache_yaml features.

Once you've identified which pair of features is making it slower, see if you can isolate it to an individual one of them, or if it's both of them.

[guilleiguaran]

ok, reporting some results:

with all features disabled:

bin/rails runner "puts Rails.env"  10.17s user 3.92s system 51% cpu 27.452 total

load_path_cache: true, autoload_paths_cache: false

bin/rails runner "puts Rails.env"  7.78s user 0.98s system 51% cpu 17.012 total

load_path_cache: true, autoload_paths_cache: true

bin/rails runner "puts Rails.env"  8.09s user 0.96s system 51% cpu 17.679 total

compile_cache_iseq: true, compile_cache_yaml: false

bin/rails runner "puts Rails.env"  9.56s user 5.13s system 23% cpu 1:01.33 total

compile_cache_iseq: false, compile_cache_yaml: true

bin/rails runner "puts Rails.env"  9.66s user 3.97s system 49% cpu 27.367 total

Now, the best combination that I've found is enabling everything except compile_cache_iseq

bin/rails runner "puts Rails.env"  7.52s user 1.04s system 48% cpu 17.789 total

[guilleiguaran]

This confirm that RubyVM::InstructionSequence.load_from_binary is running slower in my case than loading directly the source, right?

[burke]

Can you replace lib/bootsnap/compile_cache/iseq.rb with the following, run it again with compile_cache_iseq enabled, and paste the last line it prints?:

require 'bootsnap/bootsnap'
require 'zlib'

module Bootsnap
  module CompileCache
    module ISeq
      class << self
        attr_accessor :cache_dir
      end

      $counts = { i2s: 0, s2o: 0, i2o: 0, uncompilable: 0 }
      at_exit { puts $counts.inspect }

      def self.input_to_storage(_, path)
        $counts[:i2s] += 1
        RubyVM::InstructionSequence.compile_file(path).to_binary
      rescue SyntaxError
        $counts[:uncompilable] += 1
        raise Uncompilable, 'syntax error'
      end

      def self.storage_to_output(binary)
        $counts[:s2o] += 1
        RubyVM::InstructionSequence.load_from_binary(binary)
      rescue RuntimeError => e
        if e.message == 'broken binary format'
          STDERR.puts "[Bootsnap::CompileCache] warning: rejecting broken binary"
          return nil
        else
          raise
        end
      end

      def self.input_to_output(_)
        $counts[:i2o] += 1
        nil # ruby handles this
      end

      module InstructionSequenceMixin
        def load_iseq(path)
          # Having coverage enabled prevents iseq dumping/loading.
          return nil if defined?(Coverage) && Bootsnap::CompileCache::Native.coverage_running?

          Bootsnap::CompileCache::Native.fetch(
            Bootsnap::CompileCache::ISeq.cache_dir,
            path.to_s,
            Bootsnap::CompileCache::ISeq
          )
        rescue RuntimeError => e
          if e.message =~ /unmatched platform/
            puts "unmatched platform for file #{path}"
          end
          raise
        end

        def compile_option=(hash)
          super(hash)
          Bootsnap::CompileCache::ISeq.compile_option_updated
        end
      end

      def self.compile_option_updated
        option = RubyVM::InstructionSequence.compile_option
        crc = Zlib.crc32(option.inspect)
        Bootsnap::CompileCache::Native.compile_option_crc32 = crc
      end

      def self.install!(cache_dir)
        Bootsnap::CompileCache::ISeq.cache_dir = cache_dir
        Bootsnap::CompileCache::ISeq.compile_option_updated
        class << RubyVM::InstructionSequence
          prepend InstructionSequenceMixin
        end
      end
    end
  end
end

[guilleiguaran]

This is the output replacing the code:

{:i2s=>0, :s2o=>3300, :i2o=>0, :uncompilable=>0}

[burke]

Huh, ok, can you change the definition of storage_to_output to:

      $t = 0
      at_exit { puts $t }
      def self.storage_to_output(binary)
        $counts[:s2o] += 1
        t=Time.now
        b = RubyVM::InstructionSequence.load_from_binary(binary)
        $t += (Time.now - t)
        b
      rescue RuntimeError => e
        if e.message == 'broken binary format'
          STDERR.puts "[Bootsnap::CompileCache] warning: rejecting broken binary"
          return nil
        else
          raise
        end
      end

[guilleiguaran]

ok, running the app a couple of times I got this:

during first run after of deleting cache:

~/src/cookpad[master] % time bin/rails runner "puts Rails.env"
development
0.47127000000000047
{:i2s=>3301, :s2o=>3301, :i2o=>0, :uncompilable=>0}
bin/rails runner "puts Rails.env"  9.46s user 2.72s system 43% cpu 27.728 total

during subsequent runs:

~/src/cookpad[master] % time bin/rails runner "puts Rails.env"
development
0.6067550000000022
{:i2s=>0, :s2o=>3301, :i2o=>0, :uncompilable=>0}
bin/rails runner "puts Rails.env"  6.49s user 1.60s system 16% cpu 48.926 total

[burke]

Oh wow, I wonder where that time is going then. Bizarre.

[jonleighton]

Hey, thanks for Bootsnap! I've also just tried it out today and experienced a similar issue - compile_cache_iseq makes things slower. This is with Ruby 2.4.4 in an Alpine Linux Docker container.

[rafaelfranca]

Yeah. I just experienced this at Shopify too. I'll try to isolate the cause but I believe RubyVM::InstructionSequence.load_from_binary is the cause.

[jonleighton]

Something I was pondering the other day is that maybe it is related to sharing the host's filesystem with the Docker container. I was trying this on Mac, and I know there is extra overhead on that platform. Might try to run some experiments when I get a chance.

[burke]

Yeah, we could probably document this better, but I would expect performance weirdness when mounting the cache FS over the network, since it would just double the number of network roundtrips. If time-to-access latency is the dominating concern, that would slow it down for sure.