1The following is an example of running rb_calltime.d and tracing the elapsed 2times for functions. 3 4We run rb_calltime.d while running the program Code/Ruby/func_abc.rb. We can 5see that there are four sections in the DTrace output 6 7# rb_calltime.d 8Tracing... Hit Ctrl-C to end. 9^C 10 11Count, 12 FILE TYPE NAME COUNT 13 . obj-new NoMemoryError 1 14 . obj-new SystemStackError 1 15 . obj-new ThreadGroup 1 16 . obj-new fatal 1 17 func_abc.rb func Object::func_a 1 18 func_abc.rb func Object::func_b 1 19 func_abc.rb func Object::func_c 1 20 . obj-new Object 3 21 func_abc.rb func IO::write 3 22 func_abc.rb func Module::method_added 3 23 func_abc.rb func Object::print 3 24 func_abc.rb func Object::sleep 3 25 - total - 15 26 27Elapsed times (us), 28 FILE TYPE NAME TOTAL 29 . obj-new SystemStackError 3 30 . obj-new NoMemoryError 3 31 . obj-new fatal 11 32 . obj-new ThreadGroup 13 33 . obj-new Object 26 34 35Exclusive function elapsed times (us), 36 FILE TYPE NAME TOTAL 37 func_abc.rb func Module::method_added 9 38 func_abc.rb func Object::print 92 39 func_abc.rb func IO::write 185 40 func_abc.rb func Object::func_c 344 41 func_abc.rb func Object::func_a 379 42 func_abc.rb func Object::func_b 383 43 func_abc.rb func Object::sleep 3020597 44 - total - 3021992 45 46Inclusive function elapsed times (us), 47 FILE TYPE NAME TOTAL 48 func_abc.rb func Module::method_added 9 49 func_abc.rb func IO::write 185 50 func_abc.rb func Object::print 277 51 func_abc.rb func Object::func_c 1009829 52 func_abc.rb func Object::func_b 2019781 53 func_abc.rb func Object::sleep 3020597 54 func_abc.rb func Object::func_a 3021983 55 56The first section, Count, shows us how many times each function associated 57with func_abc.rb was called. It also shows other functions called by the Ruby 58engine. 59 60The second section, elapsed times, shows how long each action that was not 61calling a function took. 62 63The third section, exclusive function elapsed times, shows us how many 64microseconds the program spends in each function. This does not include the 65time spent in any sub-functions called by that particular function. The last 66line gives us the total time in microseconds. 67 68The fourth section, inclusive function elapsed times, are the absolute time 69from when the function began to when it completed - which includes off-CPU time 70due to other system events such as I/O, scheduling, interrupts, etc. In 71particular, for this case it has included the time waiting for the sleep 72commands. 73 74Elapsed times are useful for identifying where latencies are. 75See Notes/ALLelapsed_notes.txt for more details. Also see 76Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 77detailed explanation of exclusive vs inclusive function time. 78