No primeiro post da série vimos como configurar a captura de logs nos processos do PDI, e obter informações básicas sobre os resultados de um processo qualquer.

No segundo post eu mostrei como usar os dados de performance de uma transformação para “caçar” gargalos.

Na terceira e última parte vamos entender como usar as tabelas logging channel para montar um relatório que lista todas as transformações e jobs executados a partir de um job-pai.

Cenário

Eis um exemplo básico de ETL que carrega um Data Warehouse dimensional:

Job principal de refresh do DW Beltrano.
Job principal de refresh do DW Beltrano.

O job acima chama uma transformação que, como o nome diz, define as variáveis do processo, e depois segue chamando os subjobs, cada um com uma tarefa específica: atualizar dimensões, carregar fatos e por fim preencher as tabelas pré-agregadas para OLAP. Por último é chamada outra transformação que coleta informações sobre o estado do DW naquele dia.

Dentro de cada um daqueles subjobs temos uma sequência de transformações, como, por exemplo, a carga das dimensões:

Job de sequenciamento de carga das dimensões.
Job de sequenciamento de carga das dimensões.

E cada uma dessas transformações faz a real movimentação de dados:

Carga da dimensão Cliente.
Carga da dimensão Cliente.

Para sabermos se tudo funcionou precisamos consultar o log de cada uma delas. Como os jobs estão amarrados com avanços condicionais (setas verdes), se der algum problema, o processo inteiro é abortado. Isso dá alguma facilidade de monitoração. Rodando no Spoon, o erro fica aparente:

Problema no processamento das dimensões.
Problema no processamento das dimensões.

Só que em produção não temos Spoon, então precisamos examinar o log:

2016/03/19 10:44:20 - Spoon - Starting job...
2016/03/19 10:44:20 - Refresh DW Beltrano - Start of job execution
2016/03/19 10:44:20 - Refresh DW Beltrano - Starting entry [Seta Variáveis]
2016/03/19 10:44:20 - Seta Variáveis - Loading transformation from XML file [file:///home/beltrano/ETL_Beltrano/t_a_seta_variaveis.ktr]
2016/03/19 10:44:20 - BELTRANO - KTR - Seta Variáveis - Dispatching started for transformation [BELTRANO - KTR - Seta Variáveis]
2016/03/19 10:44:20 - Grava timestamp.0 - Connected to database [beltrano_dw] (commit=1000)
2016/03/19 10:44:20 - Recupera Timestamp do Refresh.0 - Finished processing (I=0, O=0, R=1, W=2, U=0, E=0)
2016/03/19 10:44:20 - Seta variável.0 - Setting environment variables...
2016/03/19 10:44:20 - Seta variável.0 - Set variable REFRESH_TIMESTAMP to value [2016/03/19 10:44:20.724]
2016/03/19 10:44:20 - Seta variável.0 - Finished after 1 rows.
2016/03/19 10:44:20 - Seta variável.0 - Finished processing (I=0, O=0, R=1, W=1, U=0, E=0)
2016/03/19 10:44:20 - Grava timestamp.0 - Finished processing (I=0, O=1, R=1, W=1, U=0, E=0)
2016/03/19 10:44:20 - Refresh DW Beltrano - Starting entry [Carga das Dimensões]
2016/03/19 10:44:20 - Refresh DW Beltrano - Carga das Dimensões - Starting entry [Dimensão Clientes]
2016/03/19 10:44:20 - Dimensão Clientes - Loading transformation from XML file [file:///home/beltrano/ETL_Beltrano/t_d_clientes.ktr]
2016/03/19 10:44:20 - Dimensão Clientes - Dispatching started for transformation [Dimensão Clientes]
2016/03/19 10:44:21 - Lê CNPJs.0 - Finished reading query, closing connection.
2016/03/19 10:44:21 - Lê CNPJs.0 - Finished processing (I=5000, O=0, R=0, W=5000, U=0, E=0)
2016/03/19 10:44:21 - Insere Tipo.0 - Finished processing (I=0, O=0, R=5000, W=5000, U=0, E=0)
2016/03/19 10:44:21 - Formata fluxo PJ.0 - Finished processing (I=0, O=0, R=5000, W=5000, U=0, E=0)
2016/03/19 10:44:21 - Lê CPFs.0 - Finished reading query, closing connection.
2016/03/19 10:44:21 - Lê CPFs.0 - Finished processing (I=50000, O=0, R=0, W=50000, U=0, E=0)
2016/03/19 10:44:21 - Insere Tipo e Cargo.0 - Finished processing (I=0, O=0, R=50000, W=50000, U=0, E=0)
2016/03/19 10:44:21 - Formata fluxo PF.0 - Finished processing (I=0, O=0, R=50000, W=50000, U=0, E=0)
2016/03/19 10:44:21 - Une fluxos.0 - Finished processing (I=0, O=0, R=55000, W=55000, U=0, E=0)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - ERROR (version 5.4.0.0-128, build 1 from 2015-06-03_13-41-59 by buildguy) : Unexpected error
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - ERROR (version 5.4.0.0-128, build 1 from 2015-06-03_13-41-59 by buildguy) : org.pentaho.di.core.exception.KettleDatabaseException: 
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - An error occurred executing SQL: 
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - SELECT count(*) FROM d_clientes WHERE cliente_sk = 0
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - ERROR: relation "d_clientes" does not exist
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -   Position: 22
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - 
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.openQuery(Database.java:1722)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.openQuery(Database.java:1652)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.openQuery(Database.java:1648)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.openQuery(Database.java:1635)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.getOneRow(Database.java:2963)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.trans.steps.dimensionlookup.DimensionLookup.checkDimZero(DimensionLookup.java:1681)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.trans.steps.dimensionlookup.DimensionLookup.processRow(DimensionLookup.java:216)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.trans.step.RunThread.run(RunThread.java:62)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at java.lang.Thread.run(Thread.java:745)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - Caused by: org.postgresql.util.PSQLException: ERROR: relation "d_clientes" does not exist
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -   Position: 22
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2198)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1927)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:561)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:405)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:285)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     at org.pentaho.di.core.database.Database.openQuery(Database.java:1711)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 -     ... 8 more
2016/03/19 10:44:21 - Ordena lista.0 - Finished processing (I=0, O=0, R=55000, W=15882, U=0, E=0)
2016/03/19 10:44:21 - Dimensão Clientes - ERROR (version 5.4.0.0-128, build 1 from 2015-06-03_13-41-59 by buildguy) : Errors detected!
2016/03/19 10:44:21 - Estado.0 - Finished processing (I=28, O=0, R=6154, W=6154, U=0, E=0)
2016/03/19 10:44:21 - Carrega Dimensão Clientes.0 - Finished processing (I=0, O=0, R=1, W=0, U=0, E=1)
2016/03/19 10:44:21 - Dimensão Clientes - Transformation detected one or more steps with errors.
2016/03/19 10:44:21 - Dimensão Clientes - Transformation is killing the other steps!
2016/03/19 10:44:21 - Cidade.0 - Finished processing (I=9715, O=0, R=8553, W=8552, U=0, E=0)
2016/03/19 10:44:21 - Dimensão Clientes - ERROR (version 5.4.0.0-128, build 1 from 2015-06-03_13-41-59 by buildguy) : Errors detected!
2016/03/19 10:44:21 - Refresh DW Beltrano - Carga das Dimensões - Finished job entry [Dimensão Clientes] (result=[false])
2016/03/19 10:44:21 - Refresh DW Beltrano - Finished job entry [Carga das Dimensões] (result=[false])
2016/03/19 10:44:21 - Refresh DW Beltrano - Finished job entry [Seta Variáveis] (result=[false])
2016/03/19 10:44:21 - Refresh DW Beltrano - Job execution finished
2016/03/19 10:44:21 - Spoon - Job has ended.

Lendo o log descobrimos, facilmente, que o problema é a tabela d_clientes, que não foi criada no DW.

“Facilmente”?

Talvez em um processo simples, com poucos passos – e quando o erro aparece logo no começo. Mas achar o erro em um log desses, que pode chegar a vários megabytes, é qualquer coisa, menos “fácil”.

Você pode argumentar que basta fazer uma busca por ERROR. Verdade, mas precisaria fazer a busca no log inteiro, até o fim! E depois outra: onde é que apareceu mesmo esse erro? Examine o log outra vez: depois que achar o erro, você precisa seguir o log para cima, para descobrir em que arquivo (job ou transformação) ele ocorreu, ou para baixo, até encontrar o nome do job/transformação – mas não o nome do arquivo!

Resumindo: dá para fazer, mas é um porre.

Encontrando Nemo. Digo, Erros!

Eu sempre digo que sou um cara prático (preguiçoso é feio, ainda que seja mais franco, hehe) e gosto de usar computadores para fazer qualquer tarefa que possa ser feita por eles.

Uma forma mais fácil de encontrar erros é montar uma consulta como a do primeiro artigo e listar tudo que possuir o campo status igual a stop:

 (SELECT
       id_job,
       'Job' as tipo,
       jobname as nome,
       status,
       to_char(replaydate, 'DD/MM/YY HH24:MI:SS') as replaydate
  FROM job
  WHERE status='stop')
UNION
  (SELECT
       id_batch,
       'Transformação' as tipo,
       transname as nome,
       status,
       to_char(replaydate, 'DD/MM/YY HH24:MI:SS') as replaydate
  FROM transformation
  WHERE status='stop')
ORDER BY replaydate,nome

Resultado:

id tipo nome status replaydate
3 Job Popula Empresa-Case stop 23/02/16 20:48
8 Job Empresa-Case – Popula Tabelas Indepentes stop 23/02/16 20:55
2037 Transformação BELTRANO – KTR – Seta Variáveis stop 19/03/16 10:32
2039 Transformação Dimensão Clientes stop 19/03/16 10:33
2041 Transformação Dimensão Clientes stop 19/03/16 10:35
2043 Transformação Dimensão Clientes stop 19/03/16 10:44

Bem melhor, não? O problema aqui é que ele traz todo mundo. Ainda precisaríamos fazer algum filtro para pegar só o do dia anterior, ou até uma semana para trás, ou algo assim.

Mas podemos fazer melhor.

16.3 Árvore Genea-LOG-ica

Segundo Matt Casters, a tabela de logging channels surgiu como uma forma de amarrar os diversos logs: todas as coisas que são geradas no PDI ganham um ID particular, que é usado sempre que precisam – internamento ou no registro de log – se referir à aquele objeto. (Pelo menos foi o que eu entendi.) Isso é uma evolução em relação ao sistema antigo, que usava um ID sequencial para cada item, o que, convenhamos, é algo um tanto quanto noob.

O sistema de logs do PDI grava os canais de log em um tabela com o seguinte layout:

Coluna Tipo Descrição
id_batch int4 ID do lote
channel_id varchar ID do canal
log_date timestamp Data de registro nesta tabela
logging_object_type varchar Tipo do objeto: job, stransformação, banco de dados etc.
object_name varchar Nome do objeto
object_copy varchar Número da cópia do objeto
repository_directory varchar Caminho do objeto (repositório em banco)
filename varchar Diretório e nome do arquivo que contém este objeto
object_id varchar ID do objeto no repositório (repositório em banco)
object_revision varchar Versão do objeto (só para versão EE)
parent_channel_id varchar ID do canal do objeto-pai, que criou este objeto
root_channel_id varchar ID do canal do objeto-ancestral, que deu origem a todos os outros

O PDI pode salvar jobs e transformações em um sistema de arquivos, como um arquivo XML, ou em um repositório em banco de dados. As colunas da tabela que se referem a atributos válidos apenas para artefatos gravados no repositório em banco de dados recebem nulo quando o job ou transformação é gravado como um arquivo ordinário.


Pelo fato de os IDs serem gerados como um hash, o risco de colisão é próximo de nulo. Tanto é assim que as tabelas para canais de job e transformação tem o mesmo layout, e a Pentaho recomenda usar uma só tabela para registrar os dois.

Eis o conteúdo de algumas destas colunas:

Algumas colunas da tabela logging Channels.
Algumas colunas da tabela logging Channels.

Podemos usar essa tabela para listar todos os jobs e transformações envolvidos em um único processo. Depois, usando as tabelas de log de job e transformação, podemos adicionar o status e ordená-los pela data e hora de inicialização (replaydate.) Podemos montar um relatório com esse resultado. Daí poderemos revisar o processamento do dia e encontrar eventuais falhas muito mais – agora sim! – facilmente.

Vamos fazer isso, então.

Lista de Jobs-Raiz

Um job-raiz, por falta de um termo melhor, é um job que está na raiz de um processamento qualquer, e corresponde à lista de todos os tipos de objeto (coluna logging_object_type) JOB, cujo pai é nulo e que as tem a coluna root_channel_id igual à channel_id. Por exemplo, na figura anterior, o último job do ID_BATCH igual à 1023 é um job-raiz.

A consulta que traz isso é:

SELECT id_batch,
       channel_id,
       log_date,
       object_name
FROM job_logging_channels
WHERE logging_object_type = 'JOB'
      AND parent_channel_id IS NULL
      AND channel_id = root_channel_id

E eis o resultado:

id_batch channel_id log_date object_name
18 f411e0d2-… 2016-02-23 21:45:12.588 Popula Empresa-Case
22 9e142006-… 2016-02-23 22:27:00.323 Popula Tabelas de Pedidos
1023 b604142b-… 2016-03-19 10:27:20.576 Refresh DW Beltrano

Essa lista é o primeiro filtro do relatório: o conteúdo da coluna object_name será apresentado ao usuário como um prompt. E como cada job pode ter sido executado diversas vezes, um segundo prompt vai apresentar a lista de datas em que aquele processo foi executado, para que o usuário escolha que corrida analisar.

A lista de datas de execução é obtida com uma consulta na tabela de log do job, filtrada pelo object_name. Usando o job Popula Empresa-Case como exemplo, a lista de datas vem desta consulta:

SELECT DISTINCT
       channel_id,
       replaydate
FROM job
WHERE jobname = 'Popula Empresa-Case'

Usando essas consultas eu comecei o relatório:

Relatório de linhagem do job, com prompts de job e corrida.
Relatório de linhagem do job, com prompts de job e corrida.

Lista de Descendentes

A forma como a tabela de canais foi bolada permite construir uma consulta recursiva, para recuperar todas as partes de um processo, descendo até o último nível. Essa é a forma correta de consultar essa tabela. Porém, como eu não sei tanto SQL para poder construir uma consulta recursiva, vou apenas ser criativo e fazer de outra forma.

Os descendentes daquele job-raiz tem todos uma coisa em comum: o mesmo job-raiz (duhn.) Logo, podemos selecionar todos os elementos – jobs e transformações – que foram executados no mesmo pacote fazendo outra consutla à tabela de log. Eis como selecionar somente os jobs e transformações disparados pelo job principal:

SELECT channel_id,
       logging_object_type,
       object_name
FROM job_logging_channels
WHERE logging_object_type IN ('JOB','TRANS')
      AND root_channel_id = ${job_raiz}

O resultado, especificamente para o caso do job-raiz 9e142006-fb5d-4b28-8b87-1ff0c706919e, é:

channel_id logging_object_type object_name
d4d5227e-c07b-45d1-a6a9-715310de2e7e TRANS Gera Pedidos
56639da7-cb6d-435f-8d1e-c3a1f99c8687 TRANS Gera Parâmetros para Itens de Pedidos
06af3232-75ea-4b7f-b178-eab915e190df TRANS Seta Variáveis de Subitens
ee44ed8d-dbcc-431b-9b9d-d8220fe78838 TRANS Gera Pedidos Detalhes
aa0a4992-be94-4f8e-b0bf-98d14c0baaef JOB Popula Itens de Pedidos
957dc288-16e1-462c-9f1a-89efb026a2a2 TRANS Seta Variáveis de Subitens
4f2927bf-14c5-4b5a-a0d3-8a4c8eb597d7 TRANS Gera Pedidos Detalhes
a4dbea3e-6731-4fc3-92fb-1230888847d9 TRANS Seta Variáveis de Subitens
095dd255-20ec-4b96-a1d5-cf3a316f248d TRANS Gera Pedidos Detalhes
9e142006-fb5d-4b28-8b87-1ff0c706919e JOB Popula Tabelas de Pedidos

Pronto! Temos a nossa lista de jobs e transformações que compõe o job principal! Agora precisamos apenas dos detalhes de cada um deles, que estão nas respectivas tabelas de log de job e de transformação.

Detalhando a Lista

Como os detalhes de jobs e transformações estão em tabelas separadas, vamos fazer dois JOINs e depois reuni-los. Primeiro, os detalhes dos jobs:

SELECT logging_object_type,
       object_name,
       status,
       replaydate
FROM job_logging_channels, job
WHERE logging_object_type = 'JOB'
      AND job_logging_channels.channel_id = job.channel_id
      AND root_channel_id = ${job_raiz}

E agora os das transformações:

SELECT logging_object_type,
       object_name,
       status,
       replaydate
FROM job_logging_channels, transformation
WHERE logging_object_type = 'TRANS'
      AND job_logging_channels.channel_id = transformation.channel_id
      AND root_channel_id = ${job_raiz}

Unindo as duas consultas, temos o resultado completo:

Relatório completo, mostrando a linhagem de execução, ordenada por data/hora.
Relatório completo, mostrando a linhagem de execução, ordenada por data/hora.

Conclusão & Encerramento

O Pentaho Data Integration é uma das mais modernas e sofisticadas ferramentas de integração de dados disponíveis. Entre seus vários recursos estão a captura de logs muito detalhados, dos quais podemos extrair um gama de informaçôes sobre os processos executados por ele.

Nesta série vimos como configurar e usar o sistema de logs do PDI para obter uma visão simples, ainda que minimamente completa, sobre o que se passou em uma dada corrida (primeiro post).

No segundo post vimos como analisar os logs das transformações para detectar os gargalos, isto é, os pontos que puxam a velocidade da dita transformação para baixo.

Com este terceiro post concluímos a série. Vimos como usar um recurso fundamental do sistema de logs, a tabela de “canais” de log (logging channels), para montar uma listagem que sequencia todos os jobs e transformações executados em um processo (clique aqui para baixar o relatório.)

Esses três artigos formam um exemplo simples e prático para monitorar o processo diário, mas há muito que podemos fazer para melhorar a gestão de um DW. Por exemplo, temos todas as possibilidades de automação de detecção de erros e acionamentos por e-mail.

Até a próxima. ;-)

Deixe uma resposta

Preencha os seus dados abaixo ou clique em um ícone para log in:

Logotipo do WordPress.com

Você está comentando utilizando sua conta WordPress.com. Sair / Alterar )

Imagem do Twitter

Você está comentando utilizando sua conta Twitter. Sair / Alterar )

Foto do Facebook

Você está comentando utilizando sua conta Facebook. Sair / Alterar )

Foto do Google+

Você está comentando utilizando sua conta Google+. Sair / Alterar )

Conectando a %s