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