Programma’s schrijven is leuk, maar ze snel maken kan lastig zijn. Python programma’s zijn daarop geen uitzondering, maar de basis profiling toolchain is eigenlijk niet zo ingewikkeld om te gebruiken. Hier wil ik je laten zien hoe je snel je Python code kunt profilen en analyseren om uit te vinden welk deel van de code je zou moeten optimaliseren.
Profileren van een Python programma is het doen van een dynamische analyse die de uitvoeringstijd meet van het programma en alles waaruit het is opgebouwd. Dat betekent dat de tijd wordt gemeten die in elk van de functies wordt doorgebracht. Dit geeft je gegevens over waar je programma tijd aan besteedt, en welk gebied het waard zou kunnen zijn om te optimaliseren.
Het is een zeer interessante oefening. Veel mensen richten zich op lokale optimalisaties, zoals bijvoorbeeld bepalen welke van de Python functies range of xrange sneller zal zijn. Het blijkt dat weten welke sneller is misschien nooit een probleem is in uw programma, en dat de tijd die u wint met een van de bovenstaande functies misschien niet de tijd waard is die u besteedt aan het onderzoeken ervan, of aan het discussiëren erover met uw collega.
Proberen om een programma blindelings te optimaliseren zonder te meten waar het zijn tijd aan besteedt, is een nutteloze oefening. Het volgen van je gevoel alleen is niet altijd voldoende.
Er zijn vele soorten profiling, zoals er vele dingen zijn die je kunt meten. In deze oefening zullen we ons richten op CPU-gebruik profilering, dat wil zeggen de tijd die elke functie besteedt aan het uitvoeren van instructies. Uiteraard zouden we veel meer soorten profiling en optimalisaties kunnen doen, zoals geheugenprofilering die het geheugengebruik van elk stuk code zou meten – iets waar ik over praat in The Hacker’s Guide to Python.
cProfile
Sinds Python 2.5, biedt Python een C-module genaamd cProfile die een redelijke overhead heeft en een goed genoeg functieset biedt. Het basisgebruik komt neer op:
Hoewel je er ook een script mee kunt draaien, wat handig blijkt te zijn:
Dit drukt alle aangeroepen functies af, met de tijd die in elk is gestoken en het aantal keren dat ze zijn aangeroepen.
Geavanceerde visualisatie met KCacheGrind
Hoewel het nuttig is, is het uitvoerformaat erg basaal en maakt het niet gemakkelijk om kennis te pakken voor complete programma’s. Voor meer geavanceerde visualisatie, maak ik gebruik van KCacheGrind. Als je de afgelopen jaren in C hebt geprogrammeerd en geprofileerd, heb je het wellicht gebruikt, omdat het primair is ontworpen als front-end voor door Valgrind gegenereerde call-graphs.
Om het te kunnen gebruiken, moet je een cProfile resultaatbestand genereren, en het vervolgens converteren naar KCacheGrind formaat. Om dat te doen, gebruik ik pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofEn het KCacheGrind venster verschijnt op magische wijze!
Concrete zaak: Carbonara optimalisatie
Ik was nieuwsgierig naar de prestaties van Carbonara, de kleine timeseries library die ik voor Gnocchi heb geschreven. Ik besloot wat basis profiling te doen om te zien of er iets voor de hand lag om te optimaliseren.
Om een programma te profilen, moet je het draaien. Maar het hele programma in profiling mode draaien kan een hoop data genereren waar je niets om geeft, en voegt ruis toe aan wat je probeert te begrijpen. Omdat Gnocchi duizenden unit tests heeft en een paar voor Carbonara zelf, heb ik besloten om de code die door deze unit tests wordt gebruikt te profilen, omdat het een goede afspiegeling is van de basiseigenschappen van de library.
Noteer op dat dit een goede strategie is voor een nieuwsgierige en naïeve first-pass profiling.
Er is geen manier dat je er zeker van kunt zijn dat de hotspots die je in de unit tests ziet, ook de werkelijke hotspots zijn die je in productie zult tegenkomen. Daarom is een profilering in omstandigheden en met een scenario dat nabootst wat er in productie wordt gezien vaak een noodzaak als je je programma optimalisatie verder moet duwen en waarneembare en waardevolle winst wilt behalen.
Ik activeerde cProfile met behulp van de hierboven beschreven methode, het creëren van een cProfile.Profile object rond mijn tests (ik ben eigenlijk begonnen om dat in testtools te implementeren). Vervolgens heb ik KCacheGrind gedraaid zoals hierboven beschreven. Met behulp van KCacheGrind heb ik de volgende cijfers gegenereerd.
De test die ik hier heb geprofileerd heet test_fetch en is vrij eenvoudig te begrijpen: het stopt gegevens in een timeserie-object, en haalt vervolgens het geaggregeerde resultaat op. De bovenstaande lijst laat zien dat 88 % van de ticks wordt gespendeerd in set_values (44 ticks boven de 50). Deze functie wordt gebruikt om waarden in te voegen in de timeserie, niet om de waarden op te halen. Dat betekent dat het echt langzaam is om gegevens in te voegen, en vrij snel om ze daadwerkelijk op te halen.
Bij het lezen van de rest van de lijst blijkt dat verschillende functies de rest van de tikken delen, update, _first_block_timestamp, _truncate, _resample, enz. Sommige van de functies in de lijst maken geen deel uit van Carbonara, dus het heeft geen zin om ze te optimaliseren. Het enige dat kan worden geoptimaliseerd is, soms, het aantal keren dat ze worden aangeroepen.
De aanroepgrafiek geeft me wat meer inzicht in wat hier aan de hand is. Gebruikmakend van mijn kennis over hoe Carbonara werkt, denk ik niet dat de hele stack links voor _first_block_timestamp veel zin heeft. Deze functie wordt verondersteld de eerste tijdstempel voor een aggregaat te vinden, bijv. met een tijdstempel van 13:34:45 en een periode van 5 minuten, zou de functie 13:30:00 moeten teruggeven. De manier waarop het momenteel werkt is door de resample functie van Pandas aan te roepen op een timeserie met slechts één element, maar dat lijkt erg traag te zijn. Sterker nog, op dit moment vertegenwoordigt deze functie 25% van de tijd die set_values besteedt (11 tikken op 44).
Gelukkig genoeg heb ik onlangs een kleine functie toegevoegd genaamd _round_timestamp die precies doet wat _first_block_timestamp nodig heeft zonder een Pandas functie aan te roepen, dus geen resample. Dus heb ik die functie uiteindelijk op deze manier herschreven:
En toen heb ik precies dezelfde test opnieuw uitgevoerd om de uitvoer van cProfile te vergelijken.
De lijst met functies lijkt deze keer heel anders. De door set_values gebruikte tijd is gedaald van 88 % naar 71 %.
De aanroep-stack voor set_values laat dat goed zien: we kunnen de functie _first_block_timestamp niet eens meer zien, omdat die zo snel is dat hij helemaal van het scherm is verdwenen. Het wordt nu als onbelangrijk beschouwd door de profiler.
Dus we versnellen gewoon het hele invoegproces van waarden in Carbonara met een mooie 25 % in een paar minuten. Niet zo slecht voor een eerste naïeve pass, toch?
Als je meer wilt weten, ik heb een heel hoofdstuk geschreven over het optimaliseren van code in Scaling Python. Kijk maar eens!