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