LINUX_book
456 pág.

LINUX_book


DisciplinaLinux712 materiais1.839 seguidores
Pré-visualização50 páginas
1 total
It can also be useful to time both the difference between system call entries
and the time spent in the system calls. With this information, it is possible to
get the time spent in the user code between the system calls. Keep in mind that
this isn\u2019t very accurate unless there is a considerable amount of time spent in
the user code. It also requires writing a small script to parse the strace output.
ion 250% strace -Tr main
0.000000 execve(\u201c./main\u201d, [\u201cmain\u201d], [/* 64 vars */]) = 0
0.000931 fcntl64(0, F_GETFD) = 0 <0.000012>
0.000090 fcntl64(1, F_GETFD) = 0 <0.000022>
0.000060 fcntl64(2, F_GETFD) = 0 <0.000012>
0.000054 uname({sys=\u201dLinux\u201d, node=\u201dion\u201d, ...}) = 0 <0.000014>
0.000307 geteuid32() = 7903 <0.000011>
0.000040 getuid32() = 7903 <0.000012>
0.000039 getegid32() = 200 <0.000011>
0.000039 getgid32() = 200 <0.000011>
0.000075 brk(0) = 0x80a3ce8 <0.000012>
0.000050 brk(0x80a3d08) = 0x80a3d08 <0.000012>
0.000043 brk(0x80a4000) = 0x80a4000 <0.000011>
0.000054 brk(0x80a5000) = 0x80a5000 <0.000013>
0.000058 open(\u201c/tmp/foo\u201d, O_RDONLY) = -1 ENOENT (No such file or
\u27a5directory) <0.000024>
0.000095 _exit(5) = ?
2.3 Important strace Options
Note: Some of the time spent may not be due to a system call or user
code but may be due to the scheduling behavior of the system. The program
may not execute on a CPU for a small period of time on a busy system
because other programs are competing for CPU time.
2.3.3 Verbose Mode
By default, strace does not include all of the information for every system call.
It usually provides a good balance between enough information and too much.
However, there are times when more information is required to diagnose a
problem. The verbose option -v tells strace to include full information for system
calls such as stat or uname.
ion 251% strace -v main
execve(\u201c./main\u201d, [\u201cmain\u201d], [/* 64 vars */]) = 0
fcntl64(0, F_GETFD) = 0
fcntl64(1, F_GETFD) = 0
58 strace and System Call Tracing Explained Chap. 2
fcntl64(2, F_GETFD) = 0
uname({sysname=\u201dLinux\u201d, nodename=\u201dion\u201d, release=\u201d2.4.19-64GB-SMP\u201d,
\u27a5version=\u201d#1 SMP Mon Oct 21 18:48:05
UTC 2002&quot;, machine=\u201di686&quot;}) = 0
geteuid32() = 7903
getuid32() = 7903
getegid32() = 200
getgid32() = 200
brk(0) = 0x80a3ce8
brk(0x80a3d08) = 0x80a3d08
brk(0x80a4000) = 0x80a4000
brk(0x80a5000) = 0x80a5000
open(\u201c/tmp/foo\u201d, O_RDONLY) = -1 ENOENT (No such file or
\u27a5directory)
_exit(5) = ?
Notice that the uname system call is fully formatted with all information
included. Compare this to the preceding examples (such as the strace of the
statically linked program):
uname({sys=\u201dLinux\u201d, node=\u201dion\u201d, ...}) = 0
Another verbose feature is -s, which can be useful for showing more information
for the read and write system calls. This option can be used to set the maximum
size of a string to a certain value.
ion 687% strace dd if=strace.strace of=/dev/null bs=32768 |& tail
\u27a5-15 | head -10
write(1, \u201cDATA, 30354, 0xbfffe458, [0x2e6f\u201d..., 32768) = 32768
read(0, \u201cETFD, FD_CLOEXEC\\u201d, 30) = 30\nptra\u201d..., 32768) = 32768
write(1, \u201cETFD, FD_CLOEXEC\\u201d, 30) = 30\nptra\u201d..., 32768) = 32768
read(0, \u201ced) \u2014\nrt_sigprocmask(SIG_BLOCK\u201d..., 32768) = 32768
write(1, \u201ced) \u2014\nrt_sigprocmask(SIG_BLOCK\u201d..., 32768) = 32768
read(0, \u201c) && WSTOPSIG(s) == SIGTRAP], 0x\u201d..., 32768) = 7587
write(1, \u201c) && WSTOPSIG(s) == SIGTRAP], 0x\u201d..., 7587) = 7587
read(0, \u201c\u201d, 32768) = 0
write(2, \u201c7+1 records in\n\u201d, 157+1 records in
) = 15
Of course, this shows very little information about the contents that were read
or written by dd. In many cases, an investigation requires more or all of the
information. Using the switch -s 256, the same system call trace will show 256
bytes of information for each read/write:
ion 688% strace -s 256 dd if=strace.strace of=/dev/null bs=32768 | &
tail -15 | head -10
\u27a5write(1, \u201cDATA, 30354, 0xbfffe458, [0x2e6f732e]) =
0\nptrace(PTRACE_PEEKDATA, 30354, 0xbfffe45c, [0xbfff0031]) =
59
0\nwrite(2, \\u201dopen(\\\\u201d/home/wilding/sqllib/lib/l\\u201d..., 54) =
54\nptrace(PTRACE_SYSCALL, 30354, 0x1, SIG_0) = 0\n\u2014 SIGCHLD (Child
exited) \u2014\nrt_sigprocmask(SI\u201d..., 32768) = 32768
\u27a5read(0, \u201cETFD, FD_CLOEXEC\\u201d, 30) = 30\nptrace(PTRACE_SYSCALL,
30354, 0x1, SIG_0) = 0\n\u2014 SIGCHLD (Child exited) \u2014
\nrt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\nwait4(-1,
[WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =
30354\nrt_sigprocmask(SIG_BLOCK, [\u201c..., 32768) = 32768
\u27a5write(1, \u201cETFD, FD_CLOEXEC\\u201d, 30) = 30\nptrace(PTRACE_SYSCALL,
30354, 0x1, SIG_0) = 0\n\u2014 SIGCHLD (Child exited) \u2014
\nrt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0\nwait4(-1,
[WIFSTOPPED(s) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =
30354\nrt_sigprocmask(SIG_BLOCK, [\u201c..., 32768) = 32768
\u27a5read(0, \u201ced) \u2014\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE TERM],
NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX, [0x4]) =
0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]) =
0\nptrace(PTRACE_PEEKUSER, 30354, 4*EBX, [0x1]) =
0\nptrace(PTRACE_PEEKUSER, \u201c..., 32768) = 32768
\u27a5write(1, \u201ced) \u2014\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT PIPE
TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX,
[0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]) =
0\nptrace(PTRACE_PEEKUSER, 30354, 4*EBX, [0x1]) =
0\nptrace(PTRACE_PEEKUSER, \u201c..., 32768) = 32768
\u27a5read(0, \u201c) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) = 30354\n\u2014
SIGCHLD (Child exited) \u2014\nrt_sigprocmask(SIG_BLOCK, [HUP INT QUIT
PIPE TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*ORIG_EAX,
[0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX, [0xffffffda]\u201d...,
32768) = 7587
\u27a5write(1, \u201c) && WSTOPSIG(s) == SIGTRAP], 0x40000000, NULL) =
30354\n\u2014 SIGCHLD (Child exited) \u2014\nrt_sigprocmask(SIG_BLOCK, [HUP
INT QUIT PIPE TERM], NULL, 8) = 0\nptrace(PTRACE_PEEKUSER, 30354,
4*ORIG_EAX, [0x4]) = 0\nptrace(PTRACE_PEEKUSER, 30354, 4*EAX,
[0xffffffda]\u201d..., 7587) = 7587
\u27a5read(0, \u201c\u201d, 32768) = 0
\u27a5write(2, \u201c7+1 records in\n\u201d, 157+1 records in\u201d ) = 15
The amount of information shown in the strace output here is pretty
intimidating, and you can see why strace doesn\u2019t include all of the information
by default. Use the -s switch only when needed.
2.3.4 Tracing a Running Process
Sometimes it is necessary to trace an existing process that is running, such as
a Web daemon (such as apache) or xinetd. The strace tool provides a simple
way to attach to running processes with the -p switch:
ion 257% strace -p 3423
2.3 Important strace Options
60 strace and System Call Tracing Explained Chap. 2
Once attached, both the strace tool and the traced process behave as if strace
ran the process off of the command line. Attaching to a running process
establishes a special parent-child relationship between the tracing process and
the traced process. Everything is pretty much the same after strace is attached.
All of the same strace options work whether strace is used to trace a program
off of the command line or whether strace is used to attach to a running process.
2.4 EFFECTS AND ISSUES OF USING STRACE
The strace tool is somewhat intrusive (although it isn\u2019t too bad). It will slow
down the traced process, and it may also wake up a sleeping process if the
process is waiting in the pause() function. It is rare that strace actually causes
any major problems, but it is good to be aware of the effects.
The strace tool prints its output to stderr, which makes it a bit easier to
separate the output