cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt

   1 The following are examples of rb_syscolors.d.
   2
   3 This is a simple script to trace the method flow of Ruby functions within a
   4 program, and the system calls made.  It renders the output in color ("colour")
   5 using terminal escape sequences (which you can tweak by modifying the script).
   6
   7 Here it traces the example program, Code/Ruby/func_abc.rb.
   8
   9 WARNING: This output is full of terminal escape sequences, so if you are
  10 trying to view this through an editor or web browser - it may look awful.
  11 Try viewing this using "more" (although, depending on your terminal, it
  12 still may look awful).
  13
  14 # rb_syscolors.d -c ./func_abc.rb
  15 C    PID  DELTA(us)              FILE:LINE TYPE     -- NAME
  16 \e[2;32m0 146499          2                 ":-    syscall  -> munmap\e[0m
  17 \e[2;32m0 146499         35                 ":-    syscall  <- munmap\e[0m
  18 \e[2;32m0 146499         56                 ":-    syscall  -> mmap\e[0m
  19 \e[2;32m0 146499         18                 ":-    syscall  <- mmap\e[0m
  20 \e[2;32m0 146499         41                 ":-    syscall  -> setcontext\e[0m
  21 \e[2;32m0 146499         10                 ":-    syscall  <- setcontext\e[0m
  22 \e[2;32m0 146499         10                 ":-    syscall  -> getrlimit\e[0m
  23 \e[2;32m0 146499         11                 ":-    syscall  <- getrlimit\e[0m
  24 \e[2;32m0 146499          9                 ":-    syscall  -> getpid\e[0m
  25 \e[2;32m0 146499          8                 ":-    syscall  <- getpid\e[0m
  26 \e[2;32m0 146499         66                 ":-    syscall  -> setcontext\e[0m
  27 \e[2;32m0 146499          8                 ":-    syscall  <- setcontext\e[0m
  28 \e[2;32m0 146499       1125                 ":-    syscall  -> sysi86\e[0m
  29 \e[2;32m0 146499         12                 ":-    syscall  <- sysi86\e[0m
  30 \e[2;32m0 146499         86                 ":-    syscall  -> open64\e[0m
  31 \e[2;32m0 146499         89                 ":-    syscall  <- open64\e[0m
  32 \e[2;32m0 146499         13                 ":-    syscall  -> ioctl\e[0m
  33 \e[2;32m0 146499         35                 ":-    syscall  <- ioctl\e[0m
  34 \e[2;32m0 146499         15                 ":-    syscall  -> close\e[0m
  35 \e[2;32m0 146499         16                 ":-    syscall  <- close\e[0m
  36 \e[2;32m0 146499        141                 ":-    syscall  -> getrlimit64\e[0m
  37 \e[2;32m0 146499         10                 ":-    syscall  <- getrlimit64\e[0m
  38 \e[2;32m0 146499         37                 ":-    syscall  -> brk\e[0m
  39 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  40 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  41 \e[2;32m0 146499         17                 ":-    syscall  <- brk\e[0m
  42 \e[2;32m0 146499         19                 ":-    syscall  -> brk\e[0m
  43 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  44 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  45 \e[2;32m0 146499         11                 ":-    syscall  <- brk\e[0m
  46 \e[2;32m0 146499        495                 ":-    syscall  -> brk\e[0m
  47 \e[2;32m0 146499         11                 ":-    syscall  <- brk\e[0m
  48 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  49 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  50 \e[2;32m0 146499         55                 ":-    syscall  -> sysconfig\e[0m
  51 \e[2;32m0 146499          9                 ":-    syscall  <- sysconfig\e[0m
  52 \e[2;32m0 146499        109                 ":-    syscall  -> brk\e[0m
  53 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  54 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  55 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  56 \e[2;32m0 146499        189                 ":-    syscall  -> brk\e[0m
  57 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  58 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  59 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  60 \e[2;32m0 146499        161                 ":-    syscall  -> brk\e[0m
  61 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  62 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  63 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  64 \e[2;32m0 146499        144                 ":-    syscall  -> brk\e[0m
  65 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  66 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  67 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  68 \e[2;32m0 146499        184                 ":-    syscall  -> brk\e[0m
  69 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  70 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  71 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  72 \e[2;32m0 146499        129                 ":-    syscall  -> brk\e[0m
  73 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  74 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  75 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  76 \e[2;32m0 146499        174                 ":-    syscall  -> brk\e[0m
  77 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  78 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
  79 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  80 \e[2;32m0 146499        145                 ":-    syscall  -> brk\e[0m
  81 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  82 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  83 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  84 \e[2;32m0 146499        129                 ":-    syscall  -> brk\e[0m
  85 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  86 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  87 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  88 \e[2;32m0 146499        134                 ":-    syscall  -> brk\e[0m
  89 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  90 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  91 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
  92 \e[2;32m0 146499        135                 ":-    syscall  -> brk\e[0m
  93 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  94 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  95 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
  96 \e[2;32m0 146499        136                 ":-    syscall  -> brk\e[0m
  97 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
  98 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
  99 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 100 \e[2;32m0 146499         98                 ":-    syscall  -> brk\e[0m
 101 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 102 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
 103 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
 104 \e[2;32m0 146499        132                 ":-    syscall  -> brk\e[0m
 105 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 106 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 107 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 108 \e[2;32m0 146499        125                 ":-    syscall  -> brk\e[0m
 109 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 110 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 111 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
 112 \e[2;32m0 146499        189                 ":-    syscall  -> brk\e[0m
 113 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 114 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 115 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 116 \e[2;32m0 146499        413                 ":-    syscall  -> brk\e[0m
 117 \e[2;32m0 146499         11                 ":-    syscall  <- brk\e[0m
 118 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
 119 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 120 \e[2;32m0 146499        171                 ":-    syscall  -> brk\e[0m
 121 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 122 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
 123 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 124 \e[2;32m0 146499        137                 ":-    syscall  -> brk\e[0m
 125 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 126 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 127 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 128 \e[2;32m0 146499        188                 ":-    syscall  -> brk\e[0m
 129 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 130 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
 131 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
 132 \e[2;32m0 146499        135                 ":-    syscall  -> sigaction\e[0m
 133 \e[2;32m0 146499         10                 ":-    syscall  <- sigaction\e[0m
 134 \e[2;32m0 146499         10                 ":-    syscall  -> sigaction\e[0m
 135 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 136 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 137 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 138 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 139 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 140 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 141 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 142 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 143 \e[2;32m0 146499          8                 ":-    syscall  <- sigaction\e[0m
 144 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 145 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 146 \e[2;32m0 146499          9                 ":-    syscall  -> sigaction\e[0m
 147 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 148 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 149 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 150 \e[2;32m0 146499         12                 ":-    syscall  -> sigpending\e[0m
 151 \e[2;32m0 146499          8                 ":-    syscall  <- sigpending\e[0m
 152 \e[2;32m0 146499         15                 ":-    syscall  -> schedctl\e[0m
 153 \e[2;32m0 146499         44                 ":-    syscall  <- schedctl\e[0m
 154 \e[2;32m0 146499         17                 ":-    syscall  -> lwp_sigmask\e[0m
 155 \e[2;32m0 146499          8                 ":-    syscall  <- lwp_sigmask\e[0m
 156 \e[2;32m0 146499          9                 ":-    syscall  -> sigaction\e[0m
 157 \e[2;32m0 146499          8                 ":-    syscall  <- sigaction\e[0m
 158 \e[2;32m0 146499         11                 ":-    syscall  -> lwp_sigmask\e[0m
 159 \e[2;32m0 146499          8                 ":-    syscall  <- lwp_sigmask\e[0m
 160 \e[2;32m0 146499          9                 ":-    syscall  -> lwp_sigmask\e[0m
 161 \e[2;32m0 146499          7                 ":-    syscall  <- lwp_sigmask\e[0m
 162 \e[2;32m0 146499          8                 ":-    syscall  -> sigaction\e[0m
 163 \e[2;32m0 146499          7                 ":-    syscall  <- sigaction\e[0m
 164 \e[2;32m0 146499          8                 ":-    syscall  -> lwp_sigmask\e[0m
 165 \e[2;32m0 146499          7                 ":-    syscall  <- lwp_sigmask\e[0m
 166 \e[2;32m0 146499         65                 ":-    syscall  -> brk\e[0m
 167 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 168 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 169 \e[2;32m0 146499         11                 ":-    syscall  <- brk\e[0m
 170 \e[2;32m0 146499        149                 ":-    syscall  -> getuid\e[0m
 171 \e[2;32m0 146499          9                 ":-    syscall  <- getuid\e[0m
 172 \e[2;32m0 146499         12                 ":-    syscall  -> getgid\e[0m
 173 \e[2;32m0 146499          8                 ":-    syscall  <- getgid\e[0m
 174 \e[2;32m0 146499         29                 ":-    syscall  -> brk\e[0m
 175 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 176 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 177 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 178 \e[2;32m0 146499        184                 ":-    syscall  -> brk\e[0m
 179 \e[2;32m0 146499          8                 ":-    syscall  <- brk\e[0m
 180 \e[2;32m0 146499          9                 ":-    syscall  -> brk\e[0m
 181 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 182 \e[2;32m0 146499        171                 ":-    syscall  -> brk\e[0m
 183 \e[2;32m0 146499          9                 ":-    syscall  <- brk\e[0m
 184 \e[2;32m0 146499          8                 ":-    syscall  -> brk\e[0m
 185 \e[2;32m0 146499         10                 ":-    syscall  <- brk\e[0m
 186 \e[2;32m0 146499         48                 ":-    syscall  -> getuid\e[0m
 187 \e[2;32m0 146499          8                 ":-    syscall  <- getuid\e[0m
 188 \e[2;32m0 146499          9                 ":-    syscall  -> getuid\e[0m
 189 \e[2;32m0 146499          7                 ":-    syscall  <- getuid\e[0m
 190 \e[2;32m0 146499         10                 ":-    syscall  -> getgid\e[0m
 191 \e[2;32m0 146499          7                 ":-    syscall  <- getgid\e[0m
 192 \e[2;32m0 146499          8                 ":-    syscall  -> getgid\e[0m
 193 \e[2;32m0 146499          7                 ":-    syscall  <- getgid\e[0m
 194 \e[2;32m0 146499         79                 ":-    syscall  -> open64\e[0m
 195 \e[2;32m0 146499         31                 ":-    syscall  <- open64\e[0m
 196 \e[2;32m0 146499         14                 ":-    syscall  -> llseek\e[0m
 197 \e[2;32m0 146499          9                 ":-    syscall  <- llseek\e[0m
 198 \e[2;32m0 146499          9                 ":-    syscall  -> close\e[0m
 199 \e[2;32m0 146499         12                 ":-    syscall  <- close\e[0m
 200 \e[2;32m0 146499         15                 ":-    syscall  -> open64\e[0m
 201 \e[2;32m0 146499         13                 ":-    syscall  <- open64\e[0m
 202 \e[2;32m0 146499         21                 ":-    syscall  -> fstat64\e[0m
 203 \e[2;32m0 146499         11                 ":-    syscall  <- fstat64\e[0m
 204 \e[2;32m0 146499         22                 ":-    syscall  -> read\e[0m
 205 \e[2;32m0 146499         36                 ":-    syscall  <- read\e[0m
 206 \e[2;32m0 146499        153                 ":-    syscall  -> read\e[0m
 207 \e[2;32m0 146499         10                 ":-    syscall  <- read\e[0m
 208 \e[2;32m0 146499         11                 ":-    syscall  -> llseek\e[0m
 209 \e[2;32m0 146499          8                 ":-    syscall  <- llseek\e[0m
 210 \e[2;32m0 146499          8                 ":-    syscall  -> close\e[0m
 211 \e[2;32m0 146499          9                 ":-    syscall  <- close\e[0m
 212 \e[1;35m0 146499         23       func_abc.rb:3    line     -- \e[0m
 213 \e[2;35m0 146499         64       func_abc.rb:3    method   -> Module::method_added\e[0m
 214 \e[2;35m0 146499         24       func_abc.rb:3    method   <- Module::method_added\e[0m
 215 \e[1;35m0 146499         20       func_abc.rb:8    line     -- \e[0m
 216 \e[2;35m0 146499         15       func_abc.rb:8    method   -> Module::method_added\e[0m
 217 \e[2;35m0 146499         13       func_abc.rb:8    method   <- Module::method_added\e[0m
 218 \e[1;35m0 146499         13       func_abc.rb:14   line     -- \e[0m
 219 \e[2;35m0 146499         14       func_abc.rb:14   method   -> Module::method_added\e[0m
 220 \e[2;35m0 146499         13       func_abc.rb:14   method   <- Module::method_added\e[0m
 221 \e[1;35m0 146499         12       func_abc.rb:20   line     -- \e[0m
 222 \e[2;35m0 146499         13       func_abc.rb:20   method   -> Object::func_a\e[0m
 223 \e[1;35m0 146499         12       func_abc.rb:15   line       -- \e[0m
 224 \e[2;35m0 146499         10       func_abc.rb:15   method     -> Object::print\e[0m
 225 \e[2;35m0 146499         22       func_abc.rb:15   method       -> IO::write\e[0m
 226 \e[2;32m0 146499         38                 ":-    syscall        -> ioctl\e[0m
 227 \e[2;32m0 146499         11                 ":-    syscall        <- ioctl\e[0m
 228 \e[2;32m0 146499         20                 ":-    syscall        -> fstat64\e[0m
 229 \e[2;32m0 146499          9                 ":-    syscall        <- fstat64\e[0m
 230 \e[2;32m0 146499          9                 ":-    syscall        -> brk\e[0m
 231 \e[2;32m0 146499          8                 ":-    syscall        <- brk\e[0m
 232 \e[2;32m0 146499          8                 ":-    syscall        -> brk\e[0m
 233 \e[2;32m0 146499         11                 ":-    syscall        <- brk\e[0m
 234 \e[2;32m0 146499         25                 ":-    syscall        -> fstat64\e[0m
 235 \e[2;32m0 146499          8                 ":-    syscall        <- fstat64\e[0m
 236 \e[2;35m0 146499         10       func_abc.rb:15   method       <- IO::write\e[0m
 237 \e[2;35m0 146499         13       func_abc.rb:15   method     <- Object::print\e[0m
 238 \e[1;35m0 146499         12       func_abc.rb:16   line       -- \e[0m
 239 \e[2;35m0 146499         10       func_abc.rb:16   method     -> Object::sleep\e[0m
 240 \e[2;32m0 146499         20                 ":-    syscall      -> gtime\e[0m
 241 \e[2;32m0 146499          9                 ":-    syscall      <- gtime\e[0m
 242 \e[2;32m0 146499         24                 ":-    syscall      -> pollsys\e[0m
 243 \e[2;32m0 146499    1006964                 ":-    syscall      <- pollsys\e[0m
 244 \e[2;32m0 146499         26                 ":-    syscall      -> gtime\e[0m
 245 \e[2;32m0 146499         14                 ":-    syscall      <- gtime\e[0m
 246 \e[2;35m0 146499         18       func_abc.rb:16   method     <- Object::sleep\e[0m
 247 \e[1;35m0 146499         27       func_abc.rb:17   line       -- \e[0m
 248 \e[2;35m0 146499         21       func_abc.rb:17   method     -> Object::func_b\e[0m
 249 \e[1;35m0 146499         19       func_abc.rb:9    line         -- \e[0m
 250 \e[2;35m0 146499         12       func_abc.rb:9    method       -> Object::print\e[0m
 251 \e[2;35m0 146499         14       func_abc.rb:9    method         -> IO::write\e[0m
 252 \e[2;35m0 146499         15       func_abc.rb:9    method         <- IO::write\e[0m
 253 \e[2;35m0 146499         12       func_abc.rb:9    method       <- Object::print\e[0m
 254 \e[1;35m0 146499         12       func_abc.rb:10   line         -- \e[0m
 255 \e[2;35m0 146499          9       func_abc.rb:10   method       -> Object::sleep\e[0m
 256 \e[2;32m0 146499         12                 ":-    syscall        -> gtime\e[0m
 257 \e[2;32m0 146499          8                 ":-    syscall        <- gtime\e[0m
 258 \e[2;32m0 146499         11                 ":-    syscall        -> pollsys\e[0m
 259 \e[2;32m0 146499    1009739                 ":-    syscall        <- pollsys\e[0m
 260 \e[2;32m0 146499         26                 ":-    syscall        -> gtime\e[0m
 261 \e[2;32m0 146499         14                 ":-    syscall        <- gtime\e[0m
 262 \e[2;35m0 146499         18       func_abc.rb:10   method       <- Object::sleep\e[0m
 263 \e[1;35m0 146499         27       func_abc.rb:11   line         -- \e[0m
 264 \e[2;35m0 146499         21       func_abc.rb:11   method       -> Object::func_c\e[0m
 265 \e[1;35m0 146499         20       func_abc.rb:4    line           -- \e[0m
 266 \e[2;35m0 146499         12       func_abc.rb:4    method         -> Object::print\e[0m
 267 \e[2;35m0 146499         14       func_abc.rb:4    method           -> IO::write\e[0m
 268 \e[2;35m0 146499         15       func_abc.rb:4    method           <- IO::write\e[0m
 269 \e[2;35m0 146499         12       func_abc.rb:4    method         <- Object::print\e[0m
 270 \e[1;35m0 146499         12       func_abc.rb:5    line           -- \e[0m
 271 \e[2;35m0 146499          9       func_abc.rb:5    method         -> Object::sleep\e[0m
 272 \e[2;32m0 146499         12                 ":-    syscall          -> gtime\e[0m
 273 \e[2;32m0 146499          8                 ":-    syscall          <- gtime\e[0m
 274 \e[2;32m0 146499         11                 ":-    syscall          -> pollsys\e[0m
 275 Function A
 276 Function B
 277 Function C
 278 \e[2;32m0 146499    1009762                 ":-    syscall          <- pollsys\e[0m
 279 \e[2;32m0 146499         25                 ":-    syscall          -> gtime\e[0m
 280 \e[2;32m0 146499         14                 ":-    syscall          <- gtime\e[0m
 281 \e[2;35m0 146499         19       func_abc.rb:5    method         <- Object::sleep\e[0m
 282 \e[2;35m0 146499         26       func_abc.rb:5    method       <- Object::func_c\e[0m
 283 \e[2;35m0 146499         13       func_abc.rb:11   method     <- Object::func_b\e[0m
 284 \e[2;35m0 146499         13       func_abc.rb:17   method   <- Object::func_a\e[0m
 285 \e[2;32m0 146499         33                 ":-    syscall  -> sigaction\e[0m
 286 \e[2;32m0 146499         10                 ":-    syscall  <- sigaction\e[0m
 287 \e[2;32m0 146499        100                 ":-    syscall  -> open64\e[0m
 288 \e[2;32m0 146499        107                 ":-    syscall  <- open64\e[0m
 289 \e[2;32m0 146499         10                 ":-    syscall  -> ioctl\e[0m
 290 \e[2;32m0 146499         10                 ":-    syscall  <- ioctl\e[0m
 291 \e[2;32m0 146499         11                 ":-    syscall  -> close\e[0m
 292 \e[2;32m0 146499         17                 ":-    syscall  <- close\e[0m
 293 \e[2;32m0 146499         28                 ":-    syscall  -> write\e[0m
 294 \e[2;32m0 146499         20                 ":-    syscall  <- write\e[0m
 295 \e[2;32m0 146499         11                 ":-    syscall  -> rexit\e[0m
 296
 297 Here you can see the output showing the path the program follows in its
 298 execution.
 299
 300 ie:
 301 \e[2;35m0 146499         10       func_abc.rb:16   method     -> Object::sleep\e[0m
 302 \e[2;32m0 146499         20                 ":-    syscall      -> gtime\e[0m
 303 \e[2;32m0 146499          9                 ":-    syscall      <- gtime\e[0m
 304 \e[2;32m0 146499         24                 ":-    syscall      -> pollsys\e[0m
 305 \e[2;32m0 146499    1006964                 ":-    syscall      <- pollsys\e[0m
 306 \e[2;32m0 146499         26                 ":-    syscall      -> gtime\e[0m
 307 \e[2;32m0 146499         14                 ":-    syscall      <- gtime\e[0m
 308 \e[2;35m0 146499         18       func_abc.rb:16   method     <- Object::sleep\e[0m
 309 \e[1;35m0 146499         27       func_abc.rb:17   line       -- \e[0m
 310 \e[2;35m0 146499         21       func_abc.rb:17   method     -> Object::func_b\e[0m
 311 \e[1;35m0 146499         19       func_abc.rb:9    line         -- \e[0m
 312 \e[2;35m0 146499         12       func_abc.rb:9    method       -> Object::print\e[0m
 313 \e[2;35m0 146499         14       func_abc.rb:9    method         -> IO::write\e[0m
 314 \e[2;35m0 146499         15       func_abc.rb:9    method         <- IO::write\e[0m
 315 \e[2;35m0 146499         12       func_abc.rb:9    method       <- Object::print\e[0m
 316 \e[1;35m0 146499         12       func_abc.rb:10   line         -- \e[0m
 317
 318 shows that on cpu 0 the program is running a sleep command at line 16 of the
 319 func_abc.rb program (the pollsys and gtime syscalls are used in the Ruby
 320 engine to implement sleep).  Then func_b runs, and prints a line
 321 (using Object::print which uses IO::write).  Notice that the 'write' syscall
 322 does not happen until later.  It is probably being buffered by Ruby - you can
 323 confirm this through further DTracing.  Notice also tht you can see the output
 324 of the program:
 325
 326 Function A
 327 Function B
 328 Function C
 329
 330 in the file happening before the write syscall is run.  DTrace does not do its
 331 output in 'real time'.  There is a slight delay due to buffering.