io-trace

io-trace copied to clipboard

IO tracing framework for Ruby MRI (c) 2010 Lourens Naudé (methodmissing)

http://github.com/methodmissing/io-trace

Supported Platforms

Tested and initially developed in an OS X Leopard environment with latest MRI 1.8.7 trunk. Pending testing in BSD and Solaris environments, although the D + dtrace subset used is known to be cross platform.See the TODO section for further caveats and a roadmap estimate.

Very much work in progress at the moment, but usable in a development environment on OS X.

How it works

We support a number of predefined (and locked down) tracing strategies.

IO::Trace::SUMMARY default, no FD, file or line specific contexts IO::Trace::SETUP connect, open, close, fcntl, stat etc. IO::Trace::READ read, receive etc. IO::Trace::WRITE write, send etc. IO::Trace::ALL combo of SETUP, READ and WRITE

Formatting of results (aggregates) is open ended and allows the user to extend with their own formatters in Ruby.Formatters is expected to implement a lambda{|stream, trace| ... } contract.

High level steps per trace run include

• Parse and compile a strategy
• Enable tracing
• Setup an MRI event hook for RUBY_EVENT_LINE (called whenever LINE is bumped)
• yields the traced block
• Unregister event hook
• Stops tracing
• Snapshot collected aggregates
• Walk collected aggregates
• Dump results to a stream via a given formatter (both optional)

Use cases

• Instrumenting IO setup overhead
• Figure out where reads / writes is generated from
• Per request tracing to ensure we're not doing excessive IO in request / response cycles in a Rack environment

TODO

• Documentation
• Bump test coverage
• Abort early on non-superuser perms before allocating tracing resources
• Instrument IO wait, not just inclusive time
• BSD + Solaris testing
• Guard against excessive dtrace handle consumption
• Split dtrace specific infrastructure to ext/framework/dtrace.h
• Introduce support for SystemTap (http://sourceware.org/systemtap/)
• Improve on middleware
• Flesh out more focussed web app specific strategies

config.ru

require "io/trace" require "logger" require "net/http"

app = lambda do |env| resp = Net::HTTP.get('www.wildfireapp.com', '/') [200, {"Content-Type" => "text/plain"}, [resp]] end

use IO::Trace::Middleware, :strategy => :WRITE, :stream => Logger.new(STDOUT) run app

read strategy

methodmissing-2:race lourens$ sudo rackup [2010-10-07 01:22:51] INFO WEBrick 1.3.1 [2010-10-07 01:22:51] INFO ruby 1.8.7 (2010-01-10) [i686-darwin10.4.0] [2010-10-07 01:22:51] INFO WEBrick::HTTPServer#start: pid=4709 port=9292

File Line Probe FD Feature

/Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 135 readv_nocancel 8 bytes 56276 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 135 readv_nocancel 8 time 1.053446 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 135 readv_nocancel 8 cpu 0.587824 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 135 readv_nocancel 8 calls 21 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 4 bytes 442 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 4 time 1.528309 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 4 cpu 0.044459 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 4 calls 8 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 9 bytes 8 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 9 time 0.651593 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 9 cpu 0.020702 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 recvfrom_nocancel 9 calls 2 127.0.0.1 - - [07/Oct/2010 01:22:57] "GET / HTTP/1.1" 200 55706 1.1169 ^C[2010-10-07 01:23:03] INFO going to shutdown ... [2010-10-07 01:23:03] INFO WEBrick::HTTPServer#start done.

write strategy

methodmissing-2:race lourens$ sudo rackup [2010-10-07 01:23:17] INFO WEBrick 1.3.1 [2010-10-07 01:23:17] INFO ruby 1.8.7 (2010-01-10) [i686-darwin10.4.0] [2010-10-07 01:23:17] INFO WEBrick::HTTPServer#start: pid=4716 port=9292

File Line Probe FD Feature

/Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 177 writev_nocancel 8 bytes 58 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 177 writev_nocancel 8 time 0.057234 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 177 writev_nocancel 8 cpu 0.032078 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/protocol.rb 177 writev_nocancel 8 calls 1 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 bytes 2 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 time 0.034803 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 cpu 0.011973 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 calls 2 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 bytes 178 /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 time 0.664275 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 cpu 0.034724 ms /Users/lourens/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/net/http.rb 706 sendto_nocancel 4 calls 4 127.0.0.1 - - [07/Oct/2010 01:23:22] "GET / HTTP/1.1" 200 55706 1.1833 ^C[2010-10-07 01:23:31] INFO going to shutdown ... [2010-10-07 01:23:32] INFO WEBrick::HTTPServer#start done.

To run the test suite:

rake

Middleware example:

rake test:middleware

Work in progress, thanks for watching!