Blog do Luti: março 2014

segunda-feira, 31 de março de 2014

DB2 trap problem determination

Durante minha vida profissional pude observar muitas análises ruins quando se está tentando determinar a causa raiz de um problema. O x da questão usualmente não é a qualidade técnica do profissional, mas sim a metodologia adotada detalhar a situação para se criar uma linha de eventos válida, somada a uma frequentemente falta de paciência em varrer os logs e analisar com calma as evidências.

Pensando nisso eu escrevi um pequeno passo a passo para uma identificação de causa raia que fiz em uma instância do DB2 que uso para meus testes, onde sem querer esbarrei em um bug do DB2. Espero que sirva como um bom exemplo de análise, independente do produto que você trabalha.

Cenário: em meu ambiente de laboratório eu notei que uma instância do DB2 recorrentemente parava de funcionar na madrugada, sendo necessário um db2start para coloca-la operacional.

Como fiz a análise...

1. Partindo de um momento perto do horário em que o serviço foi interrompido analisa-se o diaglog, onde encontro uma entrada muito importante:

2014-03-26-00.43.45.477605-180 I38149015A601 LEVEL: Error

PID : 9475 TID : 4383345469712 PROC : db2sysc 0

INSTANCE: db2inst1 NODE : 000 DB : HCOREDB

APPHDL : 0-10765 APPID: *LOCAL.db2inst1.140326052243

AUTHID : DB2INST1 HOSTNAME: db2luti

EDUID : 5674 EDUNAME: db2agent (HCOREDB) 0

FUNCTION: DB2 UDB, base sys utilities, sqleagnt_sigsegvh, probe:1

MESSAGE : Error in agent servicing application with coor_node:

DATA #1 : Hexdump, 2 bytes

0x000003FC9380996C : 0000

2. Em seguida começamos a ver diversas entradas no diretório do FODC (First Ocurrence Data Capture). Analisando o diretório FODC temos N diretórios com o timestamp do trap, o de nosso interesse é FODC_Trap_2014-03-26-00.43.45.300571_0000.

3. Neste diretório temos diversos artefatos que foram gerados, mas para essa análise o que nos interessa é o arquivo com trap, que é um snapshot do estado do DB2 quando o stack dump foi capturado (*.trap.txt).

a. Neste caso foi gerado o 9475.5674.000.trap.txt;

b. Notem o PID e EDUID destacados no diaglog, o nome do arquivo do trap é iniciado pelo process ID do db2sysc no Linux e o EDU ID do agente;

4. O arquivo do trap tem diversas informações, entre elas a stack que fica um pouco chata de ler por conta dos nomes gerados pelo compilador. Então para analisar o arquivo e limpar o nome dos métodos, peçam ajuda ao c++filt:

cat 9475.5674.000.trap.txt | c++filt | less

a. Signal #11 Indica um erro inesperado (9 é o SIGKILL, 2 é o SIGINT, etc..;)

Signal #11 (SIGSEGV): si_addr is 0x000003FC2640A000, si_code is 0x00000002 (SEGV_ACCERR:Invalid permissions for mapped object.)

b. A entrada <POFDisassembly> (POF = Point Of Failure) é o método que estava sendo executado quando o problema aconteceu.

sqldHashZValue32(int, sqlz_value**, sqld_sortkey**) + 0x0116 (/home/db2inst1/sqllib/lib64/libdb2e.so.1)

c. Isso já dá um ótimo filtro de pesquisa no Google ou Bing, tentem: db2 10.1 “sqldHashZValue32”

i. De cara a primeira saída é interessante: http://www-01.ibm.com/support/docview.wss?uid=swg1IC92798 (IC92798: RUNNING MULTIPLE CONCURRENT SAMPLED DETAILED INDEX RUNSTATS MIGHT CAUSE A SERVER ABEND OR INACCURATE INDEX STATISTICS)

d. Na APAR temos o detalhamento do problema e stack trace de interesse:

sqloEDUCodeTrapHandler

sqldHashZValue32

sqlis_touch_page

sqliProcessColStats

sqlischs

sqlistat

sqldIndexStats

sqlrLocalRunstats

e. Para garantir que se trata do mesmo problema, vamos comparar a stack no arquivo de trap:

0x000003FFFAAC4888 sqloEDUCodeTrapHandler + 0x0250 (/home/db2inst1/sqllib/lib64/libdb2e.so.1)

0x000003FC93809DF0 address: 0x3fc93809df0

0x000003FFF8BB97D6 sqldHashZValue32(int, sqlz_value**, sqld_sortkey**) + 0x0116