Capítulo 33 Rastreio de processo do usuário

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.

Sub-rotinas copyin() e copyinstr()

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.

Evitando erros

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                        

Eliminando a interferência de dtrace(1M)

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.

Provedor syscall

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.

Ação ustack()

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.

Matriz uregs[]

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.

Em plataformas AMD64, a matriz uregs possui o mesmo conteúdo que em plataformas x86, além dos elementos adicionais listados na tabela seguinte:

Os alias listados na tabela seguinte podem ser usados em todas as plataformas:

Provedor pid

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.

Rastreio de limite de função do usuário

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.

Exemplo 33–1 userfunc.d: rastrear retorno e entrada de função do usuário

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

Rastreando instruções arbitrárias

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.

Exemplo 33–2 errorpath.d: rastrear o caminho de erro da chamada da função do usuário

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