1The following are examples of rb_cputime.d. 2 3This script traces the on-CPU time of Ruby functions and prints a report. 4Here it traces the example program, Code/Ruby/func_slow.rb 5 6# rb_cputime.d 7Tracing... Hit Ctrl-C to end. 8^C 9 10Count, 11 FILE TYPE NAME COUNT 12 . obj-new NoMemoryError 1 13 . obj-new SystemStackError 1 14 . obj-new ThreadGroup 1 15 . obj-new fatal 1 16 func_slow.rb func Object::func_a 1 17 func_slow.rb func Object::func_b 1 18 func_slow.rb func Object::func_c 1 19 . obj-new Object 3 20 func_slow.rb func IO::write 3 21 func_slow.rb func Module::method_added 3 22 func_slow.rb func Object::print 3 23 func_slow.rb func Fixnum::< 600003 24 func_slow.rb func Fixnum::+ 1200000 25 - total - 1800015 26 27Elapsed times (us), 28 FILE TYPE NAME TOTAL 29 . obj-new SystemStackError 2 30 . obj-new NoMemoryError 2 31 . obj-new fatal 11 32 . obj-new ThreadGroup 12 33 . obj-new Object 19 34 35Exclusive function on-CPU times (us), 36 FILE TYPE NAME TOTAL 37 func_slow.rb func Module::method_added 4 38 func_slow.rb func Object::print 57 39 func_slow.rb func IO::write 180 40 func_slow.rb func Object::func_a 405946 41 func_slow.rb func Fixnum::< 691125 42 func_slow.rb func Object::func_b 809970 43 func_slow.rb func Object::func_c 1225235 44 func_slow.rb func Fixnum::+ 1285200 45 - total - 4417721 46 47Inclusive function on-CPU times (us), 48 FILE TYPE NAME TOTAL 49 func_slow.rb func Module::method_added 4 50 func_slow.rb func IO::write 180 51 func_slow.rb func Object::print 238 52 func_slow.rb func Fixnum::< 691125 53 func_slow.rb func Fixnum::+ 1285200 54 func_slow.rb func Object::func_c 2212572 55 func_slow.rb func Object::func_b 3683688 56 func_slow.rb func Object::func_a 4417717 57 58You can see the results are printed in four sections. 59 60The first section reports how many times each subroutine was called, and it's 61type. 62 63The second section reports on the on-CPU time of anything that was not of type 64"func", in this case the only elements reported here are of type obj-new. 65 66The exclusive function on-CPU times shows, amongst other results, that func_a 67spent around 0.4 seconds on-CPU. This time excludes time spent in other 68subroutines. 69 70The inclusive function on-CPU times show that func_a spent around 4.4 71seconds on-CPU. This includes the time spent in other subroutines called. 72 73These on-CPU times are the time the thread spent running on a CPU, from when 74the subroutine began to when it completed. This does not include time 75spent off-CPU time such as sleeping for I/O or waiting for scheduling. 76 77On-CPU times are useful for showing who is causing the CPUs to be busy. 78See Notes/ALLoncpu_notes.txt for more details. Also see 79Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 80detailed explanation of exclusive vs inclusive subroutine time. 81 82