Programas de escrita é divertido, mas torná-los rápidos pode ser uma dor. Os programas Python não são exceção a isso, mas a cadeia de ferramentas básicas de criação de perfil não é tão complicada de usar. Aqui, eu gostaria de lhe mostrar como você pode rapidamente fazer um perfil e analisar o seu código Python para encontrar que parte do código você deve otimizar.
Profiling a Python program está fazendo uma análise dinâmica que mede o tempo de execução do programa e tudo o que o compõe. Isso significa medir o tempo gasto em cada uma de suas funções. Isto lhe dará dados sobre onde seu programa está gastando tempo, e que área pode valer a pena otimizar.
É um exercício muito interessante. Muitas pessoas focam em otimizações locais, como determinar, por exemplo, qual das funções Python range ou xrange vai ser mais rápido. Acontece que saber qual delas é mais rápida pode nunca ser um problema em seu programa, e que o tempo ganho por uma das funções acima pode não valer o tempo que você gasta pesquisando isso, ou discutindo sobre isso com seu colega.
Tentar otimizar cegamente um programa sem medir onde ele está realmente gastando seu tempo é um exercício inútil. Seguir apenas as suas entranhas nem sempre é suficiente.
Existem muitos tipos de perfis, pois há muitas coisas que você pode medir. Neste exercício, vamos focar no perfil de utilização da CPU, ou seja, o tempo gasto por cada função executando instruções. Obviamente, poderíamos fazer muito mais tipos de criação de perfis e otimizações, tais como criação de perfis de memória que mediriam a memória utilizada por cada pedaço de código – algo que eu falo no The Hacker’s Guide to Python.
cProfile
Desde Python 2.5, Python fornece um módulo em C chamado cProfile que tem uma sobrecarga razoável e oferece um conjunto de recursos suficientemente bom. O uso básico vai até:
Pois você também pode executar um script com ele, que acaba sendo útil:
Isso imprime todas as funções chamadas, com o tempo gasto em cada uma e o número de vezes que elas foram chamadas.
Visualização avançada com KCacheGrind
Embora seja útil, o formato de saída é muito básico e não facilita a obtenção de conhecimento para programas completos. Para uma visualização mais avançada, eu aproveito o KCacheGrind. Se você fez alguma programação em C e perfilamento nestes últimos anos, você pode tê-lo usado, já que ele foi projetado principalmente como front-end para o Valgrind gerado por call-graphs.
A fim de usar, você precisa gerar um arquivo de resultados cProfile, então converta-o para o formato KCacheGrind. Para fazer isso, eu uso pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofE a janela KCacheGrind aparece magicamente!
Caso de criação: Carbonara optimization
Estava curioso sobre as performances de Carbonara, a pequena biblioteca de timeseries que escrevi para o Gnocchi. Decidi fazer alguns perfis básicos para ver se havia alguma otimização óbvia para fazer.
Para fazer o perfil de um programa, você precisa executá-lo. Mas executar o programa inteiro no modo de criação de perfil pode gerar muitos dados que você não se importa, e adiciona ruído ao que você está tentando entender. Como o Gnocchi tem milhares de testes unitários e alguns para a própria Carbonara, decidi traçar o perfil do código utilizado por esses testes unitários, pois é um bom reflexo dos recursos básicos da biblioteca.
Note que essa é uma boa estratégia para um curioso e ingênuo perfil de primeira passagem.
Não há como ter certeza de que os hotspots que você verá nos testes unitários são os hotspots reais que você encontrará na produção. Portanto, um perfil em condições e com um cenário que imita o que é visto na produção é muitas vezes uma necessidade se você precisa empurrar a otimização do seu programa e quer alcançar ganhos perceptíveis e valiosos.
Ativei o cProfile usando o método descrito acima, criando um objeto cProfile.Profile em torno dos meus testes (na verdade comecei a implementar isso em testtools). Eu então executei o KCacheGrind como descrito acima. Usando KCacheGrind, eu gerei as seguintes figuras.
O teste que eu fiz aqui chama-se test_fetch e é bastante fácil de entender: ele coloca os dados em um objeto timeserie, e então vai buscar o resultado agregado. A lista acima mostra que 88 % dos ticks são gastos em set_values (44 ticks acima de 50). Esta função é usada para inserir valores no timeserie, não para ir buscar os valores. Isso significa que é muito lento inserir dados, e muito rápido recuperá-los.
Ler o resto da lista indica que várias funções compartilham o resto dos ticks, update, _first_block_timestamp, _truncate, _resample, etc. Algumas das funções da lista não fazem parte da Carbonara, por isso não vale a pena procurar optimizá-las. A única coisa que pode ser otimizada é, às vezes, o número de vezes que elas são chamadas.
O gráfico de chamadas me dá um pouco mais de percepção sobre o que está acontecendo aqui. Usando meu conhecimento sobre como Carbonara funciona, eu não acho que toda a pilha à esquerda para _first_block_timestamp faça muito sentido. Esta função deve encontrar o primeiro timestamp para um agregado, por exemplo, com um timestamp de 13:34:45 e um período de 5 minutos, a função deve retornar 13:30:00. A forma como funciona atualmente é chamando a função resample de Pandas em um timeerie com apenas um elemento, mas isso parece ser muito lento. De fato, atualmente esta função representa 25% do tempo gasto por set_values (11 ticks em 44).
Felizmente, eu recentemente adicionei uma pequena função chamada _round_timestamp que faz exatamente o que _first_block_timestamp precisa sem chamar nenhuma função de Pandas, então não resample. Então acabei reescrevendo essa função desta forma:
E depois voltei a executar o mesmo teste para comparar a saída do cProfile.
A lista de funções parece bastante diferente desta vez. O número de tempo gasto por set_values caiu de 88 % para 71 %.
A pilha de chamadas para set_values mostra isso muito bem: não podemos nem mesmo ver a função _first_block_timestamp pois ela é tão rápida que desapareceu totalmente da tela. Agora está sendo considerada insignificante pelo profiler.
Então nós apenas aceleramos todo o processo de inserção de valores em Carbonara por uns agradáveis 25 % em poucos minutos. Nada mal para uma primeira passagem ingênua, certo?
Se você quiser saber mais, escrevi um capítulo inteiro sobre otimização de código em Scaling Python. Olha só!