The following are examples of rb_syscolors.d. This is a simple script to trace the method flow of Ruby functions within a program, and the system calls made. It renders the output in color ("colour") using terminal escape sequences (which you can tweak by modifying the script). Here it traces the example program, Code/Ruby/func_abc.rb. WARNING: This output is full of terminal escape sequences, so if you are trying to view this through an editor or web browser - it may look awful. Try viewing this using "more" (although, depending on your terminal, it still may look awful). # rb_syscolors.d -c ./func_abc.rb C PID DELTA(us) FILE:LINE TYPE -- NAME 0 146499 2 ":- syscall -> munmap 0 146499 35 ":- syscall <- munmap 0 146499 56 ":- syscall -> mmap 0 146499 18 ":- syscall <- mmap 0 146499 41 ":- syscall -> setcontext 0 146499 10 ":- syscall <- setcontext 0 146499 10 ":- syscall -> getrlimit 0 146499 11 ":- syscall <- getrlimit 0 146499 9 ":- syscall -> getpid 0 146499 8 ":- syscall <- getpid 0 146499 66 ":- syscall -> setcontext 0 146499 8 ":- syscall <- setcontext 0 146499 1125 ":- syscall -> sysi86 0 146499 12 ":- syscall <- sysi86 0 146499 86 ":- syscall -> open64 0 146499 89 ":- syscall <- open64 0 146499 13 ":- syscall -> ioctl 0 146499 35 ":- syscall <- ioctl 0 146499 15 ":- syscall -> close 0 146499 16 ":- syscall <- close 0 146499 141 ":- syscall -> getrlimit64 0 146499 10 ":- syscall <- getrlimit64 0 146499 37 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 17 ":- syscall <- brk 0 146499 19 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 11 ":- syscall <- brk 0 146499 495 ":- syscall -> brk 0 146499 11 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 55 ":- syscall -> sysconfig 0 146499 9 ":- syscall <- sysconfig 0 146499 109 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 189 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 161 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 144 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 184 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 129 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 174 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 145 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 129 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 134 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 135 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 136 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 98 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 132 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 125 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 189 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 413 ":- syscall -> brk 0 146499 11 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 171 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 137 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 188 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 135 ":- syscall -> sigaction 0 146499 10 ":- syscall <- sigaction 0 146499 10 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 8 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 9 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 12 ":- syscall -> sigpending 0 146499 8 ":- syscall <- sigpending 0 146499 15 ":- syscall -> schedctl 0 146499 44 ":- syscall <- schedctl 0 146499 17 ":- syscall -> lwp_sigmask 0 146499 8 ":- syscall <- lwp_sigmask 0 146499 9 ":- syscall -> sigaction 0 146499 8 ":- syscall <- sigaction 0 146499 11 ":- syscall -> lwp_sigmask 0 146499 8 ":- syscall <- lwp_sigmask 0 146499 9 ":- syscall -> lwp_sigmask 0 146499 7 ":- syscall <- lwp_sigmask 0 146499 8 ":- syscall -> sigaction 0 146499 7 ":- syscall <- sigaction 0 146499 8 ":- syscall -> lwp_sigmask 0 146499 7 ":- syscall <- lwp_sigmask 0 146499 65 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 11 ":- syscall <- brk 0 146499 149 ":- syscall -> getuid 0 146499 9 ":- syscall <- getuid 0 146499 12 ":- syscall -> getgid 0 146499 8 ":- syscall <- getgid 0 146499 29 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 184 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 9 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 171 ":- syscall -> brk 0 146499 9 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 10 ":- syscall <- brk 0 146499 48 ":- syscall -> getuid 0 146499 8 ":- syscall <- getuid 0 146499 9 ":- syscall -> getuid 0 146499 7 ":- syscall <- getuid 0 146499 10 ":- syscall -> getgid 0 146499 7 ":- syscall <- getgid 0 146499 8 ":- syscall -> getgid 0 146499 7 ":- syscall <- getgid 0 146499 79 ":- syscall -> open64 0 146499 31 ":- syscall <- open64 0 146499 14 ":- syscall -> llseek 0 146499 9 ":- syscall <- llseek 0 146499 9 ":- syscall -> close 0 146499 12 ":- syscall <- close 0 146499 15 ":- syscall -> open64 0 146499 13 ":- syscall <- open64 0 146499 21 ":- syscall -> fstat64 0 146499 11 ":- syscall <- fstat64 0 146499 22 ":- syscall -> read 0 146499 36 ":- syscall <- read 0 146499 153 ":- syscall -> read 0 146499 10 ":- syscall <- read 0 146499 11 ":- syscall -> llseek 0 146499 8 ":- syscall <- llseek 0 146499 8 ":- syscall -> close 0 146499 9 ":- syscall <- close 0 146499 23 func_abc.rb:3 line --  0 146499 64 func_abc.rb:3 method -> Module::method_added 0 146499 24 func_abc.rb:3 method <- Module::method_added 0 146499 20 func_abc.rb:8 line --  0 146499 15 func_abc.rb:8 method -> Module::method_added 0 146499 13 func_abc.rb:8 method <- Module::method_added 0 146499 13 func_abc.rb:14 line --  0 146499 14 func_abc.rb:14 method -> Module::method_added 0 146499 13 func_abc.rb:14 method <- Module::method_added 0 146499 12 func_abc.rb:20 line --  0 146499 13 func_abc.rb:20 method -> Object::func_a 0 146499 12 func_abc.rb:15 line --  0 146499 10 func_abc.rb:15 method -> Object::print 0 146499 22 func_abc.rb:15 method -> IO::write 0 146499 38 ":- syscall -> ioctl 0 146499 11 ":- syscall <- ioctl 0 146499 20 ":- syscall -> fstat64 0 146499 9 ":- syscall <- fstat64 0 146499 9 ":- syscall -> brk 0 146499 8 ":- syscall <- brk 0 146499 8 ":- syscall -> brk 0 146499 11 ":- syscall <- brk 0 146499 25 ":- syscall -> fstat64 0 146499 8 ":- syscall <- fstat64 0 146499 10 func_abc.rb:15 method <- IO::write 0 146499 13 func_abc.rb:15 method <- Object::print 0 146499 12 func_abc.rb:16 line --  0 146499 10 func_abc.rb:16 method -> Object::sleep 0 146499 20 ":- syscall -> gtime 0 146499 9 ":- syscall <- gtime 0 146499 24 ":- syscall -> pollsys 0 146499 1006964 ":- syscall <- pollsys 0 146499 26 ":- syscall -> gtime 0 146499 14 ":- syscall <- gtime 0 146499 18 func_abc.rb:16 method <- Object::sleep 0 146499 27 func_abc.rb:17 line --  0 146499 21 func_abc.rb:17 method -> Object::func_b 0 146499 19 func_abc.rb:9 line --  0 146499 12 func_abc.rb:9 method -> Object::print 0 146499 14 func_abc.rb:9 method -> IO::write 0 146499 15 func_abc.rb:9 method <- IO::write 0 146499 12 func_abc.rb:9 method <- Object::print 0 146499 12 func_abc.rb:10 line --  0 146499 9 func_abc.rb:10 method -> Object::sleep 0 146499 12 ":- syscall -> gtime 0 146499 8 ":- syscall <- gtime 0 146499 11 ":- syscall -> pollsys 0 146499 1009739 ":- syscall <- pollsys 0 146499 26 ":- syscall -> gtime 0 146499 14 ":- syscall <- gtime 0 146499 18 func_abc.rb:10 method <- Object::sleep 0 146499 27 func_abc.rb:11 line --  0 146499 21 func_abc.rb:11 method -> Object::func_c 0 146499 20 func_abc.rb:4 line --  0 146499 12 func_abc.rb:4 method -> Object::print 0 146499 14 func_abc.rb:4 method -> IO::write 0 146499 15 func_abc.rb:4 method <- IO::write 0 146499 12 func_abc.rb:4 method <- Object::print 0 146499 12 func_abc.rb:5 line --  0 146499 9 func_abc.rb:5 method -> Object::sleep 0 146499 12 ":- syscall -> gtime 0 146499 8 ":- syscall <- gtime 0 146499 11 ":- syscall -> pollsys Function A Function B Function C 0 146499 1009762 ":- syscall <- pollsys 0 146499 25 ":- syscall -> gtime 0 146499 14 ":- syscall <- gtime 0 146499 19 func_abc.rb:5 method <- Object::sleep 0 146499 26 func_abc.rb:5 method <- Object::func_c 0 146499 13 func_abc.rb:11 method <- Object::func_b 0 146499 13 func_abc.rb:17 method <- Object::func_a 0 146499 33 ":- syscall -> sigaction 0 146499 10 ":- syscall <- sigaction 0 146499 100 ":- syscall -> open64 0 146499 107 ":- syscall <- open64 0 146499 10 ":- syscall -> ioctl 0 146499 10 ":- syscall <- ioctl 0 146499 11 ":- syscall -> close 0 146499 17 ":- syscall <- close 0 146499 28 ":- syscall -> write 0 146499 20 ":- syscall <- write 0 146499 11 ":- syscall -> rexit Here you can see the output showing the path the program follows in its execution. ie: 0 146499 10 func_abc.rb:16 method -> Object::sleep 0 146499 20 ":- syscall -> gtime 0 146499 9 ":- syscall <- gtime 0 146499 24 ":- syscall -> pollsys 0 146499 1006964 ":- syscall <- pollsys 0 146499 26 ":- syscall -> gtime 0 146499 14 ":- syscall <- gtime 0 146499 18 func_abc.rb:16 method <- Object::sleep 0 146499 27 func_abc.rb:17 line --  0 146499 21 func_abc.rb:17 method -> Object::func_b 0 146499 19 func_abc.rb:9 line --  0 146499 12 func_abc.rb:9 method -> Object::print 0 146499 14 func_abc.rb:9 method -> IO::write 0 146499 15 func_abc.rb:9 method <- IO::write 0 146499 12 func_abc.rb:9 method <- Object::print 0 146499 12 func_abc.rb:10 line --  shows that on cpu 0 the program is running a sleep command at line 16 of the func_abc.rb program (the pollsys and gtime syscalls are used in the Ruby engine to implement sleep). Then func_b runs, and prints a line (using Object::print which uses IO::write). Notice that the 'write' syscall does not happen until later. It is probably being buffered by Ruby - you can confirm this through further DTracing. Notice also tht you can see the output of the program: Function A Function B Function C in the file happening before the write syscall is run. DTrace does not do its output in 'real time'. There is a slight delay due to buffering.