1 The following are examples of rb_cputime.d.
3 This script traces the on-CPU time of Ruby functions and prints a report.
4 Here it traces the example program, Code/Ruby/func_slow.rb
7 Tracing... Hit Ctrl-C to end.
12 . obj-new NoMemoryError 1
13 . obj-new SystemStackError 1
14 . obj-new ThreadGroup 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
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
29 . obj-new SystemStackError 2
30 . obj-new NoMemoryError 2
32 . obj-new ThreadGroup 12
35 Exclusive function on-CPU times (us),
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
47 Inclusive function on-CPU times (us),
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
58 You can see the results are printed in four sections.
60 The first section reports how many times each subroutine was called, and it's
63 The 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.
66 The exclusive function on-CPU times shows, amongst other results, that func_a
67 spent around 0.4 seconds on-CPU. This time excludes time spent in other
70 The inclusive function on-CPU times show that func_a spent around 4.4
71 seconds on-CPU. This includes the time spent in other subroutines called.
73 These on-CPU times are the time the thread spent running on a CPU, from when
74 the subroutine began to when it completed. This does not include time
75 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
77 On-CPU times are useful for showing who is causing the CPUs to be busy.
78 See Notes/ALLoncpu_notes.txt for more details. Also see
79 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
80 detailed explanation of exclusive vs inclusive subroutine time.