Analisando os Logs do PDI – Parte 1

O Pentaho Data Integration, antigamente conhecido por Kettle, é a ferramenta de integração de dados da Suite Pentaho. É, de longe, a ferramenta de maior sucesso deles e tanto é assim que fornecedores tradicionais desse mercado “sentiram o calor” da concorrência.

Neste post eu não vou falar sobre o PDI em si, mas sobre uma de seus recursos: o log.

Toco Cru

Em inglês, log significa “tora de madeira”.

Those are the logs.

Ou diário, como em captain’s log, o diário do capitão, ou lab log, que é aquele caderninho preto em que cientistas anotam o que aconteceu nos experimentos. :-) Quando dizemos que um programa gera logs, estamos querendo dizer que ele registra, em algum lugar, informações sobre o que está acontecendo. Podem ser erros, avisos ou simplesmente uma narração das ações do programa. Em geral, cada entrada no registro possui uma etiqueta de tempo, ou timestamp, para que seja possível saber quando tal evento ocorreu, e colocá-los em sequência, para estudo.

Transformações e jobs do PDI geram uma profusão de dados durante seu processamento, e a maioria dos usuários do PDI vê parte desses dados na saída do processamento:

geekbi@dw:/opt/pentaho/5.1/data-integration$ ./pan.sh -file=/home/Beltrano/00_Beltrano_1.0/ETL/t_d_date.ktr
2016/02/21 10:50:04 - Pan - Start of run.
2016/02/21 10:50:05 - Dimensão Data - Dispatching started for transformation [Dimensão Data]
2016/02/21 10:50:05 - d_date.0 - Connected to database [beltrano_dw] (commit=10000)
2016/02/21 10:50:05 - Days of week.0 - Finished processing (I=0, O=0, R=0, W=7, U=0, E=0)
2016/02/21 10:50:05 - Months.0 - Finished processing (I=0, O=0, R=0, W=12, U=0, E=0)
2016/02/21 10:50:05 - 10000 dias: 25 anos.0 - LineNr : 5000
2016/02/21 10:50:05 - Days_since.0 - linenr 5000
2016/02/21 10:50:05 - 10000 dias: 25 anos.0 - LineNr : 10000
2016/02/21 10:50:05 - 10000 dias: 25 anos.0 - Finished processing (I=0, O=0, R=0, W=10000, U=0, E=0)
2016/02/21 10:50:05 - Days_since.0 - linenr 10000
2016/02/21 10:50:05 - Days_since.0 - Finished processing (I=0, O=0, R=10000, W=10000, U=0, E=0)
2016/02/21 10:50:05 - Calc Date.0 - Linenr 5000
2016/02/21 10:50:05 - DayOfWeekDesc.0 - linenr 5000
2016/02/21 10:50:05 - MonthDesc.0 - linenr 5000
2016/02/21 10:50:05 - Select values.0 - linenr 5000
2016/02/21 10:50:05 - d_date.0 - linenr 5000
2016/02/21 10:50:06 - Calc Date.0 - Linenr 10000
2016/02/21 10:50:06 - Calc Date.0 - Finished processing (I=0, O=0, R=10000, W=10000, U=0, E=0)
2016/02/21 10:50:06 - Quarter.0 - Finished processing (I=0, O=0, R=10000, W=10000, U=0, E=0)
2016/02/21 10:50:06 - DayOfWeekDesc.0 - linenr 10000
2016/02/21 10:50:06 - DayOfWeekDesc.0 - Finished processing (I=0, O=0, R=10007, W=10000, U=0, E=0)
2016/02/21 10:50:06 - MonthDesc.0 - linenr 10000
2016/02/21 10:50:06 - MonthDesc.0 - Finished processing (I=0, O=0, R=10012, W=10000, U=0, E=0)
2016/02/21 10:50:06 - Select values.0 - linenr 10000
2016/02/21 10:50:06 - Select values.0 - Finished processing (I=0, O=0, R=10000, W=10000, U=0, E=0)
2016/02/21 10:50:06 - d_date.0 - linenr 10000
2016/02/21 10:50:06 - d_date.0 - Finished processing (I=0, O=10000, R=10000, W=10000, U=0, E=0)
2016/02/21 10:50:06 - Pan - Finished!
2016/02/21 10:50:06 - Pan - Start=2016/02/21 10:50:04.785, Stop=2016/02/21 10:50:06.757
2016/02/21 10:50:06 - Pan - Processing ended after 1 seconds.
2016/02/21 10:50:06 - Dimensão Data -
2016/02/21 10:50:06 - Dimensão Data - Step Days_since.0 ended successfully, processed 10000 lines. ( 10000 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step Calc Date.0 ended successfully, processed 10000 lines. ( 10000 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step DayOfWeekDesc.0 ended successfully, processed 10007 lines. ( 10007 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step MonthDesc.0 ended successfully, processed 10012 lines. ( 10012 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step Select values.0 ended successfully, processed 10000 lines. ( 10000 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step d_date.0 ended successfully, processed 10000 lines. ( 10000 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step Quarter.0 ended successfully, processed 10000 lines. ( 10000 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step Days of week.0 ended successfully, processed 7 lines. ( 7 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step Months.0 ended successfully, processed 12 lines. ( 12 lines/s)
2016/02/21 10:50:06 - Dimensão Data - Step 10000 dias: 25 anos.0 ended successfully, processed 10000 lines. ( 10000 lines/s)

Essa é só a narração dos eventos, mas muitos outros dados são capturado durante o processamento: quantidade de linhas lidas e gravadas em bancos e arquivos, quantidade de linhas processadas em cada passo, conteúdo de variáveis carregadas, conexões feitas, erros, aviso – o PDI captura tudo, tudo, até a vazão da pia da cozinha. Esses dados podem ser descarregados diretamente num banco, o que habilita o gestor do projeto a monitorar a carga minuciosamente. Por exemplo, podemos criar indicadores de performance e acompanhá-los diariamente, ou buscar informações sobre o que aconteceu durante uma corrida qualquer do ETL.

Está série é composta de três posts. Nesta primeira parte vamos mostrar como configurar o PDI para injetar os dados capturados em um banco de dados e como construir um relatório bem simples, com indicadores básicos sobre o processamento.

Na Parte 2 veremos como descobrir gargalos, que são pontos de lentidão no fluxo de dados. Por fim, na parte 3, veremos um relatório que dá a genealogia (quem chamou quem, a que horas e quanto tempo levou) de um job, uma informação crucial para o monitoramento da “saúde” do processo.

Ativando a Captura de Log

O PDI descarrega seu log apenas em bancos de dados. Por isso você precisa ter um banco de destino para gravar seus logs. Normalmente eu mantenho um esquema de log nos mesmos bancos dos DWs, pois isso simplifica tanto o desenvolvimento quanto a análise.

Uma vez que você tenha um banco/esquema, precisamos definir quais tabelas receberão os logs. De novo, eu adoto um padrão: trans_LOG para log das transformações, e job_LOG para jobs. Neste caso, LOG é o nome do log capturado na tabela.

Na versão 5.4 o PDI captura os seguintes logs (com o nome da tabela que eu uso entre parênteses):

• Transformações:
  1. Transformation (transformation): registra uma linha por transformação, por corrida. O campo LOG_FIELD contém o log de texto do processamento;
  2. Step (transformation_steps): registra um sumário do processamento de cada passo, em cada transformação, por corrida, em uma linha por passo. Ligado à anterior pela coluna ID_BATCH;
  3. Performance (transformation_performance): mede a vazão de linhas através de cada passo, segundo a segundo, em cada corrida de uma transformação, uma linha por passo, por segundo. Ligado à tabela de log de transformações pela coluna ID_BATCH;
  4. Logging channels (transformation_lc): registra os nomes e propriedades dos “canais” de dados em uma transformação ou job;
  5. Metrics (não coleto esta): http://forums.pentaho.com/showthread.php?137582-Output-steps-metrics-How-to-use
• Jobs:
  1. Jobs (jobs): equivalente à da transformação, registra os dados de cada execução de um job em uma linha. Assim como na transformação, o mesmo campo LOG_FIELD contém toda saída de texto do processamento;
  2. Job Entry (job_entry):
  3. Job Logginc Channels (job_lc): registra os nomes e propriedades dos “canais” de dados em uma transformação ou job. Possui o mesmo layout que a logging channels das transformações. Pelo que entendi, a “boa prática” é serem a mesma.

---

Eu simplifiquei um pouco essas descrições, ou a coisa viraria um livro. Por exemplo, cada log possui parâmetros de tempo de vida e latência de atualização. Consultem o Pentaho Infocenter, a Wiki, o Kettle Solutions ou o Pentaho na Prática para mais informações. Nosso foco hoje é aprender a capturar e usar.

---

Todos esses parâmetros são entrados na aba de log das janelas de propriedades das transformações…

Aba de logs de uma transformação.

 

… e jobs:

Aba de logs de um job.

Para chamar essa janela clique com o botão direito sobre qualquer parte em branco de um job ou transformação e, no menu que aparecer, escolha Transformation settings (ou Job settings.)

Esses parâmetros podem ser preenchidos de três maneiras:

1. Manualmente, entrando os nomes de tabelas e valores dos parâmetros um por um, em toda transformação e job que você criar. Essa alternativa é boa para testes e estudos, enquanto você não está em projeto, por que é mais rápida e prática. Só que, se estiver em um projeto e definir todos os valores manualmente, você vai ter um trampo cabuloso para mudar qualquer coisa, pois vai ter que editar todos os artefatos, um por um, do processo inteiro;
2. Por meio de variáveis definidas pelo desenvolvedor: defina uma variável para cada parâmetro no arquivo kettle.properties e insira-as nos lugares adequados usando a sintaxe ${VARIÁVEL}. O início é tedioso, como na opção anterior, mas é mais flexível pois basta mudar a variável no kettle.properties para propagar seu valor por todo processo. É a melhor opção quando temos vários projetos, pois podemos criar lotes de variáveis para cada um;
3. Definindo valores das variáveis-default do PDI: esse método é de longe o mais prático para quem lida com um só projeto, pois você não precisa alterar nada em nenhuma transformação ou job. Cada campo das definições de log possui uma variável default. Definindo o valor destas no kettle.properties, o PDI configura a captura do log automaticamente. Por outro lado, se você trabalhar em mais de um projeto, vai precisar trocar essas variáveis sempre que mudar de projeto.

---

Alguns truques facilitam a vida do desenvolvedor: ao invés de configurar manualmente o log em todos os artefatos, crie modelos de transformação e job já configurados. Daí, quando precisar criar uma nova transformação/job, use o modelo: duplique o arquivo ou abra e salve com outro nome e comece dali. Meus modelos não apenas possuem os logs pré-configurados, como ainda deixo notas e padrões de documentação pré-preenchidos.

---

As variáveis são definidas no arquivo <diretório do usuário>/.kettle/kettle.properties. O Spoon oferece uma interface para fazer essa edição sem precisar sair da interface gráfica: clique no menu Edit e escolha a opção Edit the kettle.properties file. Aparecerá uma janela listando todas as variáveis default, mesmo que estejam vazias, além de todas as variáveis definidas pelo desenvolvedor:

Janela de edição do conteúdo do arquivo kettle.properties (variáveis.)

Lembre-se de fechar o Spoon antes de editar o arquivo diretamente. Caso contrário, não apenas ele não vai ver os novos valores e variáveis, como ainda corre-se o risco de elas serem apagadas.

Um último detalhe: quase todos os logs são capturados por default. Quase: o de performance de passo, que é o que mais gera linhas no banco, está desligado por default. Para ativá-lo marque o checkbox Enable step performance monitoring? na aba Monitoring (a última na versão 5.4) das propriedades da transformação:

Ligue o checkbox para capturar o rendimento de cada passo da transformação.

Criando as Tabelas

Como tudo no Spoon, sempre que algo escreve em uma tabela, um botão que permite criar ou ajustar essa tabela automaticamente. Para criar qualquer tabela de log basta preencher seus dados de conexão e nome, e clicar no botão SQL no fundo da janela de propriedades:

Criando as tabelas de log de transformação com ajuda do botão SQL.

Se você preencher todos os parâmetros antes e deixar o botão de SQL para o fim, o Spoon vai te dar um monte de janelas, uma para cada tabela. O mesmo vale os logs de jobs.

Analisando Logs

Para os exemplos vamos usar o log gerado pela repetição do processo de carga do Beltrano S/A, de mil pedidos. Esse backup está disponível aqui, como um pacote RAR. Consulte as instruções de restauração da base Beltrano, lembrando apenas de substituir o nome do arquivo para o do arquivo da base de logs.

Vamos ver dois relatórios tão simples quanto úteis:

• Logs de jobs e transformações
• Histórico de performance

Logs de Jobs e Transformações

Quem cuida de processos de ETL sabe que a principal pergunta que se faz é “Rodou? Deu certo? O que aconteceu?”

Ok, são três perguntas, mas no fundo todas elas querem saber a mesma coisa: se o processo funcionou ou não, e o que aconteceu, se tiver dado erro.

A forma mais simples de respondê-las seria olhar o log de texto, o relato de tudo que se passou durante o processamento. É o primeiro lugar que devemos olhar porque é ali que estão as mensagens de erros. Eu chamo esse tipo de relatório simplesmente de “Relatório de Log”: Log de Jobs e Log de Transformações. Ele mostra um cabeçalho com parâmetros do objeto sendo examinado, como datas, status e duração, e logo abaixo o conteúdo de texto do processamento. A consulta que eu uso é assim:

Transformação

SELECT
     'Duracao em Segundos' as categoria,
     id_batch,
     transname,
     status,
     lines_read,
     lines_written,
     lines_updated,
     lines_input,
     lines_output,
     lines_rejected,
     replaydate,
     logdate,
     extract(hour from (logdate - replaydate))*60*60 +
          extract(minute from (logdate - replaydate))*60 +
          extract(second from (logdate - replaydate)) as duracao,
     log_field
FROM
     transformation

Job

SELECT
     'Duracao em Segundos' as categoria,
     id_job,
     jobname,
     status,
     lines_read,
     lines_written,
     lines_updated,
     lines_input,
     lines_output,
     lines_rejected,
     replaydate,
     logdate,
     extract(hour from (logdate - replaydate))*60*60 +
          extract(minute from (logdate - replaydate))*60 +
          extract(second from (logdate - replaydate)) as duracao,
     log_field
FROM
     job

Note a diferença entre os nomes dos campos dos dois artefatos (job e transformação), mas como mesmo assim são parecidos.

Essas consultas retornam todos os logs, de todas as transformações e jobs, o que é uma coisa inútil – imagine ter que varrer centenas, milhares de páginas atrás de um job ou outro! Por isso eu filtro essa consulta com dois prompts: um para nome do artefato e outro para seu batch, ou lote. As consultas para nomes são assim:

Lista de nomes de transformações:

SELECT DISTINCT transname
FROM transformation
ORDER BY transname ASC

Lista de nomes de jobs:

SELECT DISTINCT jobname
FROM job
ORDER BY jobname ASC

Quando o prompt de nome é preenchido, o prompt de lote fica disponível. As consultas para lotes são:

Lista de lotes de transformações:

SELECT id_batch,replaydate
FROM transformation
WHERE transname=${nome_transformacao}
ORDER BY id_batch DESC

Lista de lotes de jobs:

SELECT id_job,replaydate
FROM job
WHERE jobname=${nome_job}
ORDER BY id_job DESC

Com os dois prompts preenchidos (que estão marcados como obrigatórios, a propósito), o relatório roda:

Relatório de log de transformação.

Histórico de Performance

O mesmo resultado é obtido no relatório de jobs e seria redundante mostrá-lo tal como está. Vamos avançar um pouco, e mostrar o relatório de jobs com um pouco mais de informações: um histórico de duração.

Depois de saber “se deu certo”, o aspecto mais importante do ETL é sua repetibilidade. Afinal, se montamos um processo acreditando que, todo dia, ele vai rodar em menos de uma hora, precisamos saber se isso está acontecendo ou não.

Poderíamos usar o relatório anterior e, manualmente, examinar os tempos de um mesmo job ou transformação, em várias corridas ao longo de um período – uma semana, por exemplo. Trabalhoso. Bom, nós somos o pessoal da Inteligência de Negócios ou não? Como seria um vexame ter tanto trabalho, vamos ser mais práticos: vamos colocar um gráfico das várias execuções.

Pegamos o mesmo relatório anterior e acrescentamos uma nova consulta: a lista da duração das últimas X execuções em ordem crescente:

SELECT * FROM
(SELECT
     'Duracao em Segundos' as categoria,
     id_job,
     to_char(replaydate, 'DD/MM/YY HH24:MI:SS') as replaydate,
     extract(hour from (logdate - replaydate))*60*60 +
     extract(minute from (logdate - replaydate))*60 +
     extract(second from (logdate - replaydate)) as duracao
FROM job
WHERE jobname=${nome_job}
ORDER BY id_job DESC
LIMIT 30) AS X
ORDER BY id_job ASC

O SELECT interno obtém uma lista das últimas 30 execuções do job nome_job (o nome do parâmetro que contém a seleção do usuário). O SELECT externo inverte a ordem para que o gráfico seja plotado corretamente. O resultado dessa consulta para, por exemplo, o job Popula Tabelas Dependentes, é:

categoria	id_job	replaydate	Duracao
Duracao em Segundos	2	23/02/16 20:34:24	1.064
Duracao em Segundos	5	23/02/16 20:51:37	0.671
Duracao em Segundos	7	23/02/16 20:54:54	0.655
Duracao em Segundos	11	23/02/16 21:01:08	0.652
Duracao em Segundos	14	23/02/16 21:07:54	0.742

Como um relatório pode ter apenas uma consulta ativa, e o relatório tal como está já usa uma, precisamos adicionar um sub-relatório para poder usar essa nova query. Neste sub-relatório, que herda essa consulta, adicionamos apenas o elemento de chart. Eu usei um gráfico de linhas, mas poderíamos usar qualquer outro tipo – barras, bullets, área etc.

Sub-relatório com consulta e parâmetro herdados do relatório principal.

Rodando o relatório o PRD vai exibir o prompt, já visto na figura acima. Já ao selecionar um job o gráfico será preenchido. Após selecionarmos um dos lotes – uma das corridas ou execuções do job – aparece o log logo (hehe) abaixo do plot.

Resultado: log do job selecionado, com visão simultânea das últimas execuções.

Você pode baixar esses relatórios neste link.

---

Todos os materiais foram criados com a suite 5.4 do Pentaho. Se você tentar usar, e não conseguir, deixe um comentário que eu tento te ajudar.

---

Conclusão

Com um pouco mais de trabalho – configurar a captura de log e criar os relatórios – o gestor de ETL pode conseguir uma riqueza de informações sobre seu processo. Entre outros benefícios, o gerente de ETL passa a ser capaz de dizer, em poucos minutos, com poucos cliques, se o processo rodou hoje, se demorou mais, se deu algum erro e vários outros detalhes (incluindo volume processado e tempo de cada processamento.)

Outra função importante servida pelos logs é apoio na melhoria do processo. No próximo post veremos como usar os dados de performance das transformações para analisar o perfil de processamento e identificar gargalos.

Até lá! ;-)