Profiling python com cprofile

Durante o desenvolvimento do raycife+, a performance estava ficando impraticável, chegando a cerca de 3 a 4 minutos para uma cena simples de 100×100 pixels e 7 objetos no meu velho celeron. Seguindo as dicas desse site, rodei o cprofile e pude ver onde poderia ganhar tempo.

No arquivo principal do programa esse código que executa a função main com os argumentos fornecidos na string e salva o resultado num arquivo de log.

if __name__ == '__main__':
    import cProfile
    cProfile.run('main(["raycifeplus.py", "./samples/cornellroomsmall.sdl"])' filename='raycife.cprof')

Para ler o resultado do arquivo de saída:

from pstats import Stats
stats = Stats("raycife.cprof")
stats.sort_stats('time').print_stats()

Exemplo da saída:

Mon Apr 21 11:23:35 2008    raycife.cprof

37298787 function calls in 237.746 CPU seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
1  168.955  168.955  237.734  237.734 ./raycifeplus.py:71(render)
26660558   46.400    0.000   46.409    0.000 /home/lauro/dev/raytracer/raycifeplus/gameobjects/vector3.py:165(__iter__)
5723042    9.791    0.000    9.807    0.000 /home/lauro/dev/raytracer/raycifeplus/gameobjects/vector3.py:265(__sub__)
2422914    4.633    0.000    4.636    0.000 /home/lauro/dev/raytracer/raycifeplus/gameobjects/vector3.py:369(__rmul__)
2422914    4.114    0.000    4.125    0.000 /home/lauro/dev/raytracer/raycifeplus/gameobjects/vector3.py:224(__add__)
10000    2.927    0.000    4.841    0.000 ./raycifeplus.py:80(render_pixel)
1472    0.478    0.000    0.916    0.001 ./raycifeplus.py:99(trace_point)
841    0.129    0.000    0.299    0.000 /home/lauro/dev/raytracer/raycifeplus/objfile.py:30(intersect)
1    0.119    0.119    0.182    0.182 /home/lauro/dev/raytracer/raycifeplus/pnm.py:18(write)
10000    0.044    0.000    0.044    0.000 /home/lauro/dev/raytracer/raycifeplus/pnm.py:15(set_pixel)

Nesse caso, deu para ver que parte do tempo era perdido no módulo vector3, uma implementação de vetores em 3 dimensões usando python.

No próximo vou falar sobre uma tentativa rápida de implementar a mesma funcionalidade usando C++ e criando o binding usando o SIP.

Nota: O código acima ainda poderia ser refinado para receber argumentos na linha de comando mas como é apenas um teste rápido, pode ficar p/ depois uma flag “-p” para habilitar o profiling.

Nota2: Sim, eu sei que a otimização prematura é a raíz de todo mal mas nesse caso é um teste pontual que não vai mudar o algoritmo, além de poder conhecer novas tecnologias🙂


Um Comentário


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