Bortom cProfile: Välja rätt verktyg för prestandaoptimering

$ python benchmark.py7855 messages/sec

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

Märk att det har en viss overhead, men inte lika mycket som cProfile – och overhead är enhetlig.

Pyinstrument har också ett Python-API, så du kan använda det för att profilera särskilda kodstycken i en interaktiv Python-tolk eller en Jupyter-notebook.

Utgången

Pyinstruments utgång är ett träd av anrop, som mäter väggtid:

Till skillnad från cProfiles rad-per-funktion ger Pyinstrument dig ett träd av funktionsanrop, så att du kan se kontexten för långsamheten. en funktion kan dyka upp flera gånger om långsamheten orsakas av flera kodvägar.

Som ett resultat är Pyinstruments utdata mycket lättare att tolka och ger dig en mycket bättre förståelse för ditt programs prestandastruktur än cProfiles standardutdata.

Hur det fungerar (kattutgåvan)

Föreställ dig att du har en katt och att du vill veta hur katten spenderar sin tid.

Du skulle kunna spionera på kattens varje ögonblick, men det skulle vara mycket arbete.Så istället bestämmer du dig för att ta stickprov: var femte minut sticker du in huvudet i det rum där katten befinner sig och skriver ner vad den gör.

Till exempel:

• 12:00: Sover 💤
• 12:05: Sover 💤
• 12:10: Äter 🍲
• 12:15: Använder kattlådan 💩
• 12:20: Sover 💤
• 12:25: Sover 💤
• 12:30: Sover 💤

Ett par dagar senare kan du sammanfatta dina observationer:

• 80%: Sovande 💤
• 10%: Äter 🍲
• 9%: Användning av kattlådan 💩
• 1%: Om ditt mål är att mäta var katten tillbringade den mesta av sin tid är det förmodligen korrekt, och ju mer frekventa observationer (==provtagningar) och ju fler observationer du gör, desto mer korrekt blir sammanfattningen.

  Om din katt tillbringar den mesta av sin tid med att sova, skulle du förvänta dig att de flesta observationer i urvalet skulle visa att den sover.Och ja, du kommer att missa några snabba och sällsynta aktiviteter – men för syftet ”vad tillbringade katten den mesta av sin tid med” är dessa snabba och sällsynta aktiviteter irrelevanta.

  Hur det fungerar (software edition)

  I likhet med vår katt samplar Pyinstrument ett Pythonprograms beteende i intervaller: varje 1ms kontrollerar den vilken funktion som körs för tillfället. det betyder:

  • Om en funktion är kumulativt långsam, kommer den att dyka upp ofta.
  • Om en funktion är kumulativt snabb kommer vi vanligtvis inte att se den alls.

  Det betyder att vår sammanfattning av prestanda har mindre brus: funktioner som knappt används kommer för det mesta att hoppa över.Men på det hela taget är sammanfattningen ganska korrekt när det gäller hur programmet spenderade sin tid, så länge vi tog tillräckligt många prover.

  Eliot: Det löser de två andra problemen som vi såg med cProfile:

  • Loggning kan användas i produktion.
  • Loggning kan registrera argument till funktioner.

  Som du kommer att se erbjuder Eliot några unika möjligheter som gör det bättre på att registrera prestanda än vanliga loggningsbibliotek. med detta sagt kan du med lite extra arbete få samma fördelar från andra loggningsbibliotek också.

  Lägga till loggning till befintlig kod

  Tänk på följande skiss av ett program:

  Vi kan ta den här koden och lägga till lite loggning till den:

  Specifikt gör vi två saker:

  1. Säg till Eliot var loggningsmeddelandena ska skrivas ut (i det här fallet en fil som heter ”out.log”).
  2. Vi dekorerar funktionerna med en @log_call dekorator.Detta kommer att logga det faktum att funktionen anropades, dess argument och returvärdet (eller det uppkomna undantaget).

  Eliot har andra, mer finkorniga API:er, men @log_call räcker för att demonstrera fördelarna med loggning.

  Eliots utdata

  När vi kört programmet kan vi titta på loggarna med hjälp av ett verktyg som heter eliot-tree:

  Bemärk att vi, lite som i Pyinstrument, tittar på ett träd av åtgärder.Jag har förenklat resultatet lite – ursprungligen för att det skulle få plats på en bild som jag använde i föredragsversionen av den här artikeln – men även i en prosaartikel kan vi fokusera på prestandaaspekten.

  I Eliot har varje åtgärd en start och ett slut, och kan starta andra åtgärder – därav det resulterande trädet.Eftersom vi vet när varje loggad handling börjar och slutar vet vi också hur lång tid den tog.

  I det här fallet mappar varje handling ett till ett med ett funktionsanrop.Och det finns några skillnader jämfört med Pyinstrumentets utdata:

  1. Istället för att kombinera flera funktionsanrop ser du varje enskilt anrop separat.
  2. Du kan se argumenten och returresultatet för varje anrop.
  3. Du kan se den förflutna väggklockstiden för varje åtgärd.

  Till exempel kan du se att multiplysum() tog 10 sekunder, men den stora majoriteten av tiden spenderades i multiply(), med inmatningarna 3 och 4.Så du vet omedelbart att du för prestandaoptimering vill fokusera på multiply(), och du har några startingångar (3 och 4) att leka med.

  Loggningens begränsningar

  Loggning räcker inte till på egen hand som källa till prestandainformation.

  För det första får du bara information från kod där du uttryckligen har lagt till loggningsanrop.En profiler kan köra på vilken godtycklig kod som helst utan förberedelser i förväg, men med loggning måste du göra en del arbete i förväg.

  Om du inte lagt till loggningskod får du ingen information.Eliot gör detta lite bättre, eftersom strukturen för träd av åtgärder ger dig en viss känsla för var tiden har spenderats, men det räcker fortfarande inte om loggningen är för sparsam.

  För det andra kan du inte lägga till loggning överallt eftersom det kommer att sakta ner ditt program. loggning är inte billigt – det är högre overhead än cProfile. så du måste lägga till det med omdöme, på viktiga punkter där det maximerar den information det ger utan att påverka prestandan.

  Välja rätt verktyg

  Så när ska du använda varje verktyg?

  Alltid lägga till loggning

  Varje icke-trivialt program behöver antagligen loggning, om inte annat så för att fånga upp buggar och fel.Och om du redan lägger till loggning kan du göra dig besväret att logga den information du behöver för att göra prestandadebuggning också.

  Eliot gör det lättare, eftersom loggning av åtgärder i sig ger dig förfluten tid, men du kan med lite extra arbete göra detta med vilket loggningsbibliotek som helst.

  Loggning kan hjälpa dig att upptäcka det specifika stället där ditt program är långsamt, och åtminstone några ingångar som orsakar långsamheten, men det är ofta otillräckligt.Så nästa steg är att använda en profiler, och i synnerhet en samplingsprofiler som Pyinstrument:

  • Den har låg overhead och, ännu viktigare, förvränger inte resultaten.
  • Den mäter väggtid, så den utgår inte från att CPU:n är flaskhalsen.
  • Den matar bara ut de långsammare funktionerna och utelämnar de irrelevanta snabba funktionerna.

  Använd cProfile om du behöver en anpassad kostnadsmätning

  Om du någonsin behöver skriva en anpassad profiler kan du med cProfile lägga in olika kostnadsfunktioner, vilket gör det till ett enkelt verktyg för att mäta mer ovanliga mätvärden.

  Du kan mäta:

  • Not-CPU, all den tid som spenderas på att vänta på händelser som inte är CPU.
  • Antalet frivilliga kontextbyten, det vill säga antalet systemanrop som tar lång tid.
  • Minnesallokeringar.
  • Mer allmänt, alla räknare som går upp.

  TL;DR

  Som en bra utgångspunkt för verktyg för prestandaoptimering föreslår jag att du:

  1. Loggar viktiga in- och utgångar och den förflutna tiden för viktiga åtgärder med hjälp av Eliot eller något annat loggningsbibliotek.
  2. Använd Pyinstrument – eller en annan provtagningsprofilering – som din standardprofilering.
  3. Använd cProfile när om du behöver en anpassad profilering.