Localizar gargalos de execução com cProfile

Você já usou timeit para responder: quanto tempo este trecho demora? Agora a pergunta muda: em quais funções o tempo se concentra durante uma execução?

O cProfile faz um perfilamento determinístico: acompanha eventos de chamada e retorno de funções e agrega tempos e quantidades de chamadas por função. Ele ajuda a encontrar pontos para investigar; não prova, sozinho, qual alteração deve ser feita.

Um perfil descreve somente o caminho que foi executado, com aquele volume e aquela distribuição de dados. Se a carga não aciona o comportamento que preocupa você, o diagnóstico também não o mostrará.

Para este tutorial, usaremos um cenário determinístico: dados sintéticos locais alimentam funções encadeadas que processam textos e montam um relatório. Ele é uma carga didática, não o retrato de uma aplicação real.

A imagem mostra as etapas que serão incluídas em uma única execução observada.

Crie um arquivo chamado relatorio_textos.py em uma pasta local. Ele gera sempre os mesmos dados, processa cada texto e imprime um resumo. O if __name__ == "__main__" garante que a carga só rode quando o arquivo for executado diretamente.

Copie o script completo para um arquivo local com esse nome.

Ao executar esse script com o perfilador, não será observado apenas o laço de processamento. A geração dos textos, o processamento, a montagem do relatório e outras chamadas feitas durante a execução também entram no perfil. Por isso, a carga precisa representar a pergunta que você quer investigar.

O perfil é produzido enquanto o programa realiza seu trabalho normal.

No terminal, entre na pasta onde está relatorio_textos.py e execute o comando abaixo. A opção -o grava as estatísticas no arquivo local relatorio.prof.

Execute este comando na mesma pasta do script.

O arquivo criado com cProfile -o perfil.prof ... guarda dados do perfil em formato próprio. Para consultá-lo, crie um arquivo como consultar_perfil.py na mesma pasta e carregue-o com pstats.Stats.

Essa consulta apenas lê e apresenta dados já coletados: ela não executa novamente o script perfilado.

Salve este código como consultar_perfil.py e execute: python consultar_perfil.py

Cada linha se refere a uma função registrada no perfil.

Use sort_stats() antes de print_stats() para mudar a ordem exibida:

• "cumulative" ordena pela coluna cumtime.
• "time" ordena pela coluna tottime.

Por enquanto, trate essas colunas como duas formas de organizar a investigação. No próximo step, você verá exatamente o que cada tempo inclui.

print_stats(10) mostra apenas as 10 primeiras linhas na ordem atual. Você também pode passar um padrão textual para procurar funções pelo nome:

estatisticas.print_stats("normalizar")

Os filtros reduzem o que aparece no relatório. Eles não removem chamadas do arquivo perfil.prof nem mudam o trabalho que foi perfilado.

Execute as duas consultas sobre o mesmo arquivo de perfil.

No relatório do cProfile, tottime é o tempo gasto no corpo da própria função, sem contar o tempo das funções que ela chamou. Já cumtime é o tempo acumulado: inclui o corpo da função e o trabalho de todas as chamadas descendentes feitas durante ela.

Assim, uma função que apenas organiza etapas pode ter tottime pequeno e cumtime alto.

Observe como o tempo da coordenadora inclui as funções que ela aciona.

Além de tottime e cumtime, o relatório mostra ncalls: a quantidade de chamadas registradas para uma função.

A primeira coluna percall é tottime ÷ ncalls: o tempo próprio médio por chamada. A segunda é cumtime ÷ chamadas primitivas: o tempo acumulado médio por chamada primitiva.

Não escolha um alvo apenas pela maior contagem. Uma função pode ser cara em poucas execuções, ou barata individualmente e ainda assim consumir tempo relevante quando se repete milhares de vezes.

Compare custo por chamada, frequência e contribuição total.

Em uma função recursiva, ncalls pode aparecer como total/primitivas, por exemplo, 8/3.

• 8 é o total de chamadas registradas.
• 3 é a quantidade de chamadas primitivas: chamadas que não foram provocadas por outra chamada recursiva da mesma função.

Nessa linha, o primeiro percall usa 8 como denominador; o segundo usa 3. Essa separação evita tratar cada reentrada recursiva como se fosse um início independente do caminho.

Uma linha do perfil pode mostrar que normalizar_texto concentra tempo ou possui muitas chamadas. Isso ainda não responde quem decidiu chamá-la tantas vezes.

Use as relações de chamada para separar as perguntas:

• print_callers("normalizar_texto"): quem chama a função investigada?
• print_callees("processar_registro"): quais funções são chamadas por essa função?

No cenário do relatório, uma chamada repetida de normalizar_texto pode aparecer como custo nessa função, mas a frequência pode ser determinada pelo corpo de processar_registro.

Leia as relações como setas entre funções. Para investigar a repetição, comece na função que aparece no relatório e siga para o chamador.

Crie um arquivo chamado consultar_chamadas.py na mesma pasta de relatorio.prof, gerado anteriormente. O filtro pelo nome reduz a apresentação a relações relevantes; ele não altera a execução que foi perfilada.

Consulta as relações de chamada no perfil salvo.

O cProfile acompanha chamadas e retornos para distribuir o tempo entre funções da execução observada. Essa instrumentação também acrescenta trabalho à execução, portanto os tempos do relatório não são a medição final de desempenho do programa sem perfilador.

Use o perfil para perguntar onde investigar primeiro. Em especial, muitas chamadas muito curtas podem sofrer distorção relativa maior pela sobrecarga do acompanhamento.

Leia o relatório como um mapa da carga executada.

O cProfile agrega estatísticas por função. Uma linha de uma função não recebe uma linha própria no relatório: um cumtime alto identifica a função como candidata, mas não prova qual instrução interna consome o custo.

Uma chamada a recurso nativo pode aparecer como uma entrada no perfil, porém seu trabalho interno não é detalhado em novas funções Python. E um perfil de um processo não incorpora automaticamente o trabalho feito por outros processos.

O relatório mostra chamadas da execução perfilada, com detalhes até o nível de função Python.

Use o perfil para formular uma explicação que possa falhar em um teste. Uma hipótese útil tem quatro partes:

1. Evidência: o que apareceu no perfil, como muitas chamadas de uma função e seu contexto de chamada.
2. Explicação possível: por que esse trabalho ocorre.
3. Alteração proposta: uma mudança pequena e localizada.
4. Resultado esperado: uma observação que poderá ser conferida depois.

O perfil indica onde investigar; ele não prova sozinho que uma alteração melhorará o programa.

A previsão para o novo perfil é específica: normalizar_texto deve aparecer com menos chamadas relacionadas a cada registro processado. Não exija antecipadamente uma porcentagem fixa de redução no tempo.

Para decidir, preserve a versão de referência, faça uma mudança por vez, teste a equivalência dos resultados e compare a carga completa das duas versões com medições repetidas de timeit, sem cProfile ativo. Use entradas e condições equivalentes.

A hipótese anterior era evitar a normalização repetida do mesmo texto dentro de cada registro. A versão alterada calcula o valor uma vez e o reutiliza.

O código abaixo mantém a versão de referência para comparação, testa entradas relevantes e mede as duas versões com a mesma carga. Salve-o como relatorio_validado.py e execute-o no seu computador.

Execute este arquivo primeiro sem o perfilador para rodar as verificações e as medições.

Execute python relatorio_validado.py. As verificações precisam passar antes de qualquer decisão de desempenho.

Em seguida, gere um perfil para cada versão. Os tempos absolutos podem variar; compare principalmente a contagem de normalizar e consulte as mesmas funções nos dois arquivos.

Rode os comandos no diretório em que você salvou o arquivo.

Salve como consultar_perfis.py e execute python consultar_perfis.py. A seleção por nome limita a apresentação; ela não altera o que foi perfilado.