Verder dan cProfile: Choosing the right tool for performance optimization

Note: Dit artikel is gebaseerd op een talk die ik heb gegeven op PyGotham 2019. Je kunt de video hier bekijken.

Jouw Python-programma is te traag.Misschien kan je webapplicatie het niet bijbenen, of duren bepaalde query’s erg lang.Misschien heb je een batchprogramma dat er uren of zelfs dagen over doet om te draaien.

Hoe maak je het sneller?

Het basisproces dat u waarschijnlijk zult volgen is:

1. Kies het juiste hulpmiddel om de snelheid te meten.
2. Gebruik het hulpmiddel om het knelpunt te achterhalen.
3. Verhelp het knelpunt.

Dit artikel zal zich richten op de eerste stap: het kiezen van het juiste gereedschap.En in het bijzonder, zal het behandelen:

• cProfile: De Python standaard bibliotheek deterministische profiler.
• Pyinstrument: Een sampling profiler.
• Eliot: Een logging library.

Ik zal niet in detail treden over hoe je deze tools moet gebruiken, omdat het doel is om je te helpen de juiste te kiezen. Maar ik zal uitleggen wat deze tools doen, en wanneer en waarom je de een boven de ander zou kiezen.

cProfile: Een deterministische profiler

De cProfile profiler is ingebouwd in Python, dus je hebt er waarschijnlijk van gehoord, en het kan de standaard tool zijn die je gebruikt.Het werkt door elke functie-aanroep in een programma te traceren.Daarom is het een deterministische profiler: als je het met dezelfde invoer uitvoert, zal het dezelfde uitvoer geven.

Door standaard meet cProfile proces CPU-hoeveel CPU je proces tot nu toe heeft gebruikt.Je moet altijd vragen wat je profiler meet, omdat verschillende metingen verschillende problemen kunnen detecteren.Het meten van CPU betekent dat je geen traagheid door andere oorzaken kunt detecteren, zoals het wachten op een antwoord van een database query.

Hoewel cProfile altijd beschikbaar is in je Python installatie, heeft het ook enkele problemen-en zoals je zult zien, wil je het meestal niet gebruiken.

Het gebruik van cProfile

Het gebruik van cProfile is vrij eenvoudig.Als je een script hebt dat je gewoonlijk direct uitvoert, zoals dit:

$ python benchmark.py7855 messages/sec

Dan kun je gewoon python -m cProfile voorvoegsel gebruiken om het onder de profiler uit te voeren:

Er is ook een Python profiling API, zodat je bepaalde functies kunt profileren in een Python interpreter prompt of een Jupyter notebook.

Het uitvoerformaat is een tabel, wat niet ideaal is: elke rij is een functie-aanroep die gedurende de geprofileerde tijdspanne is uitgevoerd, maar je weet niet hoe die functie-aanroep is gerelateerd aan andere functie-aanroepen.Dus als je een functie hebt die vanuit meerdere code paden kan worden bereikt, kan het moeilijk zijn om uit te vinden welk code pad verantwoordelijk was voor het aanroepen van de trage functie.

Wat cProfile je kan vertellen

Als je naar de tabel hierboven kijkt, zie je dat:

• _output.py(__call__) 50.000 keer werd aangeroepen. Het is een even getal omdat dit een benchmark script is dat dezelfde code in een lus 10.000 keer uitvoert.Als je niet opzettelijk een functie veelvuldig aanriep, kan dit nuttig zijn voor het spotten van een hoog aantal aanroepen is nuttig voor het identificeren van drukke inner loops.
• _output.py(send) gebruikte 0.618 CPU seconden (inclusief CPU tijd van functies die het aanriep), en 0.045 CPU seconden (niet inclusief functies die het aanriep).

Met deze informatie kun je trage functies opsporen die je kunt optimaliseren – traag wat CPU betreft, in ieder geval.

Hoe het werkt

cProfile meet elke functie-aanroep. In het bijzonder wordt elke functie-aanroep in de run als volgt verpakt:

start = process_time()try: f()finally: elapsed = process_time() - start

De profiler registreert CPU-tijd aan het begin en aan het eind, en het verschil wordt toegewezen aan de rekening van die functie.

De problemen met cProfile

Hoewel cProfile altijd beschikbaar is in elke Python installatie, lijdt het ook aan enkele belangrijke problemen.

Probleem #1: Hoge overhead en vervormde resultaten

Zoals u zich kunt voorstellen, heeft het extra werk voor elke functie-aanroep een aantal kosten:

$ python benchmark.py7855 messages/sec$ python -m cProfile benchmark.py5264 messages/sec... cProfile output ...

Merk op hoeveel langzamer de cProfile run is.En wat nog erger is, de vertraging is niet uniform over je hele programma: omdat het is gekoppeld aan het aantal functie-aanroepen, zullen delen van je code met meer functie-aanroepen meer worden vertraagd. Dus deze overhead kan de resultaten vertekenen.

Probleem #2: Te veel informatie

Als je je de cProfile uitvoer herinnert die we hierboven zagen, bevat het een rij voor elke functie die werd aangeroepen tijdens de programma-afloop.De meeste van die functie-aanroepen zijn irrelevant voor ons prestatieprobleem: ze worden snel uitgevoerd, en slechts een of twee keer.

Dus als je de cProfile uitvoer leest, heb je te maken met een hoop extra ruis die het signaal maskeert.

Probleem #3: Offline meting van de prestaties

Natuurlijk vaak zal uw programma alleen traag zijn wanneer het wordt uitgevoerd onder real-world omstandigheden, met real-world inputs.Misschien vertragen alleen bepaalde query’s van gebruikers uw webapplicatie, en u weet niet welke query’s.Misschien is uw batch-programma alleen traag met echte gegevens.

Maar cProfile zoals we zagen vertraagt je programma behoorlijk, en dus wil je het waarschijnlijk niet in je productie-omgeving draaien.Dus terwijl de traagheid alleen reproduceerbaar is in productie, helpt cProfile je alleen in je ontwikkelomgeving.

Probleem #4: Performance wordt alleen gemeten voor functies

cProfile kan je vertellen “slowfunc() is traag”, waarbij het het gemiddelde neemt van alle inputs naar die functie.En dat is prima als de functie altijd traag is.

Maar soms heb je wat algoritmische code die alleen traag is voor specifieke invoer.Het is heel goed mogelijk dat:

• slowfunc(100) snel is.
• slowfunc(0) is traag.

cProfile zal u niet kunnen vertellen welke invoer de traagheid veroorzaakt, wat het moeilijker kan maken om het probleem te diagnosticeren.

cProfile: Meestal onvoldoende

Als gevolg van deze problemen, zou cProfile niet uw performance tool van keuze moeten zijn.In plaats daarvan, zullen we het nu hebben over twee alternatieven:

• Pyinstrument lost de problemen #1 en #2 op.
• Eliot lost de problemen #3 en #4 op.

Pyinstrument: een sampling profiler

Pyinstrument lost twee van de problemen op die we hierboven hebben behandeld:

• Het heeft een lagere overhead dan cProfile, en het vervormt de resultaten niet.
• Het filtert irrelevante functie-aanroepen uit, dus er is minder ruis.

Pyinstrument meet de verstreken tijd van de muurklok, niet de CPU-tijd, dus het kan traagheid opvangen die wordt veroorzaakt door netwerkverzoeken, schijf-schrijfbewerkingen, lock-contention, enzovoort.

Hoe u het gebruikt

Het gebruik van Pyinstrument is vergelijkbaar met cProfile; voeg gewoon een voorvoegsel toe aan uw script:

$ python benchmark.py7561 messages/sec$ python -m pyinstrument benchmark.py6760 messages/sec... pyinstrument output ...

Merk op dat het wat overhead heeft, maar niet zoveel als cProfile-en de overhead is uniform.

Pyinstrument heeft ook een Python-API, zodat je het kunt gebruiken om bepaalde stukken code te profileren in een interactieve Python-interpreter of een Jupyter-notebook.

De output

Pyinstrument’s output is een boom van aanroepen, het meten van wandklok tijd:

In tegenstelling tot cProfile’s rij-per-functie, geeft Pyinstrument je een boom van functie-aanroepen, zodat je de context van de traagheid kunt zien. Een functie kan meerdere keren voorkomen als de traagheid wordt veroorzaakt door meerdere code paden.

Hierdoor is de output van Pyinstrument veel eenvoudiger te interpreteren, en geeft u een veel beter inzicht in de prestatiestructuur van uw programma dan de standaard output van cProfile.

Hoe het werkt (kat editie)

Stel u voor dat u een kat hebt. U wilt weten hoe die kat zijn tijd doorbrengt.

U zou haar elk moment kunnen bespioneren, maar dat zou veel werk zijn.Dus in plaats daarvan besluit u steekproeven te nemen: elke 5 minuten steekt u uw hoofd in de kamer waar de kat is, en schrijft u op wat hij doet.

Bijvoorbeeld:

• 12:00: Slapen 💤
• 12:05: Slapen 💤
• 12:10: Eten 🍲
• 12:15: De kattenbak gebruiken 💩
• 12:20: Slapen 💤
• 12:20: Slapen 💤
• 12:25: Slapend 💤
• 12:30: Slapend 💤

Een paar dagen later kunt u uw waarnemingen samenvatten:

• 80%: Slapen 💤
• 10%: Eten 🍲
• 9%: De kattenbak gebruiken 💩
• 1%: Verlangend door het raam naar vogels staren 🐦

Dus hoe nauwkeurig is deze samenvatting? Voor zover je doel is te meten waar de kat de meeste tijd doorbracht, is het waarschijnlijk nauwkeurig.En hoe frequenter de waarnemingen (==steekproeven) en hoe meer waarnemingen je doet, hoe nauwkeuriger de samenvatting.

Als je kat het grootste deel van zijn tijd slapend doorbrengt, zou je verwachten dat uit de meeste waarnemingen blijkt dat hij slaapt.En ja, je zult een aantal snelle en zeldzame activiteiten missen-maar voor het doel van “waar heeft de kat het grootste deel van zijn tijd aan besteed” zijn die snelle en zeldzame activiteiten niet relevant.

Hoe het werkt (software editie)

Net als onze kat, onderzoekt Pyinstrument het gedrag van een Python programma met tussenpozen: elke 1 ms controleert het welke functie op dat moment draait. Dat betekent:

• Als een functie cumulatief traag is, zal het vaak opduiken.
• Als een functie cumulatief snel is, zien we die meestal helemaal niet.

Dat betekent dat onze prestatie-overzicht minder ruis heeft: functies die nauwelijks worden gebruikt, worden meestal overgeslagen.Maar over het algemeen is het overzicht vrij nauwkeurig in termen van hoe het programma zijn tijd besteedde, zolang we maar genoeg monsters namen.

Eliot: Een logging bibliotheek

Het laatste gereedschap dat we in detail zullen behandelen is Eliot, een logging bibliotheek die ik schreef.Het lost de andere twee problemen op die we zagen met cProfile:

• Logging kan in productie gebruikt worden.
• Logging kan argumenten voor functies vastleggen.

Zoals je zult zien, biedt Eliot enkele unieke mogelijkheden die het beter maken in het vastleggen van prestaties dan normale logging bibliotheken.Dat gezegd hebbende, met wat extra werk kun je dezelfde voordelen ook uit andere logging bibliotheken halen.

Logging toevoegen aan bestaande code

Neem de volgende schets van een programma:

We kunnen deze code nemen en er logging aan toevoegen:

In het bijzonder doen we twee dingen:

1. Tel Eliot waar hij de logberichten moet uitvoeren (in dit geval een bestand met de naam “out.log”).
2. We versieren de functies met een @log_call decorator.Deze logt het feit dat de functie is aangeroepen, de argumenten, en de retourwaarde (of de opgeroepen uitzondering).

Eliot heeft andere, meer verfijnde API’s, maar @log_call volstaat voor het demonstreren van de voordelen van logging.

Eliot’s uitvoer

Als we het programma hebben gedraaid, kunnen we de logs bekijken met een tool genaamd eliot-tree:

Merk op dat, een beetje zoals bij Pyinstrument, we kijken naar een boom van acties.Ik heb de uitvoer een beetje vereenvoudigd – oorspronkelijk zodat het op een dia paste die ik in de voordrachtsversie van dit artikel heb gebruikt – maar zelfs in een proza-artikel kunnen we ons zo concentreren op het performance-aspect.

In Eliot heeft elke actie een begin en een eind, en kan andere acties starten – vandaar de resulterende boom.Omdat we weten wanneer elke gelogde actie begint en eindigt, weten we ook hoe lang het duurde.

In dit geval is elke actie een-op-een gekoppeld aan een functie-aanroep.En er zijn enkele verschillen met de uitvoer van Pyinstrument:

1. In plaats van meerdere functie-aanroepen te combineren, zie je elke individuele aanroep afzonderlijk.
2. U kunt de argumenten en het resultaat van elke aanroep zien.
3. U kunt de verstreken tijd van elke actie zien.

U kunt bijvoorbeeld zien dat multiplysum() 10 seconden duurde, maar het overgrote deel van de tijd werd doorgebracht in multiply(), met de invoer van 3 en 4.Je weet dus meteen dat je je voor prestatie-optimalisatie wilt richten op multiply(), en je hebt een aantal start-inputs (3 en 4) om mee te spelen.

De beperkingen van logging

Logging is op zichzelf niet voldoende als bron van prestatie-informatie.

Vooreerst krijg je alleen informatie van code waar je expliciet logging-aanroepen aan hebt toegevoegd.Een profiler kan op elk willekeurig stuk code draaien zonder voorbereiding vooraf, maar met logging moet je van tevoren wat werk doen.

Als je geen logging code hebt toegevoegd, krijg je geen informatie.Eliot maakt dit iets beter, omdat de tree-of-actions structuur je enig idee geeft waar de tijd aan is besteed, maar het is nog steeds niet voldoende als logging te schaars is.

Ten tweede, je kunt niet overal loggen, omdat dat je programma zal vertragen.Loggen is niet goedkoop- het is een hogere overhead dan cProfile.Dus je moet het oordeelkundig toevoegen, op belangrijke punten waar het de informatie die het geeft zal maximaliseren zonder de prestaties te beïnvloeden.

Kiezen van de juiste tools

Wanneer moet je elke tool gebruiken?

Altijd logging toevoegen

Elk niet-triviaal programma heeft waarschijnlijk logging nodig, al was het maar om fouten en bugs op te sporen.En als je al logging toevoegt, kun je de moeite nemen om de informatie die je nodig hebt om performance debugging te doen ook te loggen.

Eliot maakt het gemakkelijker, omdat het loggen van acties je inherent de verstreken tijd geeft, maar je kunt dit met wat extra werk met elke logging library doen.

Logging kan je helpen om de specifieke plaats te vinden waar je programma traag is, en op zijn minst enkele inputs die traagheid veroorzaken, maar het is vaak onvoldoende.Dus de volgende stap is het gebruik van een profiler, en in het bijzonder een sampling profiler zoals Pyinstrument:

• Het heeft een lage overhead, en wat nog belangrijker is, het vertekent de resultaten niet.
• Het meet wallclock tijd, dus het gaat er niet van uit dat CPU de bottleneck is.
• Het geeft alleen de langzamere functies weer, en laat de irrelevante snelle functies weg.

Gebruik cProfile als u een custom cost metric

Als u ooit een custom profiler moet schrijven, kunt u met cProfile verschillende cost functies inpluggen, waardoor het een makkelijke tool is voor het meten van meer ongebruikelijke metrics.

U kunt meten:

• Not-CPU, alle tijd besteed aan het wachten op niet-CPU events.
• Het aantal vrijwillige context-switches, d.w.z. het aantal systeemaanroepen dat lang duurt.
• Memory allocations.
• Algemener, elke teller die omhoog gaat.

TL;DR

Als een goed startpunt voor performance optimalisatie tools, stel ik voor dat u:

1. Log key inputs en outputs, en de verstreken tijd van key acties, met behulp van Eliot of een andere logging library.
2. Gebruik Pyinstrument-of een andere sampling profiler-als uw standaard profiler.
3. Gebruik cProfile als u een aangepaste profiler nodig hebt.