diff options
Diffstat (limited to 'cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt')
| -rw-r--r-- | cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt | 331 |
1 files changed, 331 insertions, 0 deletions
diff --git a/cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt b/cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt new file mode 100644 index 000000000000..854016e07e9a --- /dev/null +++ b/cddl/contrib/dtracetoolkit/Examples/rb_syscolors_example.txt @@ -0,0 +1,331 @@ +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 +[2;32m0 146499 2 ":- syscall -> munmap[0m +[2;32m0 146499 35 ":- syscall <- munmap[0m +[2;32m0 146499 56 ":- syscall -> mmap[0m +[2;32m0 146499 18 ":- syscall <- mmap[0m +[2;32m0 146499 41 ":- syscall -> setcontext[0m +[2;32m0 146499 10 ":- syscall <- setcontext[0m +[2;32m0 146499 10 ":- syscall -> getrlimit[0m +[2;32m0 146499 11 ":- syscall <- getrlimit[0m +[2;32m0 146499 9 ":- syscall -> getpid[0m +[2;32m0 146499 8 ":- syscall <- getpid[0m +[2;32m0 146499 66 ":- syscall -> setcontext[0m +[2;32m0 146499 8 ":- syscall <- setcontext[0m +[2;32m0 146499 1125 ":- syscall -> sysi86[0m +[2;32m0 146499 12 ":- syscall <- sysi86[0m +[2;32m0 146499 86 ":- syscall -> open64[0m +[2;32m0 146499 89 ":- syscall <- open64[0m +[2;32m0 146499 13 ":- syscall -> ioctl[0m +[2;32m0 146499 35 ":- syscall <- ioctl[0m +[2;32m0 146499 15 ":- syscall -> close[0m +[2;32m0 146499 16 ":- syscall <- close[0m +[2;32m0 146499 141 ":- syscall -> getrlimit64[0m +[2;32m0 146499 10 ":- syscall <- getrlimit64[0m +[2;32m0 146499 37 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 17 ":- syscall <- brk[0m +[2;32m0 146499 19 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 11 ":- syscall <- brk[0m +[2;32m0 146499 495 ":- syscall -> brk[0m +[2;32m0 146499 11 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 55 ":- syscall -> sysconfig[0m +[2;32m0 146499 9 ":- syscall <- sysconfig[0m +[2;32m0 146499 109 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 189 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 161 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 144 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 184 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 129 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 174 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 145 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 129 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 134 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 135 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 136 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 98 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 132 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 125 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 189 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 413 ":- syscall -> brk[0m +[2;32m0 146499 11 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 171 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 137 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 188 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 135 ":- syscall -> sigaction[0m +[2;32m0 146499 10 ":- syscall <- sigaction[0m +[2;32m0 146499 10 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 8 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 9 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 12 ":- syscall -> sigpending[0m +[2;32m0 146499 8 ":- syscall <- sigpending[0m +[2;32m0 146499 15 ":- syscall -> schedctl[0m +[2;32m0 146499 44 ":- syscall <- schedctl[0m +[2;32m0 146499 17 ":- syscall -> lwp_sigmask[0m +[2;32m0 146499 8 ":- syscall <- lwp_sigmask[0m +[2;32m0 146499 9 ":- syscall -> sigaction[0m +[2;32m0 146499 8 ":- syscall <- sigaction[0m +[2;32m0 146499 11 ":- syscall -> lwp_sigmask[0m +[2;32m0 146499 8 ":- syscall <- lwp_sigmask[0m +[2;32m0 146499 9 ":- syscall -> lwp_sigmask[0m +[2;32m0 146499 7 ":- syscall <- lwp_sigmask[0m +[2;32m0 146499 8 ":- syscall -> sigaction[0m +[2;32m0 146499 7 ":- syscall <- sigaction[0m +[2;32m0 146499 8 ":- syscall -> lwp_sigmask[0m +[2;32m0 146499 7 ":- syscall <- lwp_sigmask[0m +[2;32m0 146499 65 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 11 ":- syscall <- brk[0m +[2;32m0 146499 149 ":- syscall -> getuid[0m +[2;32m0 146499 9 ":- syscall <- getuid[0m +[2;32m0 146499 12 ":- syscall -> getgid[0m +[2;32m0 146499 8 ":- syscall <- getgid[0m +[2;32m0 146499 29 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 184 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 171 ":- syscall -> brk[0m +[2;32m0 146499 9 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 10 ":- syscall <- brk[0m +[2;32m0 146499 48 ":- syscall -> getuid[0m +[2;32m0 146499 8 ":- syscall <- getuid[0m +[2;32m0 146499 9 ":- syscall -> getuid[0m +[2;32m0 146499 7 ":- syscall <- getuid[0m +[2;32m0 146499 10 ":- syscall -> getgid[0m +[2;32m0 146499 7 ":- syscall <- getgid[0m +[2;32m0 146499 8 ":- syscall -> getgid[0m +[2;32m0 146499 7 ":- syscall <- getgid[0m +[2;32m0 146499 79 ":- syscall -> open64[0m +[2;32m0 146499 31 ":- syscall <- open64[0m +[2;32m0 146499 14 ":- syscall -> llseek[0m +[2;32m0 146499 9 ":- syscall <- llseek[0m +[2;32m0 146499 9 ":- syscall -> close[0m +[2;32m0 146499 12 ":- syscall <- close[0m +[2;32m0 146499 15 ":- syscall -> open64[0m +[2;32m0 146499 13 ":- syscall <- open64[0m +[2;32m0 146499 21 ":- syscall -> fstat64[0m +[2;32m0 146499 11 ":- syscall <- fstat64[0m +[2;32m0 146499 22 ":- syscall -> read[0m +[2;32m0 146499 36 ":- syscall <- read[0m +[2;32m0 146499 153 ":- syscall -> read[0m +[2;32m0 146499 10 ":- syscall <- read[0m +[2;32m0 146499 11 ":- syscall -> llseek[0m +[2;32m0 146499 8 ":- syscall <- llseek[0m +[2;32m0 146499 8 ":- syscall -> close[0m +[2;32m0 146499 9 ":- syscall <- close[0m +[1;35m0 146499 23 func_abc.rb:3 line -- [0m +[2;35m0 146499 64 func_abc.rb:3 method -> Module::method_added[0m +[2;35m0 146499 24 func_abc.rb:3 method <- Module::method_added[0m +[1;35m0 146499 20 func_abc.rb:8 line -- [0m +[2;35m0 146499 15 func_abc.rb:8 method -> Module::method_added[0m +[2;35m0 146499 13 func_abc.rb:8 method <- Module::method_added[0m +[1;35m0 146499 13 func_abc.rb:14 line -- [0m +[2;35m0 146499 14 func_abc.rb:14 method -> Module::method_added[0m +[2;35m0 146499 13 func_abc.rb:14 method <- Module::method_added[0m +[1;35m0 146499 12 func_abc.rb:20 line -- [0m +[2;35m0 146499 13 func_abc.rb:20 method -> Object::func_a[0m +[1;35m0 146499 12 func_abc.rb:15 line -- [0m +[2;35m0 146499 10 func_abc.rb:15 method -> Object::print[0m +[2;35m0 146499 22 func_abc.rb:15 method -> IO::write[0m +[2;32m0 146499 38 ":- syscall -> ioctl[0m +[2;32m0 146499 11 ":- syscall <- ioctl[0m +[2;32m0 146499 20 ":- syscall -> fstat64[0m +[2;32m0 146499 9 ":- syscall <- fstat64[0m +[2;32m0 146499 9 ":- syscall -> brk[0m +[2;32m0 146499 8 ":- syscall <- brk[0m +[2;32m0 146499 8 ":- syscall -> brk[0m +[2;32m0 146499 11 ":- syscall <- brk[0m +[2;32m0 146499 25 ":- syscall -> fstat64[0m +[2;32m0 146499 8 ":- syscall <- fstat64[0m +[2;35m0 146499 10 func_abc.rb:15 method <- IO::write[0m +[2;35m0 146499 13 func_abc.rb:15 method <- Object::print[0m +[1;35m0 146499 12 func_abc.rb:16 line -- [0m +[2;35m0 146499 10 func_abc.rb:16 method -> Object::sleep[0m +[2;32m0 146499 20 ":- syscall -> gtime[0m +[2;32m0 146499 9 ":- syscall <- gtime[0m +[2;32m0 146499 24 ":- syscall -> pollsys[0m +[2;32m0 146499 1006964 ":- syscall <- pollsys[0m +[2;32m0 146499 26 ":- syscall -> gtime[0m +[2;32m0 146499 14 ":- syscall <- gtime[0m +[2;35m0 146499 18 func_abc.rb:16 method <- Object::sleep[0m +[1;35m0 146499 27 func_abc.rb:17 line -- [0m +[2;35m0 146499 21 func_abc.rb:17 method -> Object::func_b[0m +[1;35m0 146499 19 func_abc.rb:9 line -- [0m +[2;35m0 146499 12 func_abc.rb:9 method -> Object::print[0m +[2;35m0 146499 14 func_abc.rb:9 method -> IO::write[0m +[2;35m0 146499 15 func_abc.rb:9 method <- IO::write[0m +[2;35m0 146499 12 func_abc.rb:9 method <- Object::print[0m +[1;35m0 146499 12 func_abc.rb:10 line -- [0m +[2;35m0 146499 9 func_abc.rb:10 method -> Object::sleep[0m +[2;32m0 146499 12 ":- syscall -> gtime[0m +[2;32m0 146499 8 ":- syscall <- gtime[0m +[2;32m0 146499 11 ":- syscall -> pollsys[0m +[2;32m0 146499 1009739 ":- syscall <- pollsys[0m +[2;32m0 146499 26 ":- syscall -> gtime[0m +[2;32m0 146499 14 ":- syscall <- gtime[0m +[2;35m0 146499 18 func_abc.rb:10 method <- Object::sleep[0m +[1;35m0 146499 27 func_abc.rb:11 line -- [0m +[2;35m0 146499 21 func_abc.rb:11 method -> Object::func_c[0m +[1;35m0 146499 20 func_abc.rb:4 line -- [0m +[2;35m0 146499 12 func_abc.rb:4 method -> Object::print[0m +[2;35m0 146499 14 func_abc.rb:4 method -> IO::write[0m +[2;35m0 146499 15 func_abc.rb:4 method <- IO::write[0m +[2;35m0 146499 12 func_abc.rb:4 method <- Object::print[0m +[1;35m0 146499 12 func_abc.rb:5 line -- [0m +[2;35m0 146499 9 func_abc.rb:5 method -> Object::sleep[0m +[2;32m0 146499 12 ":- syscall -> gtime[0m +[2;32m0 146499 8 ":- syscall <- gtime[0m +[2;32m0 146499 11 ":- syscall -> pollsys[0m +Function A +Function B +Function C +[2;32m0 146499 1009762 ":- syscall <- pollsys[0m +[2;32m0 146499 25 ":- syscall -> gtime[0m +[2;32m0 146499 14 ":- syscall <- gtime[0m +[2;35m0 146499 19 func_abc.rb:5 method <- Object::sleep[0m +[2;35m0 146499 26 func_abc.rb:5 method <- Object::func_c[0m +[2;35m0 146499 13 func_abc.rb:11 method <- Object::func_b[0m +[2;35m0 146499 13 func_abc.rb:17 method <- Object::func_a[0m +[2;32m0 146499 33 ":- syscall -> sigaction[0m +[2;32m0 146499 10 ":- syscall <- sigaction[0m +[2;32m0 146499 100 ":- syscall -> open64[0m +[2;32m0 146499 107 ":- syscall <- open64[0m +[2;32m0 146499 10 ":- syscall -> ioctl[0m +[2;32m0 146499 10 ":- syscall <- ioctl[0m +[2;32m0 146499 11 ":- syscall -> close[0m +[2;32m0 146499 17 ":- syscall <- close[0m +[2;32m0 146499 28 ":- syscall -> write[0m +[2;32m0 146499 20 ":- syscall <- write[0m +[2;32m0 146499 11 ":- syscall -> rexit[0m + +Here you can see the output showing the path the program follows in its +execution. + +ie: +[2;35m0 146499 10 func_abc.rb:16 method -> Object::sleep[0m +[2;32m0 146499 20 ":- syscall -> gtime[0m +[2;32m0 146499 9 ":- syscall <- gtime[0m +[2;32m0 146499 24 ":- syscall -> pollsys[0m +[2;32m0 146499 1006964 ":- syscall <- pollsys[0m +[2;32m0 146499 26 ":- syscall -> gtime[0m +[2;32m0 146499 14 ":- syscall <- gtime[0m +[2;35m0 146499 18 func_abc.rb:16 method <- Object::sleep[0m +[1;35m0 146499 27 func_abc.rb:17 line -- [0m +[2;35m0 146499 21 func_abc.rb:17 method -> Object::func_b[0m +[1;35m0 146499 19 func_abc.rb:9 line -- [0m +[2;35m0 146499 12 func_abc.rb:9 method -> Object::print[0m +[2;35m0 146499 14 func_abc.rb:9 method -> IO::write[0m +[2;35m0 146499 15 func_abc.rb:9 method <- IO::write[0m +[2;35m0 146499 12 func_abc.rb:9 method <- Object::print[0m +[1;35m0 146499 12 func_abc.rb:10 line -- [0m + +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. |