Att skriva program är roligt, men att göra dem snabba kan vara jobbigt. Pythonprogram är inget undantag, men den grundläggande verktygskedjan för profilering är faktiskt inte så komplicerad att använda. Här vill jag visa dig hur du snabbt kan profilera och analysera din Pythonkod för att hitta vilken del av koden du bör optimera.
Profilering av ett Pythonprogram är att göra en dynamisk analys som mäter exekveringstiden för programmet och allt som ingår i det. Det innebär att man mäter den tid som spenderas i var och en av dess funktioner. Detta ger dig data om var ditt program spenderar tid och vilket område som kan vara värt att optimera.
Det är en mycket intressant övning. Många människor fokuserar på lokala optimeringar, som att bestämma t.ex. vilken av Pythonfunktionerna range eller xrange som kommer att vara snabbare. Det visar sig att det kanske aldrig blir aktuellt i ditt program att veta vilken som är snabbare, och att den tid som en av funktionerna ovan vinner kanske inte är värd den tid du lägger ner på att undersöka det, eller på att diskutera det med din kollega.
Att försöka optimera ett program blint utan att mäta var det faktiskt spenderar sin tid är en värdelös övning. Att enbart följa sin magkänsla är inte alltid tillräckligt.
Det finns många typer av profilering, eftersom det finns många saker man kan mäta. I den här övningen kommer vi att fokusera på profilering av CPU-utnyttjande, det vill säga den tid som varje funktion spenderar på att utföra instruktioner. Självklart kan vi göra många fler typer av profilering och optimeringar, till exempel minnesprofilering som skulle mäta det minne som används av varje kodstycke – något som jag talar om i The Hacker’s Guide to Python.
cProfile
Sedan Python 2.5 tillhandahåller Python en C-modul som heter cProfile som har en rimlig overhead och erbjuder en tillräckligt bra funktionsuppsättning. Den grundläggande användningen går ut på att:
Det går även att köra ett skript med den, vilket visar sig vara praktiskt:
Detta skriver ut alla funktioner som anropats, med den tid som spenderats i varje funktion och antalet gånger de anropats.
Avancerad visualisering med KCacheGrind
Som är användbar är utdataformatet mycket grundläggande och gör det inte lätt att ta till sig kunskap för kompletta program. För mer avancerad visualisering använder jag mig av KCacheGrind. Om du har gjort någon C-programmering och profilering de senaste åren kan du ha använt det eftersom det i första hand är utformat som front-end för Valgrind-genererade anropsgrafer.
För att kunna använda det måste du generera en cProfile-resultatfil och sedan konvertera den till KCacheGrind-formatet. För att göra det använder jag pyprof2calltree.
$ python -m cProfile -o myscript.cprof myscript.py$ pyprof2calltree -k -i myscript.cprofOch KCacheGrind-fönstret dyker magiskt upp!
Konkret fall: Carbonara-optimering
Jag var nyfiken på prestandan hos Carbonara, det lilla tidsseriebiblioteket som jag skrev för Gnocchi. Jag bestämde mig för att göra lite grundläggande profilering för att se om det fanns någon uppenbar optimering att göra.
För att profilera ett program måste man köra det. Men att köra hela programmet i profileringsläge kan generera en massa data som du inte bryr dig om, och som tillför brus till det du försöker förstå. Eftersom Gnocchi har tusentals enhetstester och några få för själva Carbonara, bestämde jag mig för att profilera den kod som används av dessa enhetstester, eftersom det är en bra återspegling av grundläggande funktioner i biblioteket.
Bemärk att detta är en bra strategi för en nyfiken och naiv förstagångsprofilering.
Det finns inget sätt för dig att försäkra dig om att de hotspots som du kommer att se i enhetstesterna är de faktiska hotspots du kommer att stöta på i produktionen. Därför är en profilering i förhållanden och med ett scenario som efterliknar det som ses i produktionen ofta en nödvändighet om du behöver driva din programoptimering vidare och vill uppnå en märkbar och värdefull vinst.
Jag aktiverade cProfile med hjälp av den metod som beskrivs ovan, genom att skapa ett cProfile.Profile-objekt runt mina tester (jag började faktiskt implementera det i testtools). Därefter kör jag KCacheGrind enligt beskrivningen ovan. Med hjälp av KCacheGrind genererade jag följande siffror:
Testet som jag profilerade här heter test_fetch och är ganska enkelt att förstå: det lägger data i ett timeserie-objekt och hämtar sedan det aggregerade resultatet. Ovanstående lista visar att 88 % av tickarna spenderas i set_values (44 tickar över 50). Den här funktionen används för att lägga in värden i timeserie, inte för att hämta värdena. Det innebär att den är riktigt långsam för att infoga data och ganska snabb för att faktiskt hämta dem.
Läsning av resten av listan visar att flera funktioner delar på resten av tickarna, update, _first_block_timestamp, _truncate, _resample osv. Vissa av funktionerna i listan är inte en del av Carbonara, så det är ingen idé att försöka optimera dem. Det enda som kan optimeras är, ibland, antalet gånger de anropas.
Anropningsdiagrammet ger mig lite mer insikt om vad som händer här. Med hjälp av min kunskap om hur Carbonara fungerar tror jag inte att hela stapeln till vänster för _first_block_timestamp är särskilt meningsfull. Den här funktionen ska hitta den första tidsstämpeln för ett aggregat, t.ex. med en tidsstämpel på 13:34:45 och en period på 5 minuter ska funktionen återge 13:30:00. Det sätt det fungerar på för närvarande är genom att kalla resample-funktionen från Pandas på en timeserie med endast ett element, men det verkar vara mycket långsamt. Faktum är att denna funktion för närvarande utgör 25 % av den tid som set_values spenderar (11 tickar på 44).
Tyvärr har jag nyligen lagt till en liten funktion som heter _round_timestamp som gör exakt det som _first_block_timestamp behöver som utan att anropa någon Pandas-funktion, så ingen resample. Så det slutade med att jag skrev om den funktionen på följande sätt:
Och sedan körde jag om exakt samma test för att jämföra resultatet från cProfile.
Listan över funktioner verkar vara helt annorlunda den här gången. Antalet tidsåtgång som används av set_values sjönk från 88 % till 71 %.
Kallningsstapeln för set_values visar detta ganska bra: vi kan inte ens se _first_block_timestamp-funktionen eftersom den är så snabb att den helt försvann från displayen. Den betraktas nu som obetydlig av profileraren.
Så vi har bara påskyndat hela insättningsprocessen av värden i Carbonara med en trevlig 25 % på några minuter. Inte så illa för ett första naivt pass, eller hur?
Om du vill veta mer har jag skrivit ett helt kapitel om optimering av kod i Scaling Python. Kolla in det!