Commit 9d812f26 authored by Aaron Quint's avatar Aaron Quint

Merge branch 'master' of git://github.com/tmm1/rbtrace into fix_evalify

parents 436fcd78 3e3b1381
PATH
remote: .
specs:
rbtrace (0.4.2)
rbtrace (0.4.3)
ffi (>= 1.0.6)
msgpack (>= 0.4.3)
trollop (>= 1.16.2)
......
This diff is collapsed.
require 'trollop'
require 'rbtrace/rbtracer'
class RBTraceCLI
# Suggest increasing the maximum number of bytes allowed on
# a message queue to 1MB.
#
# This defaults to 16k on Linux, and is hardcoded to 2k in OSX kernel.
#
# Returns nothing.
def self.check_msgmnb
if File.exists?(msgmnb = "/proc/sys/kernel/msgmnb")
curr = File.read(msgmnb).to_i
max = 1024*1024
cmd = "sysctl kernel.msgmnb=#{max}"
if curr < max
if Process.uid == 0
STDERR.puts "*** running `#{cmd}` for you to prevent losing events (currently: #{curr} bytes)"
system(cmd)
else
STDERR.puts "*** run `sudo #{cmd}` to prevent losing events (currently: #{curr} bytes)"
end
end
end
end
# Look for any message queues pairs (pid/-pid) that no longer have an
# associated process alive, and remove them.
#
# Returns nothing.
def self.cleanup_queues
if (pids = `ps ax -o pid`.split("\n").map{ |p| p.strip.to_i }).any?
ipcs = `ipcs -q`.split("\n").grep(/^(q|0x)/).map{ |line| line[/(0x[a-f0-9]+)/,1] }
ipcs.each do |ipci|
next if ipci.match(/^0xf/)
qi = ipci.to_i(16)
qo = 0xffffffff - qi + 1
ipco = "0x#{qo.to_s(16)}"
if ipcs.include?(ipco) and !pids.include?(qi)
STDERR.puts "*** removing stale message queue pair: #{ipci}/#{ipco}"
system("ipcrm -Q #{ipci} -Q #{ipco}")
end
end
end
end
def self.run
check_msgmnb
cleanup_queues
parser = Trollop::Parser.new do
version <<-EOS
rbtrace: like strace, but for ruby code
version 0.4.3
(c) 2013 Aman Gupta (tmm1)
http://github.com/tmm1/rbtrace
EOS
banner <<-EOS
rbtrace shows you method calls happening inside another ruby process in real time.
to use rbtrace, simply `require "rbtrace"` in your ruby app.
for examples and more information, see http://github.com/tmm1/rbtrace
Usage:
rbtrace --exec <CMD> # run and trace <CMD>
rbtrace --pid <PID+> # trace the given process(es)
rbtrace --ps <CMD> # look for running <CMD> processes to trace
rbtrace -o <FILE> # write output to file
rbtrace -t # show method call start time
rbtrace -n # hide duration of each method call
rbtrace -r 3 # use 3 spaces to nest method calls
Tracers:
rbtrace --firehose # trace all method calls
rbtrace --slow=250 # trace method calls slower than 250ms
rbtrace --methods a b c # trace calls to given methods
rbtrace --gc # trace garbage collections
rbtrace -c io # trace common input/output functions
rbtrace -c eventmachine # trace common eventmachine functions
rbtrace -c my.tracer # trace all methods listed in my.tracer
Method Selectors:
sleep # any instance or class method named sleep
String#gsub # specific instance method
Process.pid # specific class method
Dir. # any class methods in Dir
Fixnum# # any instance methods of Fixnum
Trace Expressions:
method(self) # value of self at method invocation
method(@ivar) # value of given instance variable
method(arg1, arg2) # value of argument local variables
method(self.attr) # value of arbitrary ruby expression
method(__source__) # source file/line of callsite
All Options:\n
EOS
opt :exec,
"spawn new ruby process and attach to it",
:type => :strings,
:short => nil
opt :pid,
"pid of the ruby process to trace",
:type => :ints,
:short => '-p'
opt :ps,
"find any matching processes to trace",
:type => :string,
:short => nil
opt :firehose,
"show all method calls",
:short => '-f'
opt :slow,
"watch for method calls slower than 250 milliseconds",
:default => 250,
:short => '-s'
opt :slowcpu,
"watch for method calls slower than 250 milliseconds (cpu time only)",
:default => 250,
:short => nil
opt :slow_methods,
"method(s) to restrict --slow to",
:type => :strings
opt :methods,
"method(s) to trace (valid formats: sleep String#gsub Process.pid Kernel# Dir.)",
:type => :strings,
:short => '-m'
opt :gc,
"trace garbage collections"
opt :start_time,
"show start time for each method call",
:short => '-t'
opt :no_duration,
"hide time spent in each method call",
:default => false,
:short => '-n'
opt :output,
"write trace to filename",
:type => String,
:short => '-o'
opt :append,
"append to output file instead of overwriting",
:short => '-a'
opt :prefix,
"prefix nested method calls with N spaces",
:default => 2,
:short => '-r'
opt :config,
"config file",
:type => :strings,
:short => '-c'
opt :devmode,
"assume the ruby process is reloading classes and methods"
opt :fork,
"fork a copy of the process for debugging (so you can attach gdb.rb)"
opt :eval,
"evaluate a ruby expression in the process",
:type => String,
:short => '-e'
opt :backtrace,
"get lines from the current backtrace in the process",
:type => :int
opt :wait,
"seconds to wait before attaching to process",
:default => 0,
:short => nil
opt :timeout,
"seconds to wait before giving up on attach/detach",
:default => 5
end
opts = Trollop.with_standard_exception_handling(parser) do
raise Trollop::HelpNeeded if ARGV.empty?
parser.stop_on '--exec'
parser.parse(ARGV)
end
if ARGV.first == '--exec'
ARGV.shift
opts[:exec_given] = true
opts[:exec] = ARGV.dup
ARGV.clear
end
unless %w[ fork eval backtrace slow slowcpu firehose methods config gc ].find{ |n| opts[:"#{n}_given"] }
$stderr.puts "Error: --slow, --slowcpu, --gc, --firehose, --methods or --config required."
$stderr.puts "Try --help for help."
exit(-1)
end
if opts[:fork_given] and opts[:pid].size != 1
parser.die :fork, '(can only be invoked with one pid)'
end
if opts[:exec_given]
if opts[:pid_given]
parser.die :exec, '(cannot exec and attach to pid)'
end
if opts[:fork_given]
parser.die :fork, '(cannot fork inside newly execed process)'
end
end
methods, smethods = [], []
if opts[:methods_given]
methods += opts[:methods]
end
if opts[:slow_methods_given]
smethods += opts[:slow_methods]
end
if opts[:config_given]
Array(opts[:config]).each do |config|
file = [
config,
File.expand_path("../../tracers/#{config}.tracer", __FILE__)
].find{ |f| File.exists?(f) }
unless file
parser.die :config, '(file does not exist)'
end
File.readlines(file).each do |line|
line.strip!
next if line =~ /^#/
next if line.empty?
methods << line
end
end
end
tracee = nil
if opts[:ps_given]
list = `ps aux`.split("\n")
filtered = list.grep(Regexp.new opts[:ps])
filtered.reject! do |line|
line =~ /^\w+\s+(#{Process.pid}|#{Process.ppid})\s+/ # cannot trace self
end
if filtered.size > 0
max_len = filtered.size.to_s.size
STDERR.puts "*** found #{filtered.size} processes matching #{opts[:ps].inspect}"
filtered.each_with_index do |line, i|
STDERR.puts " [#{(i+1).to_s.rjust(max_len)}] #{line.strip}"
end
STDERR.puts " [#{'0'.rjust(max_len)}] all #{filtered.size} processes"
while true
STDERR.sync = true
STDERR.print "*** trace which processes? (0/1,4): "
begin
input = gets
rescue Interrupt
exit 1
end
if input =~ /^(\d+,?)+$/
if input.strip == '0'
pids = filtered.map do |line|
line.split[1].to_i
end
else
indices = input.split(',').map(&:to_i)
pids = indices.map do |i|
if i > 0 and line = filtered[i-1]
line.split[1].to_i
end
end
end
unless pids.include?(nil)
opts[:pid] = pids
break
end
end
end
else
STDERR.puts "*** could not find any processes matching #{opts[:ps].inspect}"
exit 1
end
end
if opts[:exec_given]
tracee = fork{
Process.setsid
ENV['RUBYOPT'] = "-r#{File.expand_path('../../lib/rbtrace',__FILE__)}"
exec(*opts[:exec])
}
STDERR.puts "*** spawned child #{tracee}: #{opts[:exec].inspect[1..-2]}"
if (secs = opts[:wait]) > 0
STDERR.puts "*** waiting #{secs} seconds for child to boot up"
sleep secs
end
elsif opts[:pid].size <= 1
tracee = opts[:pid].first
else
tracers = []
opts[:pid].each do |pid|
if child = fork
tracers << child
else
Process.setpgrp
STDIN.reopen '/dev/null'
$0 = "rbtrace -p #{pid} (parent: #{Process.ppid})"
opts[:output] += ".#{pid}" if opts[:output]
tracee = pid
# fall through and start tracing
break
end
end
if tracee.nil?
# this is the parent
while true
begin
break if tracers.empty?
if pid = Process.wait
tracers.delete(pid)
end
rescue Interrupt, SignalException
STDERR.puts "*** waiting on child tracers: #{tracers.inspect}"
tracers.each do |pid|
begin
Process.kill 'INT', pid
rescue Errno::ESRCH
end
end
end
end
exit!
end
end
if out = opts[:output]
output = File.open(out, opts[:append] ? 'a+' : 'w')
output.sync = true
end
begin
begin
tracer = RBTracer.new(tracee)
rescue ArgumentError => e
parser.die :pid, "(#{e.message})"
end
if opts[:fork_given]
pid = tracer.fork
STDERR.puts "*** forked off a busy looping copy at #{pid} (make sure to kill -9 it when you're done)"
elsif opts[:backtrace_given]
num = opts[:backtrace]
code = "caller.first(#{num}).join('|')"
if res = tracer.eval(code)
tracer.puts res[1..-2].split('|').join("\n ")
end
elsif opts[:eval_given]
if res = tracer.eval(code = opts[:eval])
tracer.puts ">> #{code}"
tracer.puts "=> #{res}"
end
else
tracer.out = output if output
tracer.timeout = opts[:timeout] if opts[:timeout] > 0
tracer.prefix = ' ' * opts[:prefix]
tracer.show_time = opts[:start_time]
tracer.show_duration = !opts[:no_duration]
tracer.devmode if opts[:devmode_given]
tracer.gc if opts[:gc_given]
if opts[:firehose_given]
tracer.firehose
else
tracer.add(methods) if methods.any?
if opts[:slow_given] || opts[:slowcpu_given]
tracer.watch(opts[:slowcpu_given] ? opts[:slowcpu] : opts[:slow], opts[:slowcpu_given])
tracer.add_slow(smethods) if smethods.any?
end
end
begin
tracer.recv_loop
rescue Interrupt, SignalException
end
end
ensure
if tracer
tracer.detach
end
if opts[:exec_given]
STDERR.puts "*** waiting on spawned child #{tracee}"
Process.kill 'TERM', tracee
Process.waitpid(tracee)
end
end
end
end
class String
alias :bytesize :size
end unless ''.respond_to?(:bytesize)
module FFI::LastError
Errnos = Errno::constants.map(&Errno.method(:const_get)).inject({}) do |hash, c|
hash[ c.const_get(:Errno) ] = c
hash
end
def self.exception
Errnos[error]
end
def self.raise(msg=nil)
Kernel.raise exception, msg
end
end
require 'ffi'
module MsgQ
extend FFI::Library
ffi_lib FFI::CURRENT_PROCESS
class EventMsg < FFI::Struct
BUF_SIZE = RUBY_PLATFORM =~ /linux/ ? 256 : 120
IPC_NOWAIT = 004000
layout :mtype, :long,
:buf, [:char, BUF_SIZE]
def self.send_cmd(q, str)
msg = EventMsg.new
msg[:mtype] = 1
msg[:buf].to_ptr.put_string(0, str)
ret = MsgQ.msgsnd(q, msg, BUF_SIZE, 0)
FFI::LastError.raise if ret == -1
end
def self.recv_cmd(q, block=true)
MsgQ.rb_enable_interrupt if RUBY_VERSION > '1.9' && RUBY_VERSION < '2.0'
msg = EventMsg.new
ret = MsgQ.msgrcv(q, msg, BUF_SIZE, 0, block ? 0 : IPC_NOWAIT)
if ret == -1
if !block and [Errno::EAGAIN, Errno::ENOMSG].include?(FFI::LastError.exception)
return nil
end
FFI::LastError.raise
end
msg[:buf].to_ptr.read_string_length(BUF_SIZE)
ensure
MsgQ.rb_disable_interrupt if RUBY_VERSION > '1.9' && RUBY_VERSION < '2.0'
end
end
attach_function :msgget, [:int, :int], :int
attach_function :msgrcv, [:int, EventMsg.ptr, :size_t, :long, :int], :int
attach_function :msgsnd, [:int, EventMsg.ptr, :size_t, :int], :int
if RUBY_VERSION > '1.9' && RUBY_VERSION < '2.0'
attach_function :rb_enable_interrupt, [], :void
attach_function :rb_disable_interrupt, [], :void
end
end
require 'socket'
require 'fileutils'
require 'msgpack'
require 'ffi'
require 'rbtrace/core_ext'
require 'rbtrace/msgq'
class RBTracer
# Public: The Fixnum pid of the traced process.
attr_reader :pid
# Public: The IO where tracing output is written (default: STDOUT).
attr_accessor :out
# Public: The timeout before giving up on attaching/detaching to a process.
attr_accessor :timeout
# The String prefix used on nested method calls (default: ' ').
attr_accessor :prefix
# The Boolean flag for showing how long method calls take (default: true).
attr_accessor :show_duration
# The Boolean flag for showing the timestamp when method calls start (default: false).
attr_accessor :show_time
# Create a new tracer
#
# pid - The String of Fixnum process id
#
# Returns a tracer.
def initialize(pid)
begin
raise ArgumentError unless pid
@pid = pid.to_i
raise ArgumentError unless @pid > 0
Process.kill(0, @pid)
rescue TypeError, ArgumentError
raise ArgumentError, 'pid required'
rescue Errno::ESRCH
raise ArgumentError, 'invalid pid'
rescue Errno::EPERM
raise ArgumentError, 'could not signal process, are you running as root?'
end
path = "/tmp/rbtrace-#{@pid}.sock"
@sock = Socket.new Socket::AF_UNIX, Socket::SOCK_DGRAM, 0
@sockaddr = Socket.pack_sockaddr_un(path)
@sock.bind(@sockaddr)
FileUtils.chmod 0666, path
at_exit{ FileUtils.rm(path) if File.exists?(path) }
5.times do
signal
sleep 0.15 # wait for process to create msgqs
@qo = MsgQ.msgget(-@pid, 0666)
break if @qo > -1
end
if @qo == -1
raise ArgumentError, 'pid is not listening for messages, did you `require "rbtrace"`'
end
@klasses = {}
@methods = {}
@tracers = Hash.new{ |h,k|
h[k] = {
:query => nil,
:times => [],
:names => [],
:exprs => {},
:last => false,
:arglist => false
}
}
@max_nesting = @last_nesting = @nesting = 0
@last_tracer = nil
@timeout = 5
@out = STDOUT
@out.sync = true
@prefix = ' '
@printed_newline = true
@show_time = false
@show_duration = true
@watch_slow = false
attach
end
# Watch for method calls slower than a threshold.
#
# msec - The Fixnum threshold in milliseconds
#
# Returns nothing.
def watch(msec, cpu_only=false)
@watch_slow = true
send_cmd(cpu_only ? :watchcpu : :watch, msec)
end
# Turn on the firehose (show all method calls).
#
# Returns nothing.
def firehose
send_cmd(:firehose)
end
# Turn on dev mode.
#
# Returns nothing.
def devmode
send_cmd(:devmode)
end
# Fork the process and return the copy's pid.
#
# Returns a Fixnum pid.
def fork
send_cmd(:fork)
if wait('for fork', 30){ !!@forked_pid }
@forked_pid
else
STDERR.puts '*** timed out waiting for fork'