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