Sunday December 09, 2007
DTrace has been getting a lot more press recently, since Apple has ported it to Leopard, it’s also been getting a lot of mentions in the Ruby community since Apple has included the DTrace providers for it. Yet, surprisingly few seem to actually use DTrace much (yours truly included really). So here’s a short intro to DTrace and D (not to be confused with the other D).
The essence of DTrace is probes, these are event handlers that fire whenever their particular event happens, you can then register interest in these probe events with a particular action, like printing it, aggregating usage counts and whatever other way you decide to use this information.
Since there’s over 450 000 probes in Leopard, there’s a lot of information you can gather and the trick is to start at a high level and drill down — “hmm, why are there 800 syscalls? hmm, what function caused this? what is it writing? what did it do right before it made the call to write()?” and so, one question leads to next with DTrace.
We can get a list of all the probes currently available on our system, by running dtrace -l, or drilling down with the -P flag
$ sudo dtrace -l | wc -l
454839
$ sudo dtrace -l -P syscall | head -5
ID PROVIDER MODULE FUNCTION NAME
17590 syscall syscall entry
17591 syscall syscall return
17592 syscall exit entry
17593 syscall exit return
So let’s start with asking what syscalls are currently being made by all the applications currently running (unless otherwise told to, DTrace will listen forever so finish it with ctrl+c):
$ sudo dtrace -n 'syscall:::entry{trace(execname)}'
dtrace: description 'syscall:::entry' matched 427 probes
CPU ID FUNCTION:NAME
1 17698 ioctl:entry dtrace
1 17698 ioctl:entry dtrace
1 17682 sigaction:entry dtrace
1 17682 sigaction:entry dtrace
1 17682 sigaction:entry dtrace
1 18258 __semwait_signal:entry Little Snitch U
1 17686 sigprocmask:entry WindowServer
1 17696 sigaltstack:entry WindowServer
The probes are specified in a provider:module:function:name format, with an empty entry being a wildcard, so asking for all syscall function entries would mean asking for syscall:::entry, we could get all write syscall entries by asking for syscall::write:entry and its (function) returns by asking for syscall::write:return for the write() function.
So the above output isn’t all that useful since it’s too much information for us puny humans to parse effectively. Luckily DTrace provides means of aggregating things with the @[key(s)] notation, where key(s) is an arbitary comma-seperated list of D expressions and the value is an aggregating function like count() that simply counts the number of times something happens. So to aggregate the number of syscalls on the application name we can use execname:
$ sudo dtrace -n 'syscall:::entry{ @[execname] = count() }'
dtrace: description 'syscall:::entry' matched 427 probes
^C
DirectoryServic 2
Finder 2
...
WindowServer 46
launchd 48
natd 81
SystemUIServer 113
Adium 131
ruby 356
pmTool 584
We can even expand this to see what probe function is being called using the probefunc expression:
$ sudo dtrace -n 'syscall:::entry{ @[execname, probefunc] = count() }'
dtrace: description 'syscall:::entry' matched 427 probes
^C
Finder kevent 1
Safari gettimeofday 1
Terminal mmap 1
...
ruby select 10
dtrace ioctl 14
WindowServer sigaltstack 15
WindowServer sigprocmask 15
ruby __semwait_signal 141
pmTool __sysctl 291
Ruby seems to be waiting in a semaphore/thread, lets take a look at its current stacktrace. We can do this by specifying a predicate for our probing, think of it as a conditional. So, by only registering interest in a proble if the execname == "ruby" predicate is met, we print the stack:
$ sudo dtrace -n 'syscall:::entry/execname == "ruby"/{ ustack() }'
dtrace: description 'syscall:::entry' matched 427 probes
CPU ID FUNCTION:NAME
0 18258 __semwait_signal:entry
libSystem.B.dylib`__semwait_signal+0xa
libruby.1.dylib`rb_thread_group+0x29f
libSystem.B.dylib`_pthread_start+0x141
libSystem.B.dylib`thread_start+0x22
0 18258 __semwait_signal:entry
libSystem.B.dylib`__semwait_signal+0xa
libruby.1.dylib`rb_thread_group+0x29f
libSystem.B.dylib`_pthread_start+0x141
libSystem.B.dylib`thread_start+0x22
Yep, looks like an rb_thread allright. And that makes perfect sense since I had a mongrel running there in the background.
Let’s take a look at what Ruby providers are available (you need a running ruby process to see this):
$ sudo dtrace -l -P "ruby*"
ID PROVIDER MODULE FUNCTION NAME
19708 ruby48398 libruby.1.dylib rb_call0 function-entry
19709 ruby48398 libruby.1.dylib rb_call0 function-return
19710 ruby48398 libruby.1.dylib garbage_collect gc-begin
19711 ruby48398 libruby.1.dylib garbage_collect gc-end
19712 ruby48398 libruby.1.dylib rb_eval line
19713 ruby48398 libruby.1.dylib rb_obj_alloc object-create-done
19714 ruby48398 libruby.1.dylib rb_obj_alloc object-create-start
19715 ruby48398 libruby.1.dylib garbage_collect object-free
19716 ruby48398 libruby.1.dylib rb_longjmp raise
19717 ruby48398 libruby.1.dylib rb_eval rescue
19718 ruby48398 libruby.1.dylib ruby_dtrace_probe ruby-probe
We wildcard the ruby provider name since they’re per app specific (the 48398 part is the PID). Which is cool if you’re running more than one ruby process, so you could poke around figureing out why one is eating cpu and the other isn’t (Here’s an explanation of the Ruby probes). Let’s see what method calls are being used the most in a typical Rails request:
$ sudo dtrace -n 'ruby*:::function-entry{ @[copyinstr(arg0), copyinstr(arg1)] = count() }'
dtrace: description 'ruby*:::function-entry' matched 1 probe
^C
...
Array pop 24
File::Stat size 24
Inflector inflections 24
Inflector inflections_without_route_reloading 24
...
Hash [] 557
Hash []= 623
String to_s 723
Hash key? 4379
Here we make the aggregation list keys out of the class and the method name, which is specified as argN. args[] is an array of arguments for the probe, argN is a shortcut for that array, in this case the arguments are what the probe made them up to be (class and method name, arg 2 and 3 are sourcefile and line number), but it could also be the arguments for a function call. copyinstr() simply means “make a string out of this pointer reference”.
Back to poking around, Hash lookups and String#to_s isn’t all that interesting for us right now, but I’m kinda curious about what it is stat()‘ing 24 times for a request? Let’s try and find out:
sudo dtrace -n 'ruby*:::function-entry/copyinstr(arg0) == "File::Stat" && copyinstr(arg1) == "size"/{ ustack() }'
dtrace: description 'ruby*:::function-entry' matched 1 probe
CPU ID FUNCTION:NAME
0 19708 rb_call0:function-entry
libruby.1.dylib`rb_eval_string_wrap+0x43f9
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x34ba
libruby.1.dylib`rb_eval_string_wrap+0x1f53
libruby.1.dylib`rb_eval_string_wrap+0x2dbb
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x149d
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_thread_trap_eval+0x959
libruby.1.dylib`rb_yield+0x21
libruby.1.dylib`rb_ary_each+0x1e
libruby.1.dylib`rb_eval_string_wrap+0x455f
0 19708 rb_call0:function-entry
libruby.1.dylib`rb_eval_string_wrap+0x43f9
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x1f53
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x149d
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_eval_string_wrap+0x4d65
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
libruby.1.dylib`rb_thread_trap_eval+0x959
libruby.1.dylib`rb_yield+0x21
libruby.1.dylib`rb_ary_each+0x1e
libruby.1.dylib`rb_eval_string_wrap+0x455f
libruby.1.dylib`rb_eval_string_wrap+0x5173
libruby.1.dylib`rb_eval_string_wrap+0x23ee
24
By adding the predicate of our target class and method we get only what we’re interested in, and print the stack using ustack. Unfortunately this being Ruby it’s not all that useful to us, since it’s pretty much all rb_eval-inner-ruby-runtime-here-be-dragons-stuff (I would love a ustack helper for ruby, like there is for python), that doesn’t make much sense to us. I wonder which file it’s doing this in though?
$ sudo dtrace -n 'ruby*:::function-entry/copyinstr(arg0) == "File::Stat" && copyinstr(arg1) =="size"/{ printf("%s in %s", copyinstr(arg0),copyinstr(arg2))}'
dtrace: description 'ruby*:::function-entry' matched 1 probe
File::Stat in [...]gems/mongrel-1.0.1/lib/mongrel/handlers.rb
File::Stat in [...]gems/mongrel-1.0.1/lib/mongrel/handlers.rb
File::Stat in [...]gems/mongrel-1.0.1/lib/mongrel/handlers.rb
# (output slightly truncated)
OK, so that tells us where this is happened, but not what it’s stat()‘ing, luckily File::Stat sounds like something that might be doing a syscall, and we have probes for that, here’s a script that matches up the ruby function-entry with looking at syscalls at the same time:
#!/usr/sbin/dtrace -s
#pragma D option quiet
ruby*:::function-entry
/copyinstr(arg0) == "File::Stat" && copyinstr(arg1) == "size"/
{
self->interested = 1;
self->rubymethod = copyinstr(arg1);
self->rubyclass = copyinstr(arg0)
}
syscall::stat*:entry
/self->interested/
{
printf("%s from %s#%s\n", copyinstr(arg0), self->rubyclass, self->rubymethod);
}
By defining the variable interested whenever we’re in the function-entry we’re interested in, we can use that variable as a predicate for our syscall::stat*:entry (stat* is wildcarded because there’s things like stat64() as well), making it executable and running it we see:
$ chmod +x who_be_stattin.d
$ sudo ./who_be_stattin.d
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/favicon.ico from File::Stat#size
RAILS_ROOT/public/javascripts/application.js from File::Stat#size
RAILS_ROOT/public/javascripts/application.js from File::Stat#size
RAILS_ROOT/public/javascripts/application.js from File::Stat#size
RAILS_ROOT/public/javascripts/application.js from File::Stat#size
Aha! It must be the Rails mongrel handler that checks the size of the asset files, before it sends them down the wire (it’s from a local ./script/console). Not so interesting after all, but at least we learnt a bit along the way.
Remember the ruby providers from up there? the ruby-probe one? That one is basically a plugin that lets you fire your very own probes in your app, using the (Apple shipped) DTracer class:
>> def with_my_probe &blk
>> DTracer.fire("my-probe-entry")
>> yield
>> DTracer.fire("my-probe-return")
>> end
=> nil
>> with_my_probe{ puts "moo" }
$ cat probe_my_probe.d
#!/usr/sbin/dtrace -s
ruby*:::ruby-probe
/copyinstr(arg0) == "my-probe-entry"/
{
self->interested = 1;
}
syscall:::
/self->interested/
{
/* default action is to just print it */
}
ruby*:::function-entry
/self->interested/
{
printf("%s in %s", copyinstr(arg1), copyinstr(arg0));
}
ruby*:::ruby-probe
/copyinstr(arg0) == "my-probe-return"/
{
self->interested = 0;
}
$ sudo ./probe_my_probe.d
dtrace: script './ruby_probe_test.d' matched 860 probes
CPU ID FUNCTION:NAME
1 454800 rb_call0:function-entry puts in Object
1 454800 rb_call0:function-entry write in IO
1 17598 write:entry
1 17599 write:return
1 454800 rb_call0:function-entry write in IO
1 17598 write:entry
1 17599 write:return
1 454800 rb_call0:function-entry fire in Module
# (While running 'with_my_probe{ puts "foo" }' in irb)
But more on that later. In the meantime do go off exploring your OS and applications with DTrace, you’d be surprised how quickly you can loose an hour or two just by asking “why is that doing this here?”…
Dec 10 at 04:37
Is there any place where I can find out more about the Python probes? Apart from that one article on a Sun engineer’s blog, I couldn’t really find more info on the Python ustack support. Apple shipped DTrace alright, but never packaged any proper documentation with it :(