Rastreamento de processos com o strace
ter, 22/01/2008 - 21:16 — HAmc
Talvez a habilidade mais importante e exigida de um administrador de sistemas é a resolução de problemas. Durante uma falha, esses profissionais se vêem constantemente sob enorme pressão e estresse, enquanto procuram obter informações para analisá-las e, assim, providenciar as correções necessárias.
Nesse ambiente regularmente caótico, a família Unix é excepcional ao oferecer uma variedade de ferramentas para facilitar o trabalho do administrador de sistemas. Entre essas ferramentas está o strace.
O propósito central do strace é rastrear as chamadas de sistema (system calls) produzidas por um determinado processo. Conexões TCP/IP e arquivos abertos pelo processo são algumas das muitas informações possíveis de se colher durante um rastreamento. Essas informações, aparentemente ingênuas, podem ser de grande valor para o administrador corrigir um problema do sistema, ou até mesmo para satisfazer sua intrínseca curiosidade sobre o funcionamento de um programa.
Chamadas de sistema
Por definição, uma chamada de sistema é um método usado pelo processo para requisitar um serviço do sistema operacional, ou mais especificamente, do kernel. O conjunto de chamadas de sistema fornecido pelo kernel pode ser considerado a camada de abstração entre o sistema operacional e um programa do usuário.
O bom entendimento das chamadas de sistema exige o conhecimento básico sobre linguagens de programação, preferencialmente da linguagem C. O seu conceito é o mesmo de uma função, já que recebe parâmetros e retorna um valor de acordo com os resultados obtidos.
Para exemplificar esse conceito, quando um processo precisa de informações sobre um determinado arquivo, ele usa a chamada de sistema stat(), passando como único parâmetro o caminho do arquivo. A partir disso, o kernel do sistema operacional encarrega-se de obter as informações sobre esse arquivo e repassá-las para o processo.
Colocando esse exemplo em um resultado prático, a chamada de sistema stat() aparece da seguinte maneira em um rastreamento do strace:
stat("/etc/localtime", {st_dev=makedev(253, 0), st_ino=34494, st_mode=S_IFREG|0644, st_nlink=1, st_uid=0, st_gid=0, st_blksize=4096, st_blocks=8, st_size=721, st_atime=2008/01/19-16:00:26, st_mtime=2007/10/08-09:48:25, st_ctime=2007/10/08-09:48:25}) = 0
Nota-se que o primeiro parâmetro do stat() é o arquivo /etc/localtime, do qual o processo rastreado requisitou as informações. O segundo parâmetro é justamente as informações requistadas do arquivo /etc/localtime já repassadas pelo kernel, em uma estrutura com os valores separados por vírgula e dentro de chaves. Entre os valores estão as permissões de acesso (st_mode), o tamanho do arquivo (st_size), o horário de criação (st_ctime), etc.
O valor após o sinal de igual é o resultado, ou valor de retorno, da chamada de sistema. No exemplo citado, o valor 0 (zero) retornado pelo stat() indica que sua execução ocorreu sem problemas. Cada chamada de sistema possuí diferentes valores de retorno, de acordo com o sucesso ou falha específica.
Não é o objetivo desse artigo enumerar e detalhar todas as chamadas de sistema existentes. Para conseguir mais informações, o UNIX provê uma massiva documentação sobre elas em suas boas e velhas páginas de manuais. Por exemplo, para ler mais sobre o stat() o comando é:
# man 2 stat
A possibilidade de rastrear todas as chamadas de sistema de um programa permite aprender mais sobre sua iteração com o sistema operacional, e ao mesmo tempo, determinar possíveis causas sobre um erro desconhecido.
strace
O strace foi inicialmente desenvolvido para o sistema operacional SunOS - conhecido atualmente como Solaris - e posteriormente portado para outros sistemas operacionais, incluindo o FreeBSD e o Linux. A portabilidade do strace é complexa pelo fato dele exigir modificações no kernel do sistema operacional para implementar os mecanismos de rastreamento.
No Linux, o mecanismo de rastreamento do strace é baseado em uma chamada de sistema: o ptrace(). Ele fornece um conjunto de sinais para que um processo controle e observe a execução de um outro processo.
Levando em consideração os detalhes de implementação no Linux, é possível resumir, de forma bastante simplista, os passos de um rastreamento com o seguinte roteiro:
- O usuário executa o strace passando como argumento o programa que deseja rastrear, ou o PID de um processo já existente.
- Através da chamada de sistema ptrace(), o strace envia o sinal PTRACE_TRACEME e executa o programa informado. No caso de um processo já existente, ele envia o sinal PTRACE_ATTACH.
- Após o envio do sinal apropriado, o strace usa o próprio ptrace() para interceptar todas as chamadas de sistema feitas pelo processo rastreado.
- O rastreamento é interrompido assim que o processo for finalizado, ou através dos sinais PTRACE_KILL ou PTRACE_DETACH.
Ao mesmo tempo em que a sintaxe do comando strace é simples, ele aceita uma grande variedade de opções que podem ser úteis no rastreamento de um processo ou na visualização de seu resultado. As formas mais usuais de execução estão listadas e comentadas a seguir:
- O strace executa o comando especificado e faz o rastreamento de suas chamadas de sistema, mostrando as informações diretamente no terminal ou console.
- Mesma situação do comando anterior, contudo, as informações de rastreamento serão enviadas para o arquivo especificado, ao invés do terminal ou console.
- Faz o rastreamento de um processo em execução com o PID informado.
# strace COMMANDO
# strace COMMANDO -o ARQUIVO
# strace -p PID
Para conhecer todas as opções disponíveis no strace, é recomendada a leitura de sua página de manual:
# man strace
Exemplos
O primeiro exemplo é o rastreamento de um comando fácil de compreender: o pwd. Um programa que apenas retorna o diretório corrente do usuário.
# strace pwd
1 execve("/bin/pwd", ["pwd"], [/* 19 vars */]) = 0
2 uname({sys="Linux", node="ns2.centralserver.com.br", ...}) = 0
3 brk(0) = 0x82bd000
4 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
5 open("/etc/ld.so.cache", O_RDONLY) = 3
6 fstat64(3, {st_mode=S_IFREG|0644, st_size=26266, ...}) = 0
7 old_mmap(NULL, 26266, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f89000
8 close(3) = 0
9 open("/lib/tls/libc.so.6", O_RDONLY) = 3
10 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320N\1\0004\0\0\0"..., 512) = 512
11 fstat64(3, {st_mode=S_IFREG|0755, st_size=1526024, ...}) = 0
12 old_mmap(NULL, 1227964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xcbf000
13 old_mmap(0xde5000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x125000) = 0xde5000
14 old_mmap(0xde9000, 7356, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xde9000
15 close(3) = 0
16 old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f88000
17 mprotect(0xde5000, 8192, PROT_READ) = 0
18 mprotect(0xc8b000, 4096, PROT_READ) = 0
19 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7f88aa0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
20 munmap(0xb7f89000, 26266) = 0
21 brk(0) = 0x82bd000
22 brk(0x82de000) = 0x82de000
23 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3
24 fstat64(3, {st_mode=S_IFREG|0644, st_size=48532896, ...}) = 0
25 mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7d88000
26 mmap2(NULL, 24576, PROT_READ, MAP_PRIVATE, 3, 0xda5) = 0xb7d82000
27 mmap2(NULL, 184320, PROT_READ, MAP_PRIVATE, 3, 0xdad) = 0xb7d55000
28 mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x22a5) = 0xb7d54000
29 close(3) = 0
30 getcwd("/home/heitor", 4096) = 13
31 fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
32 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7d53000
33 write(1, "/home/heitor\n", 13/home/heitor ) = 13
34 exit_group(0) = ?
As linhas do resultado acima que merecem comentários são as seguintes:
- linha 1: A chamada de sistema execve() executa o comando pwd, sem nenhum argumento.
- linha 9: O processo do pwd usa o open() para abrir a biblioteca compartilhada glibc (/lib/tls/libc.so.6) no modo somente para leitura (O_RDONLY). O resultado do open() (o valor 3) é o número do descritor associado a esse arquivo.
- linha 10: A chamada de sistema read() lê os primeiros 512 bytes da biblioteca compartilhada aberta anteriormente com open(), usando como primeiro argumento o número do descritor 3.
- linha 30: É o ponto principal do programa, pois obtém através da chamada de sistema getcwd() o diretório atual.
- linha 33: Enfim, o programa executa o write() para mostrar na tela o diretório "/home/heitor", retornado pelo getcwd().
No próximo exemplo, o strace é usado para conseguir informações sobre a seguinte situação problemática: Um programa que usa um banco de dados MySQL para realizar a autenticação, apresenta-se lento durante determinados momentos de sua execução, apesar do servidor MySQL estar funcionando corretamente.
Executando o strace, consegue-se do programa os dados abaixo:
...(cortado)...
1 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.200.66")},28) = 0
2 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
3 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
4 poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
5 sendto(3, "\22\367\1\0\0\1\0\0\0\0\0\0\5mysql\5ha-mc\3org\0\0\1\0\1", 33, MSG_NOSIGNAL, NULL, 0) = 33
6 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
7 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
8 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.200.99")}, 28) = 0
9 fcntl(4, F_GETFL) = 0x2 (flags O_RDWR)
10 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
11 poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
12 sendto(4, "\22\367\1\0\0\1\0\0\0\0\0\0\5mysql\5ha-mc\3org\0\0\1\0\1", 33, MSG_NOSIGNAL, NULL, 0) = 33
13 poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
14 ioctl(4, FIONREAD, [117]) = 0
15 recvfrom(4, "\22\367\205\200\0\1\0\1\0\2\0\2\5mysql\5ha-mc\3org\0\0\1\0\1\300\f\0\ 1\0\1\0\0\16\20\0\4\275\25t3\300\22\0\2\0\1\0 \0\16\20\0\6\3ns2\300\22\300\22\0\2\0\1\0\0\16\20 \0\6\3ns1\300\22\300O\0\1\0\1\0\0\16\20 \0\4\275\25t\24\300=\0\1\0\1\0\0\16\20\0\4\275\25t\25",1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("189.21.116.20")}, [16]) = 117
...
16 connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("189.21.116.51")}, 16) = 0
17 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
18 rt_sigaction(SIGINT, {0x55555555e150, [INT], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
19 rt_sigaction(SIGQUIT, {0x55555555e120, [QUIT], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
20 rt_sigaction(SIGPIPE, {0x55555555e180, [PIPE], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
21 rt_sigaction(SIGWINCH, {0x55555555e100, [WINCH], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0},{SIG_DFL}, 8) = 0
22 rt_sigaction(SIGTSTP, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
23 rt_sigaction(SIGTSTP, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, 8) = 0
24 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
25 ioctl(0, FIONBIO, [1]) = 0
26 ioctl(1, FIONBIO, [1]) = 0
27 ioctl(3, FIONBIO, [1]) = 0
28 setsockopt(3, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0
29 select(4, [0 3], [], [3], {0, 0}) = 1 (in [3], left {0, 0})
30 recvfrom(3, "8\0\0\0\n5.0.27-log\0\374\321\347\0FN6bil`{\0,\242\10\2\0\0\0\0\0\0 \0\0\0\0\0\0\0\0j%q1
1 connect(3, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.200.66")},28) = 0
2 fcntl(3, F_GETFL) = 0x2 (flags O_RDWR)
3 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
4 poll([{fd=3, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
5 sendto(3, "\22\367\1\0\0\1\0\0\0\0\0\0\5mysql\5ha-mc\3org\0\0\1\0\1", 33, MSG_NOSIGNAL, NULL, 0) = 33
6 poll([{fd=3, events=POLLIN}], 1, 5000) = 0
7 socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
8 connect(4, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("200.200.200.99")}, 28) = 0
9 fcntl(4, F_GETFL) = 0x2 (flags O_RDWR)
10 fcntl(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0
11 poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
12 sendto(4, "\22\367\1\0\0\1\0\0\0\0\0\0\5mysql\5ha-mc\3org\0\0\1\0\1", 33, MSG_NOSIGNAL, NULL, 0) = 33
13 poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
14 ioctl(4, FIONREAD, [117]) = 0
15 recvfrom(4, "\22\367\205\200\0\1\0\1\0\2\0\2\5mysql\5ha-mc\3org\0\0\1\0\1\300\f\0\ 1\0\1\0\0\16\20\0\4\275\25t3\300\22\0\2\0\1\0 \0\16\20\0\6\3ns2\300\22\300\22\0\2\0\1\0\0\16\20 \0\6\3ns1\300\22\300O\0\1\0\1\0\0\16\20 \0\4\275\25t\24\300=\0\1\0\1\0\0\16\20\0\4\275\25t\25",1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("189.21.116.20")}, [16]) = 117
...
16 connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("189.21.116.51")}, 16) = 0
17 rt_sigprocmask(SIG_BLOCK, NULL, [], 8) = 0
18 rt_sigaction(SIGINT, {0x55555555e150, [INT], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
19 rt_sigaction(SIGQUIT, {0x55555555e120, [QUIT], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
20 rt_sigaction(SIGPIPE, {0x55555555e180, [PIPE], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
21 rt_sigaction(SIGWINCH, {0x55555555e100, [WINCH], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0},{SIG_DFL}, 8) = 0
22 rt_sigaction(SIGTSTP, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {SIG_DFL}, 8) = 0
23 rt_sigaction(SIGTSTP, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, {0x55555555e0c0, [TSTP], SA_RESTORER|SA_RESTART, 0x2aaaab1560b0}, 8) = 0
24 ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
25 ioctl(0, FIONBIO, [1]) = 0
26 ioctl(1, FIONBIO, [1]) = 0
27 ioctl(3, FIONBIO, [1]) = 0
28 setsockopt(3, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0
29 select(4, [0 3], [], [3], {0, 0}) = 1 (in [3], left {0, 0})
30 recvfrom(3, "8\0\0\0\n5.0.27-log\0\374\321\347\0FN6bil`{\0,\242\10\2\0\0\0\0\0\0 \0\0\0\0\0\0\0\0j%q1
...(cortado)...
Exclusivamente nesse caso, é perceptível durante o rastreamento que o programa em questão fica lento exatamente na linha 6. Portanto, será analisado o trecho próximo a essa linha:
- linha 1: O processo usa a chamada de sistema connect() para realizar a conexão com o IP 200.200.200.66, na porta 53 (DNS).
- linha 5: É enviado o hostname "mysql.ha-mc.org" para a conexão criada anteriormente. Logo se concluí que essa conexão faz referência a uma consulta de DNS.
- linha 6: O processo trava na chamada de sistema pool(). Neste momento ele aguarda a resposta do servidor DNS.
- linha 8: Após não receber nenhuma resposta do primeiro servidor, ele tenta nova conexão na porta 53, desta vez no IP: 200.200.200.99
- linha 12: A mesma consulta DNS é enviada para a nova conexão.
- linha 15: O servidor DNS 200.200.200.99 responde a requisição e passa o endereço IP 189.21.116.51, referente ao host "mysql.ha-mc.org".
- linha 16: Finalmente, o processo estabelece uma conexão ao IP 189.21.116.51 na porta do MySQL (3306).
De maneira simples, e principalmente rápida, foi possível detectar que o servidor DNS primário utilizado pelo programa não está respondendo, atrasando as conexões ao servidor MySQL. Sendo assim, troca-se esse servidor DNS e o problema é resolvido.
Considerações finais
Apesar da simplicidade dos exemplos citados, fica evidente que o strace é uma ferramenta poderosa para um administrador de sistemas conseguir informações sobre um problema que, a princípio, parece obscuro. Os desenvolvedores também podem exergar alguma utilidade no strace para fazer a depuração de seus programas sem a necessidade de recompilá-lo.
E recentemente o conceito de rastreamento ganhou importância, o que levou alguns sistemas operacionais a providenciarem ferramentas mais completas. Depois da apresentação do excelente Dtrace por parte do Solaris, o FreeBSD se esforça muito para portá-lo em seu sistema, enquanto o Linux promete maravilhas com a idéia do LTTng.
Referências
Ravi (05-05-2006). strace - A very powerful trobleshooting tool for all Linux users. All about Linux. Acessado em 18-01-2008.
Zimmerly, Willian B (11-05-2006). Fun with strace and GDB Debugger. IBM DeveloperWorks. Acessado em 19-01-08
Comentários
Você é o Heitor da
Você é o Heitor da CentralServer ?
Bom, sendo ou não, parabéns pelo ótimo artigo.
Abraço !
Ótimo
Isso ainda vai me ajudar em alguma coisa, é certo.
Hey!
Muito bom o artigo.
Por acaso você se formou no Mackenzie?
Abraço!
Re: Hey!
Olá Estevão,
Eu não me formei no Mackenzie, certamente você confundiu :)
Abraço,
Heitor Augusto Murari Cardozo
=)
Valeu, muito obrigado ;)