Além do cProfile: Escolhendo a ferramenta certa para otimização de performance

Note: Este artigo é baseado em uma palestra que eu dei no PyGotham 2019. Você pode assistir o vídeo aqui.

Seu programa Python é muito lento. Talvez sua aplicação web não consiga acompanhar, ou certas consultas estejam demorando muito tempo. Talvez você tenha um programa em lote que leva horas ou até dias para ser executado.

Como você acelera?

O processo básico que você provavelmente irá seguir é:

Escolha a ferramenta certa para medir a velocidade.
Utilize a ferramenta para descobrir o gargalo de gargalo.
Fixar o gargalo.

Este artigo irá focar o primeiro passo: escolher a ferramenta certa. E em particular, irá cobrir:

cProfile: A biblioteca padrão Python profiler deterministic.
Pyinstrument: Um profiler de amostragem.
Eliot: Uma biblioteca de registo.

Não vou entrar em grandes detalhes sobre como usar estas ferramentas, porque o objectivo é ajudá-lo a escolher a correcta. Mas vou explicar o que estas ferramentas fazem, e quando e porque você escolheria uma em vez da outra.

cProfile: Um profiler determinístico

O cProfile profiler é embutido no Python, então você provavelmente já ouviu falar dele, e pode ser a ferramenta padrão que você usa. Ele funciona rastreando cada chamada de função em um programa. É por isso que é um profiler determinístico: se você executá-lo com as mesmas entradas ele dará a mesma saída.

Por padrão o cProfile mede a CPU do processo – quanto CPU o seu processo usou até agora.Você deve sempre perguntar o que seu profiler está medindo, porque medidas diferentes podem detectar problemas diferentes. Medir a CPU significa que você não pode detectar lentidão causada por outras causas, como esperar por uma resposta de uma consulta de banco de dados.

Embora o cProfile esteja sempre disponível em sua instalação do Python, ele também tem alguns problemas – e como você verá, na maioria das vezes você não quer usá-lo.

Usando cProfile

Usar cProfile é muito fácil.Se você tem um script que você normalmente executa diretamente assim:

$ python benchmark.py7855 messages/sec

Então você pode apenas prefixar python -m cProfile para executá-lo sob o profiler:

Existe também uma API de perfil Python, para que você possa perfilar funções particulares em um prompt de intérprete Python ou em um caderno Jupyter.

O formato de saída é uma tabela, o que não é ideal: cada linha é uma chamada de função que correu durante o período de tempo perfilado, mas você não sabe como essa chamada de função está relacionada com outras chamadas de função.Então se você tem uma função que pode ser alcançada a partir de múltiplos caminhos de código, pode ser difícil descobrir qual caminho de código foi responsável pela chamada da função lenta.

O que cProfile pode dizer a você

Se você olhar para a tabela acima, você pode ver que:

_output.py(__call__) foi chamada 50.000 vezes. É um número par porque este é um script de benchmark que executa o mesmo código em um loop 10.000 vezes. Se você não estava chamando uma função deliberadamente muitas vezes, isto pode ser útil para detectar um número alto de chamadas é útil para identificar loops internos ocupados.
_output.py(send) usou 0,618 segundos de CPU (incluindo o tempo de CPU das funções que chamou), e 0,045 segundos de CPU (não incluindo as funções que chamou).

Utilizando esta informação você pode detectar funções lentas, você pode otimizar – de qualquer forma, até a CPU.

Como funciona

cProfile mede cada chamada de função. Em particular, cada chamada de função na execução é envolvida assim:

start = process_time()try: f()finally: elapsed = process_time() - start

O profiler registra o tempo da CPU no início e no fim, e a diferença é alocada à conta dessa função.

Os problemas com o cProfile

Embora o cProfile esteja sempre disponível em qualquer instalação Python, ele também sofre de alguns problemas significativos.

Problema #1: Alta sobrecarga e resultados distorcidos

Como você pode imaginar, fazer trabalho extra para cada chamada de função tem alguns custos:

$ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

Note quanto mais lenta é a execução do cProfile.E o que é pior, a lentidão não é uniforme em todo o seu programa: porque está ligada ao número de chamadas de função, partes do seu código com mais chamadas de função serão mais lentas.

Problema #2: Demasiada informação

Se você se lembrar da saída do cProfile que vimos acima, ele inclui uma linha para cada função que foi chamada durante a execução do programa. A maioria dessas chamadas de função são irrelevantes para o nosso problema de desempenho: elas rodam rapidamente, e apenas uma ou duas vezes.

Então quando você está lendo a saída do cProfile, você está lidando com um monte de ruído extra mascarando o sinal.

Problema #3: Medida offline da performance

Bastante frequentemente o seu programa só será lento quando executado sob condições reais, com entradas reais. Talvez apenas consultas particulares dos utilizadores abrande a sua aplicação web, e você não sabe quais consultas.

But cProfile como vimos as lentidões fazem o seu programa um pouco, e assim você provavelmente não quer executá-lo em seu ambiente de produção.Assim, enquanto a lentidão só é reproduzível em produção, cProfile só o ajuda em seu ambiente de desenvolvimento.

Problema #4: O desempenho é medido apenas para funções

cProfile pode dizer-lhe “slowfunc() é lento”, onde ele calcula a média de todas as entradas para essa função.E isso é bom se a função for sempre lenta.

Mas às vezes você tem algum código algorítmico que só é lento para entradas específicas.É bem possível que:

slowfunc(100) seja rápido.
slowfunc(0) é lento.

cProfile não será capaz de dizer quais inputs causaram a lentidão, o que pode tornar mais difícil o diagnóstico do problema.

cProfile: Normalmente insuficiente

Como resultado destes problemas, cProfile não deve ser a sua ferramenta de desempenho de escolha. Em vez disso, a seguir vamos falar de duas alternativas:

Pyinstrument resolve os problemas #1 e #2.
Eliot resolve os problemas #3 e #4.

Pyinstrument: a sampling profiler

Pyinstrument resolve dois dos problemas que cobrimos acima:

Tem um overhead menor que o cProfile, e não distorce os resultados.
Filtra as chamadas de funções irrelevantes, assim há menos ruído.

Pyinstrument mede o tempo decorrido do relógio de parede, não o tempo da CPU, assim ele pode pegar lentidão causada por pedidos de rede, gravações em disco, contenção de travamento, e assim por diante.

Como você o usa

Usar o Pyinstrument é similar ao cProfile; basta adicionar um prefixo ao seu script:

$ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

Note que ele tem algum overhead, mas não tanto quanto o cProfile – e o overhead é uniforme.

Pyinstrument também tem uma API Python, então você pode usá-la para traçar o perfil de peças de código particulares em um interpretador interativo Python ou em um caderno Jupyter.

A saída

A saída do Pyinstrument é uma árvore de chamadas, medindo o tempo do relógio de parede:

Não parecido com o cProfile’s row-per-function, Pyinstrument dá-lhe uma árvore de chamadas de função, para que você possa ver o contexto da lentidão.

Como resultado, a saída do Pyinstrument é muito mais fácil de interpretar, e lhe dá uma compreensão muito melhor da estrutura de performance do seu programa do que a saída padrão do cProfile.

Como funciona (cat edition)

Imagine que você tem um cat.Você deseja saber como esse cat gasta seu tempo.

Vocês poderiam espiar o seu tempo todo, mas isso daria muito trabalho. Então ao invés disso decidem tirar amostras: a cada 5 minutos você enfia a cabeça na sala onde o gato está, e escreve o que ele está fazendo.

Por exemplo:

12:00: Dormindo 💤
12:05: Dormindo 💤
12:10: Comendo 🍲
12:15: Usando a caixa de lixo 💩
12:20: Dormindo 💤

12:25: Dormindo 💤
12:30: Dormindo 💤

> Poucos dias depois você pode resumir suas observações:

80%: Dormir 💤
10%: Comendo 🍲
9%: Usando a caixa de lixo 💩
1%: Olhando longamente através da janela em aves 🐦

Então quão preciso é este resumo? Na medida em que o seu objectivo é medir onde o gato passou a maior parte do seu tempo, é provavelmente preciso. E quanto mais frequentes as observações (==amostra) e quanto mais observações fizer, mais preciso é o resumo.

Se seu gato passa a maior parte do tempo dormindo, você esperaria que a maioria das observações amostradas mostrassem que ele está dormindo. E sim, você vai perder algumas atividades rápidas e raras – mas para fins de “o que o gato gastou a maior parte do seu tempo” essas atividades rápidas e raras são irrelevantes.

Como funciona (edição de software)

Tal como o nosso gato, Pyinstrument mostra o comportamento de um programa Python em intervalos: a cada 1ms ele verifica que função está sendo executada atualmente, ou seja:

Se uma função é cumulativamente lenta, ela aparecerá com frequência.
Se uma função é cumulativamente rápida, normalmente não a veremos de todo.

Isso significa que nosso resumo de desempenho tem menos ruído: funções que mal são usadas serão puladas na maioria das vezes.Mas em geral o resumo é bastante preciso em termos de como o programa gastou seu tempo, desde que tenhamos coletado amostras suficientes.

Eliot: Uma biblioteca de registro de dados

A ferramenta final que vamos cobrir em detalhes é Eliot, uma biblioteca de registro de dados que eu escrevi. Ela resolve os outros dois problemas que vimos com cProfile:

Logging pode ser usado em produção.
Logging pode gravar argumentos para funções.

Como você verá, Eliot fornece algumas capacidades únicas que o tornam melhor na gravação de desempenho do que as bibliotecas de registro normais.

Adicionando o logging ao código existente

Consulte o seguinte esboço de um programa:

Podemos pegar neste código e adicionar-lhe algum logging:

Especificamente, fazemos duas coisas:

Diga ao Eliot onde deve enviar as mensagens de log (neste caso, um ficheiro chamado “out”.log”).
Decoramos as funções com um decorador @log_call.Isto irá registrar o fato da função ter sido chamada, seus argumentos, e o valor de retorno (ou exceção elevada).

Eliot tem outras APIs mais finas, mas @log_call é suficiente para demonstrar os benefícios do log.

Eliot’s output

Após executarmos o programa, podemos olhar os logs usando uma ferramenta chamada eliot-tree:

Note que, um pouco como o Pyinstrument, estamos olhando para uma árvore de ações.Eu simplifiquei a saída um pouco – de forma original – para que ela coubesse em um slide que usei na versão talk deste artigo – mas mesmo em um artigo em prosa ela nos permite focar no aspecto da performance.

No Eliot, cada ação tem um início e um fim, e pode iniciar outras ações – daí a árvore resultante.Como sabemos quando cada ação logada começa e termina, também sabemos quanto tempo levou.

Neste caso, cada ação mapeia uma a uma com uma chamada de função. E há algumas diferenças da saída do Pyinstrument:

Em vez de combinar múltiplas chamadas de função, você vê cada chamada individual separadamente.
Você pode ver os argumentos e o resultado de retorno de cada chamada.
Você pode ver o tempo decorrido de cada ação.

Por exemplo, você pode ver que multiplysum() levou 10 segundos, mas a grande maioria do tempo foi gasto em multiply(), com as entradas de 3 e 4.Então você sabe imediatamente que para otimização de performance você quer focar em multiply(), e você tem algumas entradas iniciais (3 e 4) para brincar com.

As limitações do registro

O registro não é suficiente por si só como fonte de informações de performance.

Primeiro, você só obtém informações de código onde você adicionou explicitamente chamadas de registro.Um profiler pode correr em qualquer código arbitrário sem preparação prévia, mas com o registo tem de fazer algum trabalho prévio.

Se não adicionou código de registo, não obterá qualquer informação.Eliot torna isto um pouco melhor, uma vez que a estrutura de árvores de acções dá-lhe algum sentido onde o tempo foi gasto, mas ainda não é suficiente se o registo for muito esparso.

Segundo, você não pode adicionar logging em qualquer lugar porque isso irá retardar o seu programa.Logging não é barato – é mais caro que o cProfile.Então você precisa adicioná-lo judiciosamente, em pontos-chave onde irá maximizar a informação que ele dá sem impactar a performance.

Escolhendo as ferramentas certas

Então quando você deve usar cada ferramenta?

Adicionar sempre o log

Qualquer programa não trivial provavelmente precisa de algum log, nem que seja apenas para pegar bugs e erros.E se você já está adicionando o log, você pode ter o trabalho de registrar as informações que você precisa para fazer depuração de performance também.

Eliot torna mais fácil, uma vez que o registo de acções inerentemente dá-lhe tempo decorrido, mas pode com algum trabalho extra fazer isto com qualquer biblioteca de registo.

O registo pode ajudá-lo a detectar o local específico onde o seu programa é lento, e no mínimo algumas entradas que causam lentidão, mas muitas vezes é insuficiente.Então o próximo passo é usar um profiler, e em particular um profiler de amostragem como o Pyinstrument:

Tem pouca sobrecarga, e mais importante, não distorce os resultados.
Mede o tempo do relógio de parede, então não assume que a CPU é um gargalo.
Apenas produz as funções mais lentas, omitindo as funções rápidas irrelevantes.

Use cProfile se você precisar de uma métrica de custo personalizada

Se você precisar escrever um profiler personalizado, o cProfile permite que você conecte diferentes funções de custo, tornando-o uma ferramenta fácil para medir métricas mais incomuns.

Você pode medir:

Não-CPU, todo o tempo gasto à espera de eventos não-CPU.
O número de trocas de contexto voluntárias, ou seja, o número de chamadas de sistema que levam muito tempo.
Alocações de memória.
Mais amplamente, qualquer contador que suba.

TL;DR

Como um bom ponto de partida em ferramentas de otimização de desempenho, sugiro que você:

Entrar entradas e saídas de chaves, e o tempo decorrido de ações de chaves, usando Eliot ou alguma outra biblioteca de registro.
Utilize o Pyinstrument-ou outro profiler de amostragem como o seu profiler padrão.
Utilize o cProfile quando precisar de um profiler personalizado.