Trace no Informix

Trace no Informix

  novembro 19, 2013    Claudemar Martins de Sá

---

Conheço 3 maneiras de tirar um trace no Informix;

Primeiro Trace (onmode -I)

O usuário rodou uma consulta e esta recebendo o erro (1204 - data invalida) - Verificando o Processo

Sess       SQL            Current            Iso Lock       SQL  ISAM F.E.
Id         Stmt type      Database           Lvl Mode       ERR  ERR  Vers  Explain    
346985     SELECT         ods_fazenda        NL  Not Wait   -1204 0    9.24  Off        

Current SQL statement :
  select dba.vpnd_todas_as_pendencias.ie,    
    dba.vpnd_todas_as_pendencias.cnpj_cpf_pendencia,    
    dba.vpnd_todas_as_pendencias.ano_doc, dba.vpnd_todas_as_pendencias.dtvenc
       from dba.vpnd_todas_as_pendencias

Ativando o trace, procure o processo do usuário que esta recebendo o erro 1204

[s106:informix]$/export/home/informix> onmode -I 1204

Falei para o usuário rodar de novo a sua query

SQL:   New  Run  Modify  Use-editor  Output  Choose  Save  Info  Drop  Exit
Run the current SQL statements.

------------ ods_fazenda@sefaz_sig ------------- Press CTRL-W for Help --------

  select dba.vpnd_todas_as_pendencias.ie,    
    dba.vpnd_todas_as_pendencias.cnpj_cpf_pendencia,    
    dba.vpnd_todas_as_pendencias.ano_doc, dba.vpnd_todas_as_pendencias.dtvenc
       from dba.vpnd_todas_as_pendencias

Vai gerar um AF sobre este erro - o sistema vai ficar lento, normal - Olhando o log deve ter aparecido este AF

11/09/12 07:48:41  Verbose error trapping set, errno = 1204, session_id = -1
11/09/12 08:48:46  Assert Failed: found errno 1204 in session 346985
11/09/12 08:48:46  IBM Informix Dynamic Server Version 11.70.FC2
11/09/12 08:48:46   Who: Session(346985, dba@s106.ms, 16069, 0x15840e288)
                Thread(1260995873, sqlexec, 1583d5898, 4)
                File: rsdebug.c Line: 3615
11/09/12 08:48:46   Action: Use onmode -I to stop verbose error trapping.
11/09/12 08:48:46  stack trace for pid 20006 written to /opt/informix/tmp/af.4909ed9d
11/09/12 08:48:46   See Also: /opt/informix/tmp/af.4909ed9d
11/09/12 07:49:07  Verbose error trapping stopped.
11/09/12 08:50:09  found errno 1204 in session 346985

No arquivo de AF gerado vamos entrar nele e ver os valores que a usuário esta enviando

vi /opt/informix/tmp/af.4909ed9d

O ano esta errado (2000-01-01) tem que ficar (01-01-2000)

---- corte ----
    ,x0.ali_serie_docto ,'' ,'' ,'' ,'2000-01-01' ::date ,0 ,0 ,'' ,0 ,0 ,''
    ,'' ,0 ,'' ,'2000-01-01' ::date ,0 ,0 ,0 ,'2000-01-01' ::date ,'' from
    (("dba".pnd_mvto_alim x0 join "dba".vpnd_movimento_mais_recente x1 on
    (((x1.pnd_ano = x0.pnd_ano ) AND (x1.pnd_sequencial = x0.pnd_sequencial )
    ) AND (x1.pnm_sequencial = x0.pnm_sequencial ) ) )join "dba".pnd_tipo x2
    on (x1.pnt_codigo = x2.pnt_codigo ) ) union select x4.con_insc_est
    ,x4.pnm_cnpj_cpf ,x4.pnt_codigo ,x5.pnt_descricao ,x3.cda_num_docto
    ::varchar(10) ,'' ,x3.cda_ano_docto ,'' ,'' ,'2000-01-01' ::date ,0 ,0 ,''
    ,0 ,0 ,'' ,'' ,0 ,'' ,'2000-01-01' ::date ,0 ,0 ,0 ,'2000-01-01' ::date
---- corte ----

Desabilitando o Trace

[s106:informix]$/export/home/informix> onmode -I

Segundo Trace (onmode -Y)

Este trace consigo ver o plano de consulta do otimizador (SET EXPLAIN) do processo do usuário que esta acessando um banco do Informix, com este trace dá checar a estimativa custo relativo da consulta que o usuário esta rodando online. Eu sempre usei este comando quando o usuário reclama de lentidão de uma consulta no Informix.

Vou habilitar o comande trace no usuário csa, primeiro vejo o número do processo que ele esta rodando no Informix;

[s343:informix]$/export/home/informix> onstat -g ses | grep csa
5575     csa      1        1955     s343.ms  1        159744     154456     off

O onmode -Y tem essas opções

onmode -Y < session_id > < 0|1|2 >

0 - Desliga trace
1 - Liga trace com estatisticas
2 - Liga trace sem estatísticas

Para habilitar um trace do usuário csa processo 5575 com coleta das estatisticas (1)

[s343:informix]$/export/home/informix> onmode -Y 5575 1

Depois que o usuário rodar uma consulta depois de habilitado o trace vai gerar um arquivo SET EXPLAIN mostrando o custo dessa consulta - repare na ultima linha;

[s343:informix]$/export/home/informix> onstat -m

IBM Informix Dynamic Server Version 11.70.FC2 -- On-Line -- Up 2 days 22:50:23 -- 876324 Kbytes

Message Log File: /export/home/informix/online.log
operation may take several minutes.
11/22/13 02:00:02  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 03:00:01  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 04:00:01  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 05:00:01  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 06:00:02  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 07:00:02  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 08:00:01  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 09:00:02  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 10:00:02  Attempting to free unused operating system segments.  This
operation may take several minutes.
11/22/13 10:21:56  Explain file for session 5575 : /home/csa/sqexplain.out.5575

Checando o log para ver o que foi colegado

[s343:informix]$/export/home/informix> cat /home/csa/sqexplain.out.5575

Nos mostra as estimativas - esta consulta mesmo usando uma pesquisa sequencial scan foi bem rápida

[s343:informix]$/export/home/informix> cat /home/csa/sqexplain.out.5575

QUERY: (OPTIMIZATION TIMESTAMP: 11-22-2013 10:21:57)
------
select * from aidf


Estimated Cost: 103
Estimated # of Rows Returned: 3000

  1) dba.aidf: SEQUENTIAL SCAN


Query statistics:
-----------------

  Table map :
  ----------------------------
  Internal name     Table name
  ----------------------------
  t1                aidf

  type     table  rows_prod  est_rows  rows_scan  time       est_cost
  -------------------------------------------------------------------
  scan     t1     136        3000      150        00:00.00   103     

Desabilitando o trace;

[s343:informix]$/export/home/informix> onmode -Y 5575 0

Terceiro Trace (strace)

Este trace foi bem interessante, todas as vezes que rodava o comando de backup (onbar -b -l) ocorria um erro rodando este trace descobri o que estava causando isso.

 strace onbar -b -l

Resultado do erro

---- corte ----
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGINT, {0x436c60, [], SA_RESTORER, 0x392ca302d0}, {0x446870, [], SA_RESTORER, 0x392ca302d0}, 8) = 0
wait4(-1, write error code 32
pigz abort: write error on 
write error code 32
pigz abort: write error on 
[{WIFEXITED(s) && WEXITSTATUS(s) == 255}], 0, NULL) = 9354
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
wait4(-1, 0x7fffe8f79d04, WNOHANG, NULL) = -1 ECHILD (No child processes)
rt_sigreturn(0xffffffffffffffff)        = 0
rt_sigaction(SIGINT, {0x446870, [], SA_RESTORER, 0x392ca302d0}, {0x436c60, [], SA_RESTORER, 0x392ca302d0}, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
---- corte ----

No erro gerou várias linhas mais reparei esta parte

wait4(-1, write error code 32
pigz abort: write error on 
write error code 32
pigz abort: write error on 

Reinstalado o pigz e continuou a dar este erro, tiramos a compactação (BACKUP_FILTER e RESTORE_FILTER) parou de dar este erro no backup;