Det er sjovt at skrive programmer, men det kan være besværligt at gøre dem hurtige. Python-programmer er ingen undtagelse fra dette, men den grundlæggende værktøjskæde til profilering er faktisk ikke så kompliceret at bruge. Her vil jeg gerne vise dig, hvordan du hurtigt kan profilere og analysere din Python-kode for at finde ud af, hvilken del af koden du bør optimere.
Profilering af et Python-program er at lave en dynamisk analyse, der måler eksekveringstiden for programmet og alt det, der udgør det. Det betyder, at man måler den tid, der bruges i hver af dets funktioner. Dette vil give dig data om, hvor dit program bruger tid, og hvilket område der kan være værd at optimere.
Det er en meget interessant øvelse. Mange mennesker fokuserer på lokale optimeringer, som f.eks. at bestemme, hvilken af Python-funktionerne range eller xrange der vil være hurtigere. Det viser sig, at det måske aldrig bliver et problem i dit program at vide, hvilken der er hurtigere, og at den tid, som en af de ovennævnte funktioner vinder, måske ikke er den tid værd, du bruger på at undersøge det eller diskutere det med din kollega.
Det er en nytteløs øvelse at forsøge at optimere et program blindt uden at måle, hvor det rent faktisk bruger sin tid. Det er ikke altid tilstrækkeligt at følge sin intuition alene.
Der findes mange typer af profilering, ligesom der er mange ting, man kan måle. I denne øvelse vil vi fokusere på profilering af CPU-udnyttelse, dvs. den tid, som hver funktion bruger på at udføre instruktioner. Vi kan naturligvis lave mange flere slags profilering og optimeringer, f.eks. hukommelsesprofilering, som vil måle den hukommelse, der bruges af hvert stykke kode – noget jeg taler om i The Hacker’s Guide to Python.
cProfile
Siden Python 2.5 har Python leveret et C-modul kaldet cProfile, som har et rimeligt overhead og tilbyder et godt nok funktionssæt. Den grundlæggende brug går ud på:
Du kan dog også køre et script med det, hvilket viser sig at være praktisk:
Dette udskriver alle de kaldte funktioner med tidsforbruget i hver enkelt og antallet af gange de er blevet kaldt.
Advanceret visualisering med KCacheGrind
Og selv om det er nyttigt, er outputformatet meget grundlæggende og gør det ikke nemt at få fat i viden om komplette programmer. For mere avanceret visualisering udnytter jeg KCacheGrind. Hvis du har lavet noget C programmering og profilering i de sidste år, har du måske brugt det, da det primært er designet som front-end for Valgrind genererede call-grafer.
For at kunne bruge det, skal du generere en cProfile resultatfil og derefter konvertere den til KCacheGrind format. For at gøre det bruger jeg pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofOg KCacheGrind-vinduet vises på magisk vis!
Konkret tilfælde: Carbonara-optimering
Jeg var nysgerrig på præstationerne i Carbonara, det lille tidsseriebibliotek, som jeg skrev til Gnocchi. Jeg besluttede mig for at lave noget grundlæggende profilering for at se, om der var nogen åbenlys optimering at foretage.
For at profilere et program skal man køre det. Men at køre hele programmet i profileringstilstand kan generere en masse data, som man er ligeglad med, og som tilføjer støj til det, man forsøger at forstå. Da Gnocchi har tusindvis af enhedstests og et par stykker for selve Carbonara, besluttede jeg at profilere den kode, der bruges af disse enhedstests, da det er en god afspejling af grundlæggende funktioner i biblioteket.
Bemærk, at dette er en god strategi for en nysgerrig og naiv first-pass profilering.
Der er ingen måde, hvorpå du kan sikre dig, at de hotspots, du vil se i enhedstests, er de faktiske hotspots, du vil støde på i produktionen. Derfor er en profilering i betingelser og med et scenarie, der efterligner det, der ses i produktionen, ofte en nødvendighed, hvis du skal presse din programoptimering yderligere og ønsker at opnå en mærkbar og værdifuld gevinst.
Jeg aktiverede cProfile ved hjælp af den ovenfor beskrevne metode og oprettede et cProfile.Profile-objekt omkring mine tests (jeg er faktisk begyndt at implementere det i testtools). Derefter kører jeg KCacheGrind som beskrevet ovenfor. Ved hjælp af KCacheGrind genererede jeg følgende tal:
Den test, jeg profilerede her, hedder test_fetch og er ret nem at forstå: Den lægger data i et timeserie-objekt og henter derefter det aggregerede resultat. Ovenstående liste viser, at 88 % af ticksene bruges i set_values (44 ticks over 50). Denne funktion bruges til at indsætte værdier i timeserieobjektet, ikke til at hente værdierne. Det betyder, at den er virkelig langsom til at indsætte data, og ret hurtig til faktisk at hente dem.
Læsning af resten af listen viser, at flere funktioner deler resten af tikkene, update, _first_block_timestamp, _truncate, _resample osv. Nogle af funktionerne på listen er ikke en del af Carbonara, så der er ingen grund til at søge at optimere dem. Det eneste, der kan optimeres, er nogle gange antallet af gange, de bliver kaldt.
Kaldegrafen giver mig lidt mere indsigt i, hvad der foregår her. Ved hjælp af min viden om, hvordan Carbonara fungerer, synes jeg ikke, at hele stakken til venstre for _first_block_timestamp giver meget mening. Denne funktion skal finde det første tidsstempel for et aggregat, f.eks. med et tidsstempel på 13:34:45 og en periode på 5 minutter, bør funktionen returnere 13:30:00. Den måde, det fungerer på i øjeblikket, er ved at kalde resample-funktionen fra Pandas på et timeserie med kun ét element, men det synes at være meget langsomt. Faktisk udgør denne funktion i øjeblikket 25 % af den tid, som set_values bruger (11 ticks på 44).
Uheldigvis har jeg for nylig tilføjet en lille funktion kaldet _round_timestamp, der gør præcis det, som _first_block_timestamp har brug for, at uden at kalde nogen Pandas-funktion, så ingen resample. Så jeg endte med at omskrive den funktion på denne måde:
Og så kørte jeg nøjagtig den samme test igen for at sammenligne resultatet af cProfile.
Listen over funktioner ser helt anderledes ud denne gang. Antallet af tidsforbrug brugt af set_values faldt fra 88 % til 71 %.
Kaldestakken for set_values viser det ret godt: Vi kan ikke engang se _first_block_timestamp-funktionen, da den er så hurtig, at den helt forsvandt fra skærmen. Den bliver nu betragtet som ubetydelig af profileren.
Så vi fremskynder bare hele indsættelsesprocessen af værdier i Carbonara med en pæn 25 % på et par minutter. Ikke så dårligt for et første naivt gennemløb, vel?
Hvis du vil vide mere, har jeg skrevet et helt kapitel om optimering af kode i Scaling Python. Tjek det ud!