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 🙂
