O DTrace é uma ferramenta poderosa para entender o comportamento dos processos do usuário. O DTrace pode ser valiosíssimo durante a depuração, analisando os problemas de desempenho, ou simplesmente entendendo o comportamento de um aplicativo complexo. Este capítulo focaliza os recursos do DTrace relevantes para o rastreio da atividade do processo do usuário e fornece exemplos para o uso deles.
A interação do DTrace com os processos é um pouco diferente da maioria dos depuradores tradicionais ou das ferramentas de observação. Muitas dessas ferramentas parecer ser executadas no escopo do processo, permitindo que os usuários cancelem diretamente a referência aos ponteiros para variáveis de programa. Em vez de serem executados em um processo ou em parte dele, os testes do DTrace são executados no kernel do Solaris. Para acessar os dados do processo, um teste precisa usar as sub-rotinas copyin() ou copyinstr() para copiar dados do processo do usuário para o espaço de endereço do kernel.
Por exemplo, considere a seguinte chamada do sistema write(2):
ssize_t write(int fd, const void *buf, size_t nbytes);
O programa em D seguinte ilustra uma tentativa incorreta de imprimir o conteúdo de uma seqüência passada para a chamada do sistema write(2):
syscall::write:entry { printf("%s", stringof(arg1)); /* incorrect use of arg1 */ }
Se você tentar executar este script, o DTrace produzirá mensagens de erro semelhantes ao exemplo seguinte:
dtrace: error on enabled probe ID 1 (ID 37: syscall::write:entry): \ invalid address (0x10038a000) in action #1 |
A variável arg1, que contém o valor do parâmetro buf, é um endereço que se refere à memória no processo que está executando a chamada do sistema. Para ler a seqüência nesse endereço, use a sub-rotina copyinstr() e registre seu resultado com a ação printf() :
syscall::write:entry { printf("%s", copyinstr(arg1)); /* correct use of arg1 */
A saída deste script mostra todas as seqüências que estão sendo passadas para a chamada do sistema write(2). Entretanto, ocasionalmente, você talvez veja uma saída irregular semelhante ao exemplo seguinte:
0 37 write:entry mada��� |
A sub-rotina copyinstr() age como um argumento de entrada que é o endereço do usuário de uma seqüência ASCII terminada com nulo. Entretanto, os buffers passados para a chamada do sistema write(2) podem se referir a dados binários em vez de seqüências ASCII. Para imprimir somente a quantidade da seqüência que o chamador pretende, use a sub-rotina copyin(), que usa um tamanho como seu segundo argumento:
syscall::write:entry { printf("%s", stringof(copyin(arg1, arg2))); }
Observe que o operador stringof é necessário para que o DTrace converta corretamente os dados do usuário recuperados, usando copyin (), em uma seqüência. O uso de stringof não é necessário quando se usa copyinstr() porque esta função sempre retorna o tipo string.
As sub-rotinas copyin() e copyinstr() não podem ler a partir de endereços do usuário que ainda não foram tocados, sendo assim, mesmo um endereço válido pode causar um erro, se a página que contém esse endereço ainda não tiver tido uma falha ao ser acessada. Considere o seguinte exemplo:
# dtrace -n syscall::open:entry'{ trace(copyinstr(arg0)); }' dtrace: description 'syscall::open:entry' matched 1 probe CPU ID FUNCTION:NAME dtrace: error on enabled probe ID 2 (ID 50: syscall::open:entry): invalid address (0x9af1b) in action #1 at DIF offset 52 |
Na saída do exemplo acima, o aplicativo estava funcionando corretamente, e o endereço em arg0 era válido, mas ele se referia a uma página que ainda não tinha sido acessada pelo processo correspondente. Para resolver este problema, aguarde que o kernel ou o aplicativo use os dados antes de rastreá-lo. Por exemplo, você pode esperar até que a chamada retorne para aplicar copyinstr(), como mostrado no exemplo seguinte:
# dtrace -n syscall::open:entry'{ self->file = arg0; }' \ -n syscall::open:return'{ trace(copyinstr(self->file)); self->file = 0; }' dtrace: description 'syscall::open:entry' matched 1 probe CPU ID FUNCTION:NAME 2 51 open:return /dev/null |
Se rastrear cada chamada para a chamada do sistema write(2) , você provocará uma saída em cascada. Cada chamada para write() faz o comando dtrace(1M) chamar write(), já que ela exibe a saída, e assim por diante. Este loop de comentários é um bom exemplo de como o comando dtrace pode interferir nos dados desejados. Você pode usar um predicado simples para evitar que esses dados indesejados sejam rastreados:
syscall::write:entry /pid != $pid/ { printf("%s", stringof(copyin(arg1, arg2))); }
A variável de macro $pid se expande para o identificador do processo que ativou os testes. A variável pid contém o identificador do processo cujo segmento estava sendo executado na CPU onde o teste foi acionado. Portanto, o predicado /pid != $pid/ garante que o script não rastreie quaisquer eventos relacionados à execução deste próprio script.
O provedor syscall permite que você rastreie cada entrada e retorno da chamada do sistema. As chamadas do sistema podem ser um bom começo para entender o comportamento do processo, especialmente se o processo estiver gastando uma grande quantidade de tempo sendo executado ou bloqueado no kernel. Você pode usar o comando prstat(1M) para ver onde os processos estão gastando tempo:
$ prstat -m -p 31337 PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/NLWP 13499 user1 53 44 0.0 0.0 0.0 0.0 2.5 0.0 4K 24 9K 0 mystery/6 |
Este exemplo mostra que o processo está consumindo uma grande quantidade de tempo do sistema. Uma possível explicação para este comportamento é que o processo está executando um grande número de chamadas do sistema. Você pode usar um simples programa em D especificado na linha de comando para ver quais chamadas do sistema estão acontecendo com mais freqüência:
# dtrace -n syscall:::entry'/pid == 31337/{ @syscalls[probefunc] = count(); }' dtrace: description 'syscall:::entry' matched 215 probes ^C open 1 lwp_park 2 times 4 fcntl 5 close 6 sigaction 6 read 10 ioctl 14 sigprocmask 106 write 1092 |
Este relatório mostra quais chamadas do sistema estão sendo chamadas com mais freqüência, neste caso, a chamada do sistema write(2). Você pode usar o provedor syscall para examinar mais detalhadamente a origem das chamadas do sistema write():
# dtrace -n syscall::write:entry'/pid == 31337/{ @writes[arg2] = quantize(arg2); }' dtrace: description 'syscall::write:entry' matched 1 probe ^C value ------------- Distribution ------------- count 0 | 0 1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1037 2 |@ 3 4 | 0 8 | 0 16 | 0 32 |@ 3 64 | 0 128 | 0 256 | 0 512 | 0 1024 |@ 5 2048 | 0 |
A saída mostra que o processo está executando muitas chamadas do sistema write () com uma quantidade relativamente pequena de dados. Esta taxa poderia ser a origem do problema de desempenho deste processo específico. Este exemplo ilustra uma metodologia geral para investigar o comportamento da chamada do sistema.
Rastrear uma pilha do segmento do processo na hora em que um teste específico é ativado é freqüentemente útil para examinar um problema em maiores detalhes. A ação ustack() rastreia a pilha do segmento do usuário. Se, por exemplo, um processo que abre muitos arquivos falhar ocasionalmente na chamada do sistema open(2), use a ação ustack() para descobrir o caminho do código que executa a função open() falha:
syscall::open:entry /pid == $1/ { self->path = copyinstr(arg0); } syscall::open:return /self->path != NULL && arg1 == -1/ { printf("open for '%s' failed", self->path); ustack(); }
Este script também ilustra o uso da variável de macro $1 que usa o valor do primeiro operando especificado na linha de comando do dtrace(1M):
# dtrace -s ./badopen.d 31337 dtrace: script './badopen.d' matched 2 probes CPU ID FUNCTION:NAME 0 40 open:return open for '/usr/lib/foo' failed libc.so.1`__open+0x4 libc.so.1`open+0x6c 420b0 tcsh`dosource+0xe0 tcsh`execute+0x978 tcsh`execute+0xba0 tcsh`process+0x50c tcsh`main+0x1d54 tcsh`_start+0xdc |
A ação ustack() registra os valores do contador do programa ( PC) da pilha e o dtrace(1M) resolve esses valores de PC para nomes de símbolo, procurando nas tabelas de símbolos do processo. Se o dtrace não puder resolver o valor de PC para um símbolo, ele imprimirá o valor como um inteiro hexadecimal.
Se um processo sair ou for interrompido antes de os dados de ustack() serem formatados para saída, o dtrace talvez não consiga converter os valores de PC no rastreamento da pilha para nomes de símbolo, e será forçado a exibi-los como inteiros hexadecimais. Para resolver esta limitação, especifique um processo de interesse com a opção -c ou -p para dtrace. Consulte o Capítulo 14Utilitário dtrace(1M) para obter detalhes sobre estas e outras opções. Se o ID do processo ou o comando não for conhecido com antecedência, o exemplo seguinte de programa em D poderá ser usado para resolver a limitação:
/* * This example uses the open(2) system call probe, but this technique * is applicable to any script using the ustack() action where the stack * being traced is in a process that may exit soon. */ syscall::open:entry { ustack(); stop_pids[pid] = 1; } syscall::rexit:entry /stop_pids[pid] != 0/ { printf("stopping pid %d", pid); stop(); stop_pids[pid] = 0; }
O script acima irá parar um processo antes que ele saia, se a ação ustack() tiver sido aplicada a um segmento nesse processo. Esta técnica garante que o comando dtrace será capaz de resolver os valores de PC para nomes simbólicos. Observe que o valor de stop_pids[pid] é definido como 0 depois que ele tiver sido usado para limpar a variável dinâmica. Lembre-se de definir os processos interrompidos que estão sendo executados novamente usando o comando prun(1) ou o seu sistema acumulará muitos processos interrompidos.
A matriz uregs[] permite que você acesse registros individuais do usuário. As tabelas seguintes listam índices para a matriz uregs[] correspondente a cada arquitetura suportada do sistema Solaris.
Tabela 33–1 Constantes uregs[] SPARC
Constante |
Registro |
---|---|
0..R_G..R_G7 |
%g0....%g7 - registros globais |
0..R_O..R_O7 |
%o0....%o7 - registros externos |
0..R_L..R_L7 |
%l0....%l7 - registros locais |
0..R_I..R_I7 |
%i0....%i7 - registros internos |
R_CCR |
%ccr - registro de código de condição |
R_PC |
%pc - contador de programa |
R_NPC |
%npc - próximo contador de programa |
R_Y |
%y - registro de multiplicação/divisão |
R_ASI |
%asi - registro do identificador de espaço de endereço |
R_FPRS |
%fprs - data dos registros de ponto flutuante |
Tabela 33–2 Constantes uregs[] x86
Constante |
Registro |
---|---|
R_CS |
%cs |
R_GS |
%gs |
R_ES |
%es |
R_DS |
%ds |
R_EDI |
%edi |
R_ESI |
%esi |
R_EBP |
%ebp |
R_EAX |
%eax |
R_ESP |
%esp |
R_EAX |
%eax |
R_EBX |
%ebx |
R_ECX |
%ecx |
R_EDX |
%edx |
R_TRAPNO |
%trapno |
R_ERR |
%err |
R_EIP |
%eip |
R_CS |
%cs |
R_ERR |
%err |
R_EFL |
%efl |
R_UESP |
%uesp |
R_SS |
%ss |
Em plataformas AMD64, a matriz uregs possui o mesmo conteúdo que em plataformas x86, além dos elementos adicionais listados na tabela seguinte:
Tabela 33–3 Constantes uregs[] amd64
Constante |
Registro |
---|---|
R_RSP |
%rsp |
R_RFL |
%rfl |
R_RIP |
%rip |
R_RAX |
%rax |
R_RCX |
%rcx |
R_RDX |
%rdx |
R_RBX |
%rbx |
R_RBP |
%rbp |
R_RSI |
%rsi |
R_RDI |
%rdi |
R_R8 |
%r8 |
R_R9 |
%r9 |
R_R10 |
%r10 |
R_R11 |
%r11 |
R_R12 |
%r12 |
R_R13 |
%r13 |
R_R14 |
%r14 |
R_R15 |
%r15 |
Os alias listados na tabela seguinte podem ser usados em todas as plataformas:
Tabela 33–4 Constantes uregs[] comuns
Constante |
Registro |
---|---|
R_PC |
registro do contador de programa |
R_SP |
registro do ponteiro de pilha |
R_R0 |
primeiro código de retorno |
R_R1 |
segundo código de retorno |
O provedor pid permite que você rastreie qualquer instrução em um processo. Ao contrário da maioria dos outros provedores, os testes pid são criados por demanda com base nas descrições de teste encontradas em seus programas em D. Como resultado, nenhum teste pid estará listado na saída do dtrace -l até que você os tenha ativado.
O modo mais simples de operação do provedor pid é como um espaço do usuário análogo ao provedor fbt. O programa de exemplo seguinte rastreia todas as entradas e os retornos da função feitos a partir de uma única função. A variável de macro $1 (o primeiro operando na linha de comando) é o ID do processo a ser rastreado. A variável de macro $2 (o segundo operando na linha de comando) é o nome da função a partir da qual serão rastreadas todas as chamadas de função.
pid$1::$2:entry { self->trace = 1; } pid$1::$2:return /self->trace/ { self->trace = 0; } pid$1:::entry, pid$1:::return /self->trace/ { }
Digite o script de exemplo acima e salve-o em um arquivo chamado userfunc.d e, em seguida, execute o comando chmod para torná-lo executável. Este script produz uma saída semelhante ao exemplo seguinte:
# ./userfunc.d 15032 execute dtrace: script './userfunc.d' matched 11594 probes 0 -> execute 0 -> execute 0 -> Dfix 0 <- Dfix 0 -> s_strsave 0 -> malloc 0 <- malloc 0 <- s_strsave 0 -> set 0 -> malloc 0 <- malloc 0 <- set 0 -> set1 0 -> tglob 0 <- tglob 0 <- set1 0 -> setq 0 -> s_strcmp 0 <- s_strcmp ... |
O provedor pid só pode ser usado em processos que já estão sendo executados. Você pode usar a variável de macro $target (consulte o Capítulo 15Script) e as opções -c and -p do dtrace para criar e usar processos de interesse e instrumentá-los usando o DTrace. Por exemplo, o script de D seguinte pode ser usado para determinar a distribuição de chamadas de função feitas para libc por um processo de assunto específico:
pid$target:libc.so::entry { @[probefunc] = count(); }
Para determinar a distribuição de tais chamadas feitas pelo comando date(1), salve o script em um arquivo chamado libc.d e execute o comando seguinte:
# dtrace -s libc.d -c date dtrace: script 'libc.d' matched 2476 probes Fri Jul 30 14:08:54 PDT 2004 dtrace: pid 109196 has exited pthread_rwlock_unlock 1 _fflush_u 1 rwlock_lock 1 rw_write_held 1 strftime 1 _close 1 _read 1 __open 1 _open 1 strstr 1 load_zoneinfo 1 ... _ti_bind_guard 47 _ti_bind_clear 94 |
Você pode usar o provedor pid para rastrear qualquer instrução em qualquer função do usuário. Por demanda, o provedor pid criará um teste para cada instrução em uma função. O nome de cada teste é o deslocamento de sua instrução correspondente na função expressa como um inteiro hexadecimal. Por exemplo, para ativar um teste associado à instrução no deslocamento 0x1c na função foo do módulo bar.so no processo com PID 123, use o seguinte comando:
# dtrace -n pid123:bar.so:foo:1c |
Para ativar todos os testes na função foo, incluindo o teste de cada instrução, use o comando:
# dtrace -n pid123:bar.so:foo: |
Esse comando demonstra uma técnica extremamente poderosa para depurar e analisar os aplicativos do usuário. Erros infreqüentes podem ser difíceis de depurar por serem difíceis de reproduzir. Freqüentemente, você pode identificar um problema após a ocorrência de uma falha muito tardiamente para reconstruir o caminho do código. O exemplo seguinte demonstra como combinar o provedor pid com rastreio especulativo (consulte o Capítulo 13Rastreio especulativo) para resolver este problema rastreando cada instrução em uma função.
pid$1::$2:entry { self->spec = speculation(); speculate(self->spec); printf("%x %x %x %x %x", arg0, arg1, arg2, arg3, arg4); } pid$1::$2: /self->spec/ { speculate(self->spec); } pid$1::$2:return /self->spec && arg1 == 0/ { discard(self->spec); self->spec = 0; } pid$1::$2:return /self->spec && arg1 != 0/ { commit(self->spec); self->spec = 0; }
Executar errorpath.d resulta em uma saída semelhante ao exemplo seguinte:
# ./errorpath.d 100461 _chdir dtrace: script './errorpath.d' matched 19 probes CPU ID FUNCTION:NAME 0 25253 _chdir:entry 81e08 6d140 ffbfcb20 656c73 0 0 25253 _chdir:entry 0 25269 _chdir:0 0 25270 _chdir:4 0 25271 _chdir:8 0 25272 _chdir:c 0 25273 _chdir:10 0 25274 _chdir:14 0 25275 _chdir:18 0 25276 _chdir:1c 0 25277 _chdir:20 0 25278 _chdir:24 0 25279 _chdir:28 0 25280 _chdir:2c 0 25268 _chdir:return |