Home | History | Annotate | Line # | Download | only in Examples 
      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