rbtrace: like strace, but for ruby code
rbtrace shows you method calls happening inside another ruby process in real time.
rbtrace works on ruby 1.8 through 2.2 (and beyond), running on linux or mac osx.
rbtrace is designed to have minimal overhead, and should be safe to run in production.
usage
% gem install rbtrace
% rbtrace --help
supported Rubies
rbtrace supports all stable versions of Ruby MRI, as of 23-01-2018 this is Ruby version 2.2 and later.
tracer types
rbtrace has several different tracing modes.
firehose: show everything
% rbtrace -p <PID> --firehose
slow: show any method calls that take longer than <N> milliseconds
% rbtrace -p <PID> --slow=<N>
methods: trace calls to specific methods
% rbtrace -p <PID> --methods "Kernel#sleep" "Proc#call"
gc: trace garbage collections
% rbtrace -p <PID> --gc
memory: produce a basic memory report regarding process (including GC.stat and ObjectSpace stats)
% rbtrace -p <PID> --memory
backtraces: return backtraces for all active threads in a process
% rbtrace -p <PID> --backtraces
notes
--firehose is not reliable on osx.
--slow, --gc and --methods can be combined.
predefined tracers
rbtrace also includes a set of predefined tracers for popular ruby libraries and functions.
trace calls to activerecord adapters and any i/o functions
% rbtrace -p <PID> -c activerecord io
detailed example
require rbtrace into a process
% cat server.rb
require 'rbtrace'
class String
def multiply_vowels(num)
@test = 123
gsub(/[aeiou]/){ |m| m*num }
end
end
while true
proc {
Dir.chdir("/tmp") do
Dir.pwd
Process.pid
'hello'.multiply_vowels(3)
sleep rand*0.5
end
}.call
end
run the process
% ruby server.rb &
[1] 87854
trace a function using the process's pid
% rbtrace -p 87854 -m sleep
*** attached to process 87854
Kernel#sleep <0.138615>
Kernel#sleep <0.147726>
Kernel#sleep <0.318728>
Kernel#sleep <0.338173>
Kernel#sleep <0.373004>
Kernel#sleep
*** detached from process 87854
trace everything
% rbtrace -p 87854 --firehose
*** attached to process 87938
Kernel#proc <0.000082>
Proc#call
Dir.chdir
Dir.pwd <0.000060>
Process.pid <0.000021>
String#multiply_vowels
String#gsub
String#* <0.000023>
String#* <0.000022>
String#gsub <0.000127>
String#multiply_vowels <0.000175>
Kernel#rand <0.000018>
Float#* <0.000022>
Kernel#sleep <0.344281>
Dir.chdir <0.344858>
Proc#call <0.344908>
*** detached from process 87938
trace specific functions
% rbtrace -p 87854 -m sleep Dir.chdir Dir.pwd Process.pid "String#gsub" "String#*"
*** attached to process 87854
Dir.chdir
Dir.pwd <0.000023>
Process.pid <0.000008>
String#gsub
String#* <0.000008>
String#* <0.000007>
String#gsub <0.000050>
Kernel#sleep <0.498809>
Dir.chdir <0.499025>
Dir.chdir
Dir.pwd <0.000024>
Process.pid <0.000008>
String#gsub
String#* <0.000008>
String#* <0.000007>
String#gsub <0.000050>
Kernel#sleep
*** detached from process 87854
trace all functions in a class/module
% rbtrace -p 87854 -m "Kernel#"
*** attached to process 87854
Kernel#proc <0.000062>
Kernel#rand <0.000010>
Kernel#sleep <0.218677>
Kernel#proc <0.000016>
Kernel#rand <0.000010>
Kernel#sleep <0.195914>
Kernel#proc <0.000016>
Kernel#rand <0.000009>
Kernel#sleep
*** detached from process 87854
get values of variables and other expressions
% rbtrace -p 87854 -m "String#gsub(self, @test)" "String#*(self, __source__)" "String#multiply_vowels(self, self.length, num)"
*** attached to process 87854
String#multiply_vowels(self="hello", self.length=5, num=3)
String#gsub(self="hello", @test=123)
String#*(self="e", __source__="server.rb:6") <0.000020>
String#*(self="o", __source__="server.rb:6") <0.000018>
String#gsub <0.000085>
String#multiply_vowels <0.000198>
String#multiply_vowels(self="hello", self.length=5, num=3)
String#gsub(self="hello", @test=123)
String#*(self="e", __source__="server.rb:6") <0.000020>
String#*(self="o", __source__="server.rb:6") <0.000020>
String#gsub <0.000102>
String#multiply_vowels <0.000218>
*** detached from process 87854
watch for method calls slower than 250ms
% rbtrace -p 87854 --slow=250
*** attached to process 87854
Kernel#sleep <0.459628>
Dir.chdir <0.459828>
Proc#call <0.459849>
Kernel#sleep <0.484666>
Dir.chdir <0.484804>
Proc#call <0.484818>
*** detached from process 87854
todo
- correct irb implementation so it establishes a dedicated channel
- add triggers to start tracing slow methods only inside another method
- add watch expressions to fire tracers only when an expression is true
- add special expressions for method args (arg0, arguments)
- optimize local variable lookup to avoid instance_eval
- investigate mach_msg on osx since msgget(2) has hard kernel limits