1N/AThe following is a demonstration of the dapptrace command,
1N/A
1N/AThis is the usage for version 0.60,
1N/A
1N/A # dapptrace -h
1N/A USAGE: dapptrace [-acdeholFLU] [-u lib] { -p PID | command }
1N/A
1N/A -p PID # examine this PID
1N/A -a # print all details
1N/A -c # print syscall counts
1N/A -d # print relative times (us)
1N/A -e # print elapsed times (us)
1N/A -F # print flow indentation
1N/A -l # print pid/lwpid
1N/A -o # print CPU on cpu times
1N/A -u lib # trace this library instead
1N/A -U # trace all libraries + user funcs
1N/A -b bufsize # dynamic variable buf size
1N/A eg,
1N/A dapptrace df -h # run and examine "df -h"
1N/A dapptrace -p 1871 # examine PID 1871
1N/A dapptrace -Fp 1871 # print using flow indents
1N/A dapptrace -eop 1871 # print elapsed and CPU times
1N/A
1N/A
1N/A
1N/AThe following is an example of the default output. We run dapptrace with
1N/Athe "banner hello" command,
1N/A
1N/A # dapptrace banner hi
1N/A
1N/A # # #
1N/A # # #
1N/A ###### #
1N/A # # #
1N/A # # #
1N/A # # #
1N/A
1N/A CALL(args) = return
1N/A -> __fsr(0x2, 0x8047D7C, 0x8047D88)
1N/A <- __fsr = 122
1N/A -> main(0x2, 0x8047D7C, 0x8047D88)
1N/A -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
1N/A -> banset(0x20, 0x80614C2, 0x8047DCC)
1N/A <- banset = 36
1N/A -> convert(0x68, 0x8047DCC, 0x2)
1N/A <- convert = 319
1N/A -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
1N/A <- banfil = 57
1N/A -> convert(0x69, 0x8047DCC, 0x2)
1N/A <- convert = 319
1N/A -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
1N/A <- banfil = 57
1N/A <- banner = 118
1N/A -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
1N/A <- banprt = 74
1N/A
1N/AThe default output shows user function calls. An entry is prefixed
1N/Awith a "->", and the return has a "<-".
1N/A
1N/A
1N/A
1N/AHere we run dapptrace with the -F for flow indent option,
1N/A
1N/A # dapptrace -F banner hi
1N/A
1N/A # # #
1N/A # # #
1N/A ###### #
1N/A # # #
1N/A # # #
1N/A # # #
1N/A
1N/A CALL(args) = return
1N/A -> __fsr(0x2, 0x8047D7C, 0x8047D88)
1N/A <- __fsr = 122
1N/A -> main(0x2, 0x8047D7C, 0x8047D88)
1N/A -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
1N/A -> banset(0x20, 0x80614C2, 0x8047DCC)
1N/A <- banset = 36
1N/A -> convert(0x68, 0x8047DCC, 0x2)
1N/A <- convert = 319
1N/A -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
1N/A <- banfil = 57
1N/A -> convert(0x69, 0x8047DCC, 0x2)
1N/A <- convert = 319
1N/A -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
1N/A <- banfil = 57
1N/A <- banner = 118
1N/A -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
1N/A <- banprt = 74
1N/A
1N/AThe above output illustrates the flow of the program, which functions
1N/Acall which other functions.
1N/A
1N/A
1N/A
1N/ANow the same command is run with -d to display relative timestamps,
1N/A
1N/A # dapptrace -dF banner hi
1N/A
1N/A # # #
1N/A # # #
1N/A ###### #
1N/A # # #
1N/A # # #
1N/A # # #
1N/A
1N/A RELATIVE CALL(args) = return
1N/A 2512 -> __fsr(0x2, 0x8047D7C, 0x8047D88)
1N/A 2516 <- __fsr = 122
1N/A 2518 -> main(0x2, 0x8047D7C, 0x8047D88)
1N/A 2863 -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
1N/A 2865 -> banset(0x20, 0x80614C2, 0x8047DCC)
1N/A 2872 <- banset = 36
1N/A 2874 -> convert(0x68, 0x8047DCC, 0x2)
1N/A 2877 <- convert = 319
1N/A 2879 -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
1N/A 2882 <- banfil = 57
1N/A 2883 -> convert(0x69, 0x8047DCC, 0x2)
1N/A 2885 <- convert = 319
1N/A 2886 -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
1N/A 2888 <- banfil = 57
1N/A 2890 <- banner = 118
1N/A 2892 -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
1N/A 3214 <- banprt = 74
1N/A
1N/AThe relative times are in microseconds since the program's invocation. Great!
1N/A
1N/A
1N/A
1N/AEven better is if we use the -eo options, to print elapsed times and on-cpu
1N/Atimes,
1N/A
1N/A # dapptrace -eoF banner hi
1N/A
1N/A # # #
1N/A # # #
1N/A ###### #
1N/A # # #
1N/A # # #
1N/A # # #
1N/A
1N/A ELAPSD CPU CALL(args) = return
1N/A . . -> __fsr(0x2, 0x8047D7C, 0x8047D88)
1N/A 41 4 <- __fsr = 122
1N/A . . -> main(0x2, 0x8047D7C, 0x8047D88)
1N/A . . -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
1N/A . . -> banset(0x20, 0x80614C2, 0x8047DCC)
1N/A 29 6 <- banset = 36
1N/A . . -> convert(0x68, 0x8047DCC, 0x2)
1N/A 26 3 <- convert = 319
1N/A . . -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
1N/A 25 2 <- banfil = 57
1N/A . . -> convert(0x69, 0x8047DCC, 0x2)
1N/A 23 1 <- convert = 319
1N/A . . -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
1N/A 23 1 <- banfil = 57
1N/A 309 28 <- banner = 118
1N/A . . -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
1N/A 349 322 <- banprt = 74
1N/A
1N/ANow it is easy to see which functions take the longest (elapsed), and
1N/Awhich consume the most CPU cycles.
1N/A
1N/A
1N/A
1N/AThe following demonstrates the -U option, to trace all libraries,
1N/A
1N/A # dapptrace -U banner hi
1N/A
1N/A # # #
1N/A # # #
1N/A ###### #
1N/A # # #
1N/A # # #
1N/A # # #
1N/A
1N/A CALL(args) = return
1N/A -> ld.so.1:_rt_boot(0x8047E34, 0x8047E3B, 0x0)
1N/A -> ld.so.1:_setup(0x8047D38, 0x20AE4, 0x3)
1N/A -> ld.so.1:setup(0x8047D88, 0x8047DCC, 0x0)
1N/A -> ld.so.1:fmap_setup(0x0, 0xD27FB2E4, 0xD27FB824)
1N/A <- ld.so.1:fmap_setup = 125
1N/A -> ld.so.1:addfree(0xD27FD3C0, 0xC40, 0x0)
1N/A <- ld.so.1:addfree = 65
1N/A -> ld.so.1:security(0xFFFFFFFF, 0xFFFFFFFF, 0xFFFFFFFF)
1N/A <- ld.so.1:security = 142
1N/A -> ld.so.1:readenv_user(0x8047D88, 0xD27FB204, 0xD27FB220)
1N/A -> ld.so.1:ld_str_env(0x8047E3E, 0xD27FB204, 0xD27FB220)
1N/A <- ld.so.1:ld_str_env = 389
1N/A -> ld.so.1:ld_str_env(0x8047E45, 0xD27FB204, 0xD27FB220)
1N/A <- ld.so.1:ld_str_env = 389
1N/A -> ld.so.1:ld_str_env(0x8047E49, 0xD27FB204, 0xD27FB220)
1N/A <- ld.so.1:ld_str_env = 389
1N/A -> ld.so.1:ld_str_env(0x8047E50, 0xD27FB204, 0xD27FB220)
1N/A -> ld.so.1:strncmp(0x8047E53, 0xD27F7BEB, 0x4)
1N/A <- ld.so.1:strncmp = 113
1N/A -> ld.so.1:rd_event(0xD27FB1F8, 0x3, 0x0)
1N/A [...4486 lines deleted...]
1N/A -> ld.so.1:_lwp_mutex_unlock(0xD27FD380, 0xD27FB824, 0x8047C04)
1N/A <- ld.so.1:_lwp_mutex_unlock = 47
1N/A <- ld.so.1:rt_mutex_unlock = 34
1N/A -> ld.so.1:rt_bind_clear(0x1, 0xD279ECC0, 0xD27FDB2C)
1N/A <- ld.so.1:rt_bind_clear = 34
1N/A <- ld.so.1:leave = 210
1N/A <- ld.so.1:elf_bndr = 803
1N/A <- ld.so.1:elf_rtbndr = 35
1N/A
1N/AThe output was huge, around 4500 lines long. Function names are prefixed
1N/Awith their library name, eg "ld.so.1".
1N/A
1N/AThis full output should be used with caution, as it enables so many probes
1N/Ait could well be a burden on the system.
1N/A