Profiling Rails startup with DTrace
Dec 5, 2011 @ 1:07 pmTL;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" && 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" && 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