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 and 1.9, running on linux or mac osx.
usage
% gem install rbtrace
% rbtrace --help
examples
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)" "String#*(self)" "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
- switch ipc to msgpack instead of csv
- add triggers to start tracing slow methods only inside another method
- optimize local variable lookup to avoid instance_eval
- use shared memory region for symbol table to avoid lookup on every event
- use another shm for class name lookup, and wipe on every GC
- investigate mach_msg on osx since msgget(2) has hard kernel limits