Profiling Rails startup with DTrace

TL;DR: I’m adding DTrace probes to Ruby, and I used those to make a 6% performance improvement to rake environment. ruby*:::function-entry { printf("-> %s::%s (%s:%d)\n", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3); } $ sudo dtrace -q -s calls.d -c'rake environment' -> Module::local_constant_names (/Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb:85) -> Module::local_constants (/Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb:78) -> Module::constants (/Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb:79) -> Array::map (/Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb:86) -> Symbol::to_s (/Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb:86) ruby*:::function-entry { @[copyinstr(arg0), copyinstr(arg1)] = count(); } $ sudo dtrace -q -s calls.d -c'rake environment' Class core#define_method 6332 Symbol == 6612 Module method_added 9329 Kernel hash 9437 Array hash 11966 Array each 13101 Fixnum ^ 15540 Module === 20267 String hash 37878 Symbol to_s 214691 $ ruby*:::function-entry { @[copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3] = count(); } $ sudo dtrace -q -s calls.d -c'rake environment' Gem::Dependency requirement /Users/aaron/.local/lib/ruby/1.9.1/rubygems/dependency.rb 98 4641 Array hash /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1308 4697 Bundler::DepProxy method_missing /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/bundler-1.0.21/lib/bundler/rubygems_ext.rb 194 4809 BasicObject == /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1334 5610 Kernel === /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1334 5610 Module === /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1334 5940 Array hash /Users/aaron/.local/lib/ruby/1.9.1/rubygems/requirement.rb 135 6001 Fixnum ^ /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1308 11078 String hash /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1308 31209 Symbol to_s /Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb 86 208900 $ def local_constants #:nodoc: constants(false) end # Returns the names of the constants defined locally rather than the # constants themselves. See <tt>local_constants</tt>;. def local_constant_names local_constants.map { |c| c.to_s } end ruby*:::function-entry { k = copyinstr(arg0); m = copyinstr(arg1); } tick-5000hz /k != 0/ { @[k, m] = count(); } $ sudo dtrace -q -s calls.d -c'rake environment' Module method_added 329 Fixnum ^ 330 Mutex unlock 355 String hash 477 Array - 671 Module constants 779 Kernel require 2262 IO set_encoding 3713 Symbol to_s 4095 Kernel ` 4122 $ ruby*:::function-entry /copyinstr(arg0) == "Kernel" &amp;&amp; copyinstr(arg1) == "`"/ { @[copyinstr(arg2)] = count(); } $ sudo dtrace -q -s calls.d -c'rake environment' /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/bundler-1.0.21/lib/bundler.rb 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/coffee-rails-2120408a4063/coffee-rails.gemspec 3 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/sass-rails-3c24e4fd8dd3/sass-rails.gemspec 3 /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/execjs-1.2.9/lib/execjs/external_runtime.rb 5 $ ruby*:::function-entry /copyinstr(arg0) == "Kernel" && copyinstr(arg1) == "`"/ { self->time = timestamp; } ruby*:::function-return /copyinstr(arg0) == "Kernel" && copyinstr(arg1) == "`"/ { this->took = (timestamp - self->time) / 1000000; @[copyinstr(arg2)] = sum(this->took); @total = sum(this->took); } END { printf("Time per file:\n"); printa(@); printf("\nTOTAL: "); printa(@total); } $ time sudo dtrace -q -s calls.d -c'rake environment' Time per file: /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/bundler-1.0.21/lib/bundler.rb 15 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/coffee-rails-2120408a4063/coffee-rails.gemspec 246 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/sass-rails-3c24e4fd8dd3/sass-rails.gemspec 267 /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/execjs-1.2.9/lib/execjs/external_runtime.rb 398 TOTAL: 926 real 0m7.942s user 0m4.052s sys 0m2.909s $ ruby*:::function-entry /copyinstr(arg0) == "Kernel" &amp;&amp; copyinstr(arg1) == "`"/ { @[copyinstr(arg2), arg3] = count(); } /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/coffee-rails-2120408a4063/coffee-rails.gemspec 19 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/coffee-rails-2120408a4063/coffee-rails.gemspec 20 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/coffee-rails-2120408a4063/coffee-rails.gemspec 21 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/sass-rails-3c24e4fd8dd3/sass-rails.gemspec 22 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/sass-rails-3c24e4fd8dd3/sass-rails.gemspec 23 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/bundler/gems/sass-rails-3c24e4fd8dd3/sass-rails.gemspec 24 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/bundler-1.0.21/lib/bundler.rb 209 1 /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/execjs-1.2.9/lib/execjs/external_runtime.rb 150 5 s.files = `git ls-files`.split("\n") s.test_files = `git ls-files -- {test,spec,features}/*`.split("\n") s.executables = `git ls-files -- bin/*`.split("\n").map{ |f| File.basename(f) } def requires_sudo? return @requires_sudo if defined?(@checked_for_sudo) && @checked_for_sudo path = bundle_path path = path.parent until path.exist? sudo_present = !(`which sudo` rescue '').empty? @checked_for_sudo = true @requires_sudo = settings.allow_sudo? && !File.writable?(path) && sudo_present end def which(cmd) if File.executable? cmd cmd else path = ENV['PATH'].split(File::PATH_SEPARATOR).find { |path| File.executable? File.join(path, cmd) } path && File.expand_path(cmd, path) end end def requires_sudo? # ... sudo_present = which "sudo" # ... end require 'rubygems' require 'benchmark/ips' def sand_which cmd `which #{cmd}` end def blair_which cmd if File.executable? cmd cmd else path = ENV['PATH'].split(File::PATH_SEPARATOR).find { |path| File.executable? File.join(path, cmd) } path && File.expand_path(cmd, path) end end Benchmark.ips do |x| x.report("sand") { sand_which 'sudo' } x.report("blair") { blair_which 'sudo' } end $ ruby lol.rb sand 251.0 (±4.8%) i/s - 1265 in 5.051489s (cycle=23) blair 3222.0 (±8.2%) i/s - 16218 in 5.076616s (cycle=306) $ def which(command) Array(command).each do |name| name, args = name.split(/\s+/, 2) result = if ExecJS.windows? `#{shell_escape("#{ExecJS.root}/support/which.bat", name)}` else `#{shell_escape('command', '-v', name)} 2>/dev/null` end if path = result.strip.split("\n").first return args ? "#{path} #{args}" : path end end nil end lib/execjs/external_runtime.rb:134:in `locate_binary' lib/execjs/external_runtime.rb:97:in `initialize' lib/execjs/runtimes.rb:37:in `new' lib/execjs/runtimes.rb:37:in `<module:Runtimes>' lib/execjs/runtimes.rb:9:in `<module:ExecJS>' lib/execjs/runtimes.rb:8:in `<top (required)>' lib/execjs.rb:2:in `require' lib/execjs.rb:2:in `<top (required)>' def initialize(options) @name = options[:name] @command = options[:command] @runner_path = options[:runner_path] @test_args = options[:test_args] @test_match = options[:test_match] @encoding = options[:encoding] @binary = locate_binary end protected def locate_binary if binary = which(@command) if @test_args output = `#{shell_escape(binary, @test_args)} 2>&1` binary if output.match(@test_match) else binary end end end module ExecJS module Runtimes # ... Node = ExternalRuntime.new( :name => "Node.js (V8)", :command => ["nodejs", "node"], :runner_path => ExecJS.root + "/support/node_runner.js", :encoding => 'UTF-8' ) # ... end end diff --git a/lib/execjs/external_runtime.rb b/lib/execjs/external_runtime.rb index a8180d1..65f46f9 100644 --- a/lib/execjs/external_runtime.rb +++ b/lib/execjs/external_runtime.rb @@ -94,7 +94,7 @@ module ExecJS @test_args = options[:test_args] @test_match = options[:test_match] @encoding = options[:encoding] - @binary = locate_binary + @binary = nil end def exec(source) @@ -113,16 +113,21 @@ module ExecJS def available? require "multi_json" - @binary ? true : false + binary ? true : false end + private + def binary + @binary ||= locate_binary + end + protected def runner_source @runner_source ||= IO.read(@runner_path) end def exec_runtime(filename) - output = sh("#{shell_escape(*(@binary.split(' ') << filename))} 2>&1") + output = sh("#{shell_escape(*(binary.split(' ') << filename))} 2>&1") if $?.success? output else $ sudo dtrace -q -s calls.d -c'rake environment' /Users/aaron/.local/lib/ruby/gems/1.9.1/gems/execjs-1.2.9/lib/execjs/external_runtime.rb 155 3 $ diff --git a/lib/execjs/external_runtime.rb b/lib/execjs/external_runtime.rb index 65f46f9..88a08ce 100644 --- a/lib/execjs/external_runtime.rb +++ b/lib/execjs/external_runtime.rb @@ -121,6 +121,22 @@ module ExecJS @binary ||= locate_binary end + def which_windows(name) + result = `#{shell_escape("#{ExecJS.root}/support/which.bat", name)}` + result.strip.split("\n").first + end + + def which_unix(name) + if File.executable? cmd + cmd + else + path = ENV['PATH'].split(File::PATH_SEPARATOR).find { |path| + File.executable? File.join(path, cmd) + } + path && File.expand_path(cmd, path) + end + end + protected def runner_source @runner_source ||= IO.read(@runner_path) @@ -147,19 +163,14 @@ module ExecJS end def which(command) - Array(command).each do |name| + Array(command).find do |name| name, args = name.split(/\s+/, 2) - result = if ExecJS.windows? - `#{shell_escape("#{ExecJS.root}/support/which.bat", name)}` - else - `#{shell_escape('command', '-v', name)} 2>/dev/null` - end + path = ExecJS.windows? ? which_windows(name) : which_unix(name) - if path = result.strip.split("\n").first - return args ? "#{path} #{args}" : path - end + next unless path + + args ? "#{path} #{args}" : path end - nil end if "".respond_to?(:force_encoding) $ time rake environment real 0m2.377s user 0m2.028s sys 0m0.320s $ time rake environment real 0m2.224s user 0m1.946s sys 0m0.260s $ sudo dtrace -q -s calls.d -c'rake environment' Module === 306 Mutex unlock 324 Fixnum ^ 353 Module method_added 368 Array - 509 String hash 603 Module constants 859 Kernel require 2292 IO set_encoding 3371 Symbol to_s 4561 $ sudo dtrace -q -s calls.d -c'rake environment' Array hash /Users/aaron/.local/lib/ruby/1.9.1/rubygems/requirement.rb 255 Mutex unlock <internal:prelude> 365 Fixnum ^ /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 493 Array - /Users/aaron/git/rails/activesupport/lib/active_support/dependencies.rb 507 IO set_encoding /Users/aaron/.local/lib/ruby/1.9.1/rubygems/custom_require.rb 636 Module constants /Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb 841 IO set_encoding /Users/aaron/git/rails/activesupport/lib/active_support/dependencies.rb 1098 String hash /Users/aaron/.local/lib/ruby/1.9.1/rubygems/specification.rb 1188 Kernel require /Users/aaron/git/rails/activesupport/lib/active_support/dependencies.rb 1253 Symbol to_s /Users/aaron/git/rails/activesupport/lib/active_support/core_ext/module/introspection.rb 8981