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:
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:
E cada uma dessas transformações faz a real movimentação de dados:
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:
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:
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:
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:
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. ;-)
Geek BI 