No primeiro post da série Logs do PDI vimos como configurar as transformações e jobs do PDI para capturar os logs de processamento e como usá-los para monitorar as execuções. Neste segundo post veremos como usar esses dados para identificar gargalos.

Pias & Transformações

Imagine uma pia, na qual uma torneira despeja água. Se entrar mais água do que a pia consegue escoar, a água vai começar a se acumular. Se nada for feito, o nível de água na pia vai subir, e subir, até transbordar. Há duas formas de se evitar que a água transborde: reduzir a entrada ou aumentar a saída. Em termos mais genéricos, para evitar que a água transborde devemos condicionar a entrada à restrição. A “restrição” é justamente a válvula de escoamento da pia.

A velocidade de uma transformação, medida em linhas por segundo, l/s, está condicionada à restrição existente na transformação: a velocidade de uma transformação será igual à velocidade do seu passo mais lento. Esse passo mais lento é o gargalo.


Se uma transformação possuir passos de ordenação de linhas, agrupamentos etc., que represam linhas, a velocidade média da transformação perde essa relação direta. Ainda vai haver uma relação entre a velocidade da transformação e a velocidade do seu passo mais lento, apenas não será mais 1 para 1. Mas, para manter o didatismo do post, vamos assumir uma transformação perfeitamente esférica e sem atrito, na qual essa condição vale. ;-)


Para aumentar a velocidade de uma transformação, portanto, devemos aumentar a velocidade do fluxo (em l/s) no gargalo. Quando a velocidade no gargalo tiver subido o bastante, algum outro passo vai ser o responsável por restringir a velocidade da transformação, se transformando no novo gargalo. Removemos esse novo gargalo, aumentando a velocidade da transformação, e outro aparecerá, reiniciando o processo. Eventualmente, chegaremos num ponto de rendimento máximo da transformação, no qual uma nova mudança em qualquer passo não vai resultar em aumento de velocidade da transformação.

Simples, não?

Engarrafamento de Linhas

E como descobrimos gargalos em uma transformação?

Usando o Spoon para detectar gargalos: notou um pontilhado em volta de algum passo? É um gargalo!
Usando o Spoon para detectar gargalos: notou um pontilhado em volta de algum passo? É um gargalo!

Se você estiver rodando-a no Spoon, a interface gráfica do PDI, é muito fácil. O PDI detecta o gargalo, definido por ele como “o passo que recebe mais linhas do que é capaz de processar”, e faz com que o Spoon apresente um pontilhado animado em volta de cada passo identificado como gargalo. Esse monitoramento ocorre em tempo real, e causa efeitos curiosos: em certas situações o gargalo parece “pular” entre dois ou mais passos, e em outras vários passos são marcados como gargalos, simultaneamente. A dinâmica que causa isso está fora do escopo deste post, mas não é difícil de entender se você parar para pensar um pouco.

Para que seu Spoon mostre esse passo na sua transformação você precisa habilitar o checkbox Show bottleneck transformation steps, conforme visto na figura abaixo. Essa janela aparece quando selecionamos o item Options, no menu Tools.

Onde fica o checkbox que habilita a exibição do gargalo.
Onde fica o checkbox que habilita a exibição do gargalo.

Essa opção é muito boa durante o processo de desenvolvimento, mas o que fazer para transformações que rodamos em produção? É um ambiente diferente – memória diferente, disco diferente, carga (tarefas simultâneas) diferentes! Se bobear até o sistema operacional é diferente! Não dá para rodar uma por uma no Spoon e ficar olhando, esperando encontrar um passo-gargalo.

Você adivinhou: consultamos o log de performance.

Entendendo o Gargalo

Conforme o próprio PDI coloca, um gargalo (ou restrição) é “um passo que recebe mais linhas do que é capaz de processar”. Para entender isso você precisa saber um pouco sobre a estrutura interna de um passo.

Um passo possui, grosso modo, três partes:

  1. Buffer de entrada: onde são gravadas as linhas que chegam do passo anterior, e onde elas ficam esperando ser processadas;
  2. Motor do passo: retira uma linha do buffer de entrada, processa e grava o resultado no buffer de saída, repetindo esse processo enquanto o passo anterior estiver mandando linhas;
  3. Buffer de entrada: onde são gravadas as linhas processadas pelo passo, e onde elas aguardam até o engine do PDI movê-las para o passo seguinte.
Todo passo possui dois buffers: entrada e saída.
Todo passo possui dois buffers: entrada e saída.

Assim, se o motor do passo, o processamento em si, não for rápido o bastante, ele começa a ficar para trás: as linhas começam a se acumular no buffer de entrada. Se, além disso, se o passo seguinte for no mínimo tão rápido quanto o passo atual, as linhas processadas não “esquentam cadeira” no buffer de saída, e vão sendo levadas adiante. Por exemplo, na transformação simples mostrada abaixo, com três passos, o passo do meio é um gargalo:

O passo do meio é um gargalo: buffer de saída com menos linhas que o de entrada.
O passo do meio é um gargalo: buffer de saída com menos linhas que o de entrada.

Note que os buffers do passo do meio, representados pelas caixas de entrada e saída, aparecem vazio na saída e cheio na entrada. Essa é a condição de gargalo, ou de restrição. Se pudermos aumentar (elevar) a vazão dessa restrição, a velocidade da transformação, como um todo, aumentará.

Como vemos isso nos logs? Bom, quando rodamos uma transformação no Spoon, este monta um quadro de métricas dos passos, e atualiza-o conforme a transformação vai sendo executada, conforme as linhas vão sendo processadas.

Passos e seus parâmetros durante execução.
Passos e seus parâmetros durante execução.

A coluna input/output, última à direita na imagem anterior, exibe a relação entre a quantidade de linhas presentes no buffer de entrada, aguardando processamento, e quantidade de linhas no buffer de saída, aguardando transporte até o passo seguinte. Sempre que um passo possui mais linhas em sua entradas que em sua saída, ele está “segurando” a transformação. Para encontrarmos os gargalos de uma transformação, então, basta analisarmos os passos dela, em busca de buffers de entrada cheios e buffers de saída vazios (ou com bem menos linhas.)

Analisando Vazão em Transformações

O log que captura as métricas de cada passo, segundo a segundo, chama-se Performance. Veja como ativá-lo no primeiro post da série. Essa tabela possui as seguintes colunas:

  • id_batch
  • seq_nr
  • logdate
  • transname
  • stepname
  • step_copy
  • lines_read
  • lines_written
  • lines_updated
  • lines_input
  • lines_output
  • lines_rejected
  • errors
  • input_buffer_rows
  • output_buffer_rows

Reparou nas duas últimas? São as que nos interessam.


Não vou montar uma solução pronta, mas mostrar como usar essa tabela para desenhar algo que atenda à sua necessidade – e depois vou mostrar um exemplo do relatório que eu uso para “debugar” transformações em produção.


Precisamos de uma consulta que traga os buffers, por cada passo, por transformação. Além disso, como cada transformação pode ter sido executada várias vezes, precisamos filtrar também por lote (id_batch.) Essa consulta ficaria assim:

SELECT
  id_batch,
  transname,
  stepname,
  input_buffer_rows,
  output_buffer_rows
FROM transformation_performance
WHERE
  id_batch = X AND
  transname = 'x'

Filtrando para lote 2080 e transformação Carga da Lista de Clientes PF, temos:

id_batch transname stepname input_buffer_rows output_buffer_rows
2080 Carga da Lista de Clientes PF Gera strings aleatórias 224 276
2080 Carga da Lista de Clientes PF Cria CEP, Telefone e Fax 0 0
2080 Carga da Lista de Clientes PF Cria CEP, Telefone e Fax 0 0
2080 Carga da Lista de Clientes PF Lê nomes 0 0
2080 Carga da Lista de Clientes PF Cria as partes de CEP, Telefone e Fax 0 0
2080 Carga da Lista de Clientes PF Muda rnd_telefone/fax para string 0 0
2080 Carga da Lista de Clientes PF Seleciona endereço 2 0
2080 Carga da Lista de Clientes PF Lê sobrenomes 0 61
2080 Carga da Lista de Clientes PF Acerta tamanho das strings 0 0
2080 Carga da Lista de Clientes PF Seleciona sobrenome 61 0
2080 Carga da Lista de Clientes PF Lê lista de enderecos 0 0
2080 Carga da Lista de Clientes PF Seleciona nome 0 0
2080 Carga da Lista de Clientes PF Cria ID do Cliente 1560 225
2080 Carga da Lista de Clientes PF Insere cidade_id 1 3
2080 Carga da Lista de Clientes PF Limpa fluxo 0 0
2080 Carga da Lista de Clientes PF Cria índice do endereço 276 125
2080 Carga da Lista de Clientes PF Gerar linhas 0 2444
2080 Carga da Lista de Clientes PF Cria índices de nome 147 110
2080 Carga da Lista de Clientes PF String operations 3 1
2080 Carga da Lista de Clientes PF Absoluto de rnd_cpf 110 3
2080 Carga da Lista de Clientes PF Grava tabela 0 0
2080 Carga da Lista de Clientes PF Gera strings aleatórias 1778 5755
2080 Carga da Lista de Clientes PF Cria CEP, Telefone e Fax 0 0

E aí, consegue dizer se algum destes passos é um gargalo? Nem eu. Vamos melhorar nossa consulta: vamos agrupar por passo, remover o nome da transformação e lote da execução, já que ambos são previamente conhecidos (estão no filtro.) Fica assim:

SELECT
  stepname,
  sum(input_buffer_rows) as buffer_entrada,
  sum(output_buffer_rows) as buffer_saida
FROM transformation_performance
WHERE
  id_batch = 2080 AND
  transname = 'Carga da Lista de Clientes PF'
GROUP BY
  stepname
ORDER BY
  stepname

Resultado:

stepname buffer_entrada buffer_saida
Absoluto de rnd_cpf 4289 2770
Acerta tamanho das strings 10117 10100
Cria as partes de CEP, Telefone e Fax 100 10098
Cria CEP, Telefone e Fax 10101 20099
Cria ID do Cliente 21021 11892
Cria índice do endereço 15660 3458
Cria índices de nome 3483 4289
Gerar linhas 0 21902
Gera strings aleatórias 11889 15658
Grava tabela 20281 0
Insere cidade_id 202 259
Lê lista de enderecos 0 0
Lê nomes 0 0
Lê sobrenomes 0 61
Limpa fluxo 20099 20281
Muda rnd_telefone/fax para string 125 100
Seleciona endereço 258 714
Seleciona nome 714 100
Seleciona sobrenome 161 125
String operations 2770 202

Já dá para dizer se alguém é gargalo? Não! Veja, buffer de entrada e buffer de saída são métricas não-aditivas: somá-las ao longo do tempo não dá nenhuma informação sobre o processo. Nem somando-as ao longo dos passos, ou das transformações, nada! No máximo, como métricas não-aditivas, talvez uma média ao longo do tempo possa dar alguma idéia do que está acontecendo.

Mesmo assim, a média não ajudaria. Lembra-se que o monitoramento de gargalo do Spoon ocorre em tempo real? E que os gargalos podem pular de um passo para outro? Só conseguimos identificar um gargalo olhando o comportamento dele ao longo do tempo, momento a momento.

Incluíndo o tempo na consulta, temos:

SELECT
  stepname,
  logdate,
  sum(input_buffer_rows) as buffer_entrada,
  sum(output_buffer_rows) as buffer_saida
FROM transformation_performance
WHERE
  id_batch = 2080 AND
  transname = 'Carga da Lista de Clientes PF'
GROUP BY
  stepname,
  logdate
ORDER BY
  stepname

Vai nos dar a seguinte saída:

stepname logdate buffer_entrada buffer_saida
Absoluto de rnd_cpf 2016-02-21 16:34:41 110 3
Absoluto de rnd_cpf 2016-02-21 16:34:41 110 3
Absoluto de rnd_cpf 2016-02-21 16:34:42 87 100
Absoluto de rnd_cpf 2016-02-21 16:34:43 4092 2667
Absoluto de rnd_cpf 2016-02-21 16:34:44 0 0
Absoluto de rnd_cpf 2016-02-21 16:34:45 0 0
Absoluto de rnd_cpf 2016-02-21 16:34:46 0 0
Absoluto de rnd_cpf 2016-02-21 16:34:46 0 0
Acerta tamanho das strings 2016-02-21 16:34:41 0 0
Acerta tamanho das strings 2016-02-21 16:34:42 0 0
Acerta tamanho das strings 2016-02-21 16:34:43 120 100
Acerta tamanho das strings 2016-02-21 16:34:44 9997 10000
Acerta tamanho das strings 2016-02-21 16:34:45 0 0
Acerta tamanho das strings 2016-02-21 16:34:46 0 0
Acerta tamanho das strings 2016-02-21 16:34:46 0 0
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:41 0 0
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:42 0 0
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:43 100 101
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:44 0 9997
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:45 0 0
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:46 0 0
Cria as partes de CEP, Telefone e Fax 2016-02-21 16:34:46 0 0
Cria CEP, Telefone e Fax 2016-02-21 16:34:41 0 0
Cria CEP, Telefone e Fax 2016-02-21 16:34:42 0 0
Cria CEP, Telefone e Fax 2016-02-21 16:34:43 101 100
Cria CEP, Telefone e Fax 2016-02-21 16:34:44 10000 10000
Cria CEP, Telefone e Fax 2016-02-21 16:34:45 0 9999
Cria CEP, Telefone e Fax 2016-02-21 16:34:46 0 0

Agora podemos dizer, se em algum instante, um passo se comportou como um gargalo. Claro que examinar os dados assim é uma bobagem – podemos montar um gráfico com isso.

Relatório de Análise de Fluxos

Juntando essa consulta com os relatórios do primeiro post, montamos um relatório de análise de fluxo de transformações:

Relatório de análise de fluxo em transformações.
Relatório de análise de fluxo em transformações.

Esse relatório traça a velocidade daquele passo em linhas por segundo no gráfico de cima, e o volume de linhas presentes nos buffers, no gráfico de baixo, tudo instante a instante. O que vemos é que esse passo possui uma vazão boa, até, de 20.000 l/s, e que ele nunca esteve em condição de gargalo. Muito pelo contrário: no instante 5 ele teve o seu buffer de saída completamente cheio, sugerindo que o passo seguinte poderia ser um gargalo.

Eis o trecho da transformação que estamos analisando:

Trecho final da transformação de carga de clientes PF da Beltrano S/A.
Trecho final da transformação de carga de clientes PF da Beltrano S/A.

Os passos seguintes são um Select Values e um Table Output. Eis os buffers do Select Values:

Buffers do Select Values.
Buffers do Select Values.

E os do Table Output:

Buffers do Table Output.
Buffers do Table Output.

A-há! Veja ali, do momento 3 ao momento 6, como o buffer de entrada (a linha vermelha) sobe até atingir 10.000 linhas, enquanto o buffer de saída permanece em zero! Esse passo é um gargalo! Ele ficou com o buffer de entrada cheio, que fez com que as linhas “transbordassem” para o passo anterior, o Select Values. Tanto esse Select Values não é um gargalo que os dois buffers sobem e descem juntos. Mais ainda: foi justamente entre os momentos 3 e 6 (comuns a todos os passos, aliás, pois o log de performance captura todo mundo junto) que o buffer de saída do passo Cria CEP, Telefone e Fax saturou, isto é, atingiu seu limite de 10.000 linhas, e começou a se refletir no buffer de entrada, mesmo que por apenas um segundo (cada momento equivale a um segundo nesta escala.)

Conclusão

A partir da consulta mostrada podemos criar um relatório que exibe o estado dos buffers de cada passo momento a momento. Usando a transformação como guia, podemos analisar cada um dos passos em busca do sintoma de restrição de fluxo.

Essa não é a melhor análise, já que nos obriga a olhar um por um. Como você faria essa análise automaticamente? Como deixar para o Report Designer detectar os gargalos de uma transformação?

E apenas para fechar o problema encontrado neste exemplo: um gargalo em um passo que grava dados no banco significa que a rede e o banco é que são os gargalos. Dependendo da influência da rede e do banco na força da restrição, podemos levar o processamento para mais perto (reduzindo o custo da rede) ou melhorar o banco com, por exemplo, discos mais rápidos.

Na próxima semana terminaremos a série com um relatório de genealogia de um processo de ETL.

Até lá!


Novo Lançamento!

Sexta-feira, 11 de março de 2016, será o lançamento do meu novo livro, Autopublicação na Prática. Não deixe de passar por aqui, porque – como sempre – ele será lançado por R$ 0,00!

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