1 The following is an example of running rb_calltime.d and tracing the elapsed
4 We run rb_calltime.d while running the program Code/Ruby/func_abc.rb. We can
5 see that there are four sections in the DTrace output
8 Tracing... Hit Ctrl-C to end.
13 . obj-new NoMemoryError 1
14 . obj-new SystemStackError 1
15 . obj-new ThreadGroup 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
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
29 . obj-new SystemStackError 3
30 . obj-new NoMemoryError 3
32 . obj-new ThreadGroup 13
35 Exclusive function elapsed times (us),
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
46 Inclusive function elapsed times (us),
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
56 The first section, Count, shows us how many times each function associated
57 with func_abc.rb was called. It also shows other functions called by the Ruby
60 The second section, elapsed times, shows how long each action that was not
61 calling a function took.
63 The third section, exclusive function elapsed times, shows us how many
64 microseconds the program spends in each function. This does not include the
65 time spent in any sub-functions called by that particular function. The last
66 line gives us the total time in microseconds.
68 The fourth section, inclusive function elapsed times, are the absolute time
69 from when the function began to when it completed - which includes off-CPU time
70 due to other system events such as I/O, scheduling, interrupts, etc. In
71 particular, for this case it has included the time waiting for the sleep
74 Elapsed times are useful for identifying where latencies are.
75 See Notes/ALLelapsed_notes.txt for more details. Also see
76 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
77 detailed explanation of exclusive vs inclusive function time.