1 1.1 christos The following is an example of running rb_calldist.d and tracing the elapsed 2 1.1 christos times for functions. 3 1.1 christos 4 1.1 christos We run rb_calldist.d while running the program Code/Ruby/func_abc.rb. We can 5 1.1 christos see that there are three sections in the DTrace output 6 1.1 christos 7 1.1 christos # rb_calldist.d 8 1.1 christos Tracing... Hit Ctrl-C to end. 9 1.1 christos ^C 10 1.1 christos 11 1.1 christos Elapsed times (us), 12 1.1 christos ., obj-new, NoMemoryError 13 1.1 christos value ------------- Distribution ------------- count 14 1.1 christos 1 | 0 15 1.1 christos 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 16 1.1 christos 4 | 0 17 1.1 christos 18 1.1 christos ., obj-new, SystemStackError 19 1.1 christos value ------------- Distribution ------------- count 20 1.1 christos 1 | 0 21 1.1 christos 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 22 1.1 christos 4 | 0 23 1.1 christos 24 1.1 christos ., obj-new, ThreadGroup 25 1.1 christos value ------------- Distribution ------------- count 26 1.1 christos 4 | 0 27 1.1 christos 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 28 1.1 christos 16 | 0 29 1.1 christos 30 1.1 christos ., obj-new, fatal 31 1.1 christos value ------------- Distribution ------------- count 32 1.1 christos 4 | 0 33 1.1 christos 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 34 1.1 christos 16 | 0 35 1.1 christos 36 1.1 christos ., obj-new, Object 37 1.1 christos value ------------- Distribution ------------- count 38 1.1 christos 1 | 0 39 1.1 christos 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 40 1.1 christos 4 | 0 41 1.1 christos 8 | 0 42 1.1 christos 16 |@@@@@@@@@@@@@ 1 43 1.1 christos 32 | 0 44 1.1 christos 45 1.1 christos 46 1.1 christos Exclusive function elapsed times (us), 47 1.1 christos func_abc.rb, func, Module::method_added 48 1.1 christos value ------------- Distribution ------------- count 49 1.1 christos 1 | 0 50 1.1 christos 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 51 1.1 christos 4 |@@@@@@@@@@@@@ 1 52 1.1 christos 8 | 0 53 1.1 christos 54 1.1 christos func_abc.rb, func, Object::print 55 1.1 christos value ------------- Distribution ------------- count 56 1.1 christos 8 | 0 57 1.1 christos 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 58 1.1 christos 32 |@@@@@@@@@@@@@ 1 59 1.1 christos 64 | 0 60 1.1 christos 61 1.1 christos func_abc.rb, func, IO::write 62 1.1 christos value ------------- Distribution ------------- count 63 1.1 christos 16 | 0 64 1.1 christos 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 65 1.1 christos 64 |@@@@@@@@@@@@@ 1 66 1.1 christos 128 | 0 67 1.1 christos 68 1.1 christos func_abc.rb, func, Object::func_a 69 1.1 christos value ------------- Distribution ------------- count 70 1.1 christos 128 | 0 71 1.1 christos 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 72 1.1 christos 512 | 0 73 1.1 christos 74 1.1 christos func_abc.rb, func, Object::func_b 75 1.1 christos value ------------- Distribution ------------- count 76 1.1 christos 128 | 0 77 1.1 christos 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 78 1.1 christos 512 | 0 79 1.1 christos 80 1.1 christos func_abc.rb, func, Object::func_c 81 1.1 christos value ------------- Distribution ------------- count 82 1.1 christos 128 | 0 83 1.1 christos 256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 84 1.1 christos 512 | 0 85 1.1 christos 86 1.1 christos func_abc.rb, func, Object::sleep 87 1.1 christos value ------------- Distribution ------------- count 88 1.1 christos 262144 | 0 89 1.1 christos 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 90 1.1 christos 1048576 | 0 91 1.1 christos 92 1.1 christos 93 1.1 christos Inclusive function elapsed times (us), 94 1.1 christos func_abc.rb, func, Module::method_added 95 1.1 christos value ------------- Distribution ------------- count 96 1.1 christos 1 | 0 97 1.1 christos 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 98 1.1 christos 4 |@@@@@@@@@@@@@ 1 99 1.1 christos 8 | 0 100 1.1 christos 101 1.1 christos func_abc.rb, func, IO::write 102 1.1 christos value ------------- Distribution ------------- count 103 1.1 christos 16 | 0 104 1.1 christos 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 105 1.1 christos 64 |@@@@@@@@@@@@@ 1 106 1.1 christos 128 | 0 107 1.1 christos 108 1.1 christos func_abc.rb, func, Object::print 109 1.1 christos value ------------- Distribution ------------- count 110 1.1 christos 32 | 0 111 1.1 christos 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2 112 1.1 christos 128 |@@@@@@@@@@@@@ 1 113 1.1 christos 256 | 0 114 1.1 christos 115 1.1 christos func_abc.rb, func, Object::func_c 116 1.1 christos value ------------- Distribution ------------- count 117 1.1 christos 262144 | 0 118 1.1 christos 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 119 1.1 christos 1048576 | 0 120 1.1 christos 121 1.1 christos func_abc.rb, func, Object::func_b 122 1.1 christos value ------------- Distribution ------------- count 123 1.1 christos 524288 | 0 124 1.1 christos 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 125 1.1 christos 2097152 | 0 126 1.1 christos 127 1.1 christos func_abc.rb, func, Object::sleep 128 1.1 christos value ------------- Distribution ------------- count 129 1.1 christos 262144 | 0 130 1.1 christos 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3 131 1.1 christos 1048576 | 0 132 1.1 christos 133 1.1 christos func_abc.rb, func, Object::func_a 134 1.1 christos value ------------- Distribution ------------- count 135 1.1 christos 1048576 | 0 136 1.1 christos 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1 137 1.1 christos 4194304 | 0 138 1.1 christos 139 1.1 christos The elapsed times show us that the script spent some small amount of time 140 1.1 christos processing various events that were not functions. In this case they were all 141 1.1 christos obj-new events, and you can see that the slowest of these was a new Object at 142 1.1 christos between 16 microseconds and 31 microseconds. 143 1.1 christos 144 1.1 christos The exclusive subroutine elapsed times show that each of our user defined 145 1.1 christos functions took between 256 and 511 microseconds. This time excludes the time 146 1.1 christos spent in other subroutines. 147 1.1 christos 148 1.1 christos The inclusive subroutine elapsed times show that func_c() took between 0.5 149 1.1 christos seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and 150 1.1 christos func_a() took between 2.1 seconds and 4.2 seconds to execute. This time 151 1.1 christos includes the time spent in other subroutines called, and since func_a() called 152 1.1 christos func_b() which called func_c(), these times make sense. 153 1.1 christos 154
Indexes created Sat May 02 00:23:24 UTC 2026