Ud over cProfile: Valg af det rigtige værktøj til optimering af ydeevne

Note: Denne artikel er baseret på et foredrag, jeg holdt på PyGotham 2019. Du kan se videoen her.

Dit Python-program er for langsomt. måske kan din webapplikation ikke følge med, eller visse forespørgsler tager lang tid. måske har du et batchprogram, der tager timer eller endda dage at køre.

Hvordan fremskynder du?

Den grundlæggende proces, du sandsynligvis vil følge, er:

1. Vælg det rigtige værktøj til at måle hastigheden.
2. Brug værktøjet til at finde ud af, hvor flaskehalsen er.
3. Fiks flaskehalsen.

Denne artikel vil fokusere på det første trin: at vælge det rigtige værktøj.Og den vil især dække:

• cProfile: Python standardbibliotekets deterministiske profiler.
• Pyinstrument: En sampling profiler.
• Eliot: Et logningsbibliotek.

Jeg vil ikke gå i detaljer med, hvordan man bruger disse værktøjer, fordi målet er at hjælpe dig med at vælge det rigtige. Men jeg vil forklare, hvad disse værktøjer gør, og hvornår og hvorfor du ville vælge det ene frem for det andet.

cProfile: En deterministisk profiler

cProfile-profileren er indbygget i Python, så du har sikkert hørt om den, og det er måske det standardværktøj, du bruger.Den fungerer ved at spore hvert eneste funktionskald i et program.Derfor er det en deterministisk profiler: Hvis du kører den med de samme input, vil den give det samme output.

Som standard måler cProfile proces-CPU – hvor meget CPU din proces har brugt indtil nu.Du bør altid spørge, hvad din profiler måler, fordi forskellige mål kan opdage forskellige problemer. at måle CPU betyder, at du ikke kan opdage langsommelighed forårsaget af andre årsager, som f.eks. at vente på svar fra en databaseforespørgsel.

Mens cProfile altid er tilgængelig i din Python-installation, har den også nogle problemer – og som du vil se, vil du for det meste ikke bruge den.

Brug af cProfile

Brug af cProfile er ret nemt.Hvis du har et script, som du normalt kører direkte på følgende måde:

$ python benchmark.py7855 messages/sec

Så kan du bare sætte præfikset python -m cProfile for at køre det under profileringen:

Der er også en Python-profilerings-API, så du kan profilere bestemte funktioner i en Python-fortolkerprompt eller en Jupyter-notebook.

Outputformatet er en tabel, hvilket ikke er ideelt: Hver række er et funktionskald, der kørte i løbet af det profilerede tidsrum, men du ved ikke, hvordan det pågældende funktionskald er relateret til andre funktionskald.Så hvis du har en funktion, der kan nås fra flere kodeveje, kan det være svært at finde ud af, hvilken kodevej der var ansvarlig for at kalde den langsomme funktion.

Hvad cProfile kan fortælle dig

Hvis du kigger på tabellen ovenfor, kan du se, at:

• _output.py(__call__) blev kaldt 50.000 gange. Det er et lige tal, fordi det er et benchmark-script, der kører den samme kode i en løkke 10.000 gange.Hvis du ikke med vilje kaldte en funktion mange gange, kan dette være nyttigt til at spotte højt antal kald er nyttigt til at identificere travle indre løkker.
• _output.py(send) brugte 0,618 CPU-sekunder (inklusive CPU-tid for funktioner, den kaldte) og 0,045 CPU-sekunder (uden funktioner, den kaldte).

Med disse oplysninger kan du finde langsomme funktioner, som du kan optimere – i hvert fald langsomme for så vidt angår CPU’en.

Sådan fungerer det

cProfile måler hvert enkelt funktionskald.Især bliver hvert funktionskald i kørslen pakket ind på følgende måde:

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

Profileren registrerer CPU-tiden ved start og slut, og forskellen allokeres til den pågældende funktions konto.

Problemerne med cProfile

Selv om cProfile altid er tilgængelig i enhver Python-installation, lider den også under nogle væsentlige problemer.

Problem nr. 1: Højt overhead og forvrængede resultater

Som du kan forestille dig, har det nogle omkostninger at gøre ekstra arbejde for hvert funktionskald:

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

Bemærk, hvor meget langsommere cProfile-kørslen er.Og hvad værre er, så er forsinkelsen ikke ensartet i hele dit program: Fordi den er knyttet til antallet af funktionskald, vil dele af din kode med flere funktionskald blive mere forsinket.Så dette overhead kan forvrænge resultaterne.

Problem nr. 2: For mange oplysninger

Hvis du husker cProfile-outputtet, som vi så ovenfor, indeholder det en række for hver enkelt funktion, der blev kaldt under programkøbet. de fleste af disse funktionskald er irrelevante for vores ydelsesproblem: de kører hurtigt og kun en eller to gange.

Så når du læser cProfile-output, har du at gøre med en masse ekstra støj, der maskerer signalet.

Problem nr. 3: Offline-måling af ydeevne

Som oftest vil dit program kun være langsomt, når det køres under reelle forhold og med reelle input. måske er det kun bestemte forespørgsler fra brugere, der gør dit webprogram langsomt, og du ved ikke, hvilke forespørgsler det drejer sig om. måske er dit batchprogram kun langsomt med reelle data.

Men cProfile gør som vi så dit program ret langsomt, og derfor vil du sandsynligvis ikke køre det i dit produktionsmiljø. så mens langsommeligheden kun kan reproduceres i produktionen, hjælper cProfile dig kun i dit udviklingsmiljø.

Problem #4: Ydelsen måles kun for funktioner

cProfile kan fortælle dig “slowfunc() er langsom”, hvor den beregner et gennemsnit af alle input til den pågældende funktion.Og det er fint, hvis funktionen altid er langsom.

Men nogle gange har du noget algoritmisk kode, som kun er langsom for bestemte input.Det er meget muligt, at:

• slowfunc(100) er hurtig.
• slowfunc(0) er langsom.

cProfile vil ikke kunne fortælle dig, hvilke input der har forårsaget langsommeligheden, hvilket kan gøre det sværere at diagnosticere problemet.

cProfile: I stedet skal vi nu tale om to alternativer:

• Pyinstrument løser problemerne nr. 1 og 2.
• Eliot løser problemerne nr. 3 og 4.

Pyinstrument: en sampling profiler

Pyinstrument løser to af de problemer, vi har behandlet ovenfor:

• Det har lavere overhead end cProfile, og det forvrænger ikke resultaterne.
• Den filtrerer irrelevante funktionskald fra, så der er mindre støj.

Pyinstrument måler forløbne wallclock-tid, ikke CPU-tid, så den kan fange langsommelighed forårsaget af netværksanmodninger, diskskrivninger, låsestridigheder og så videre.

Sådan bruger du det

Brug af Pyinstrument svarer til cProfile; du skal blot tilføje et præfiks til dit script:

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

Bemærk, at det har noget overhead, men ikke så meget som cProfile – og overheadet er ensartet.

Pyinstrument har også et Python-API, så du kan bruge det til at profilere bestemte kodestykker i en interaktiv Python-fortolker eller en Jupyter-notebook.

Output

Pyinstrument’s output er et træ af kald, der måler vægurtid:

I modsætning til cProfile’s row-per-function giver Pyinstrument dig et træ af funktionskald, så du kan se konteksten for langsommelighed. en funktion kan optræde flere gange, hvis langsommeligheden skyldes flere kodeveje.

Som følge heraf er Pyinstruments output meget nemmere at fortolke og giver dig en meget bedre forståelse af dit programs ydelsesstruktur end cProfiles standardoutput.

Sådan fungerer det (katteudgaven)

Forestil dig, at du har en kat. du ønsker at vide, hvordan katten bruger sin tid.

Du kunne udspionere den hvert eneste øjeblik, men det ville være et stort arbejde.

Så i stedet beslutter du dig for at tage stikprøver: hvert femte minut stikker du hovedet ind i det rum, hvor katten befinder sig, og skriver ned, hvad den laver.

For eksempel:

• 12:00: Sover 💤
• 12:05: Sover 💤
• 12:10: Spiser 🍲
• 12:15: Bruger kattebakken 💩
• 12:20: Sover 💤
• 12:20: Sover 💤
• 12:25: Sover 💤
• 12:30: Sover 💤

Et par dage senere kan du opsummere dine observationer:

• 80%: Sovende 💤
• 10%: Spiser 🍲
• 9%: Bruger kattebakken 💩
• 1%: I det omfang dit mål er at måle, hvor katten tilbragte det meste af sin tid, er det sandsynligvis nøjagtigt, og jo hyppigere observationer (==stikprøver) og jo flere observationer du foretager, jo mere nøjagtig bliver oversigten.

  Hvis din kat bruger det meste af sin tid på at sove, vil du forvente, at de fleste observationer i stikprøverne viser, at den sover. og ja, du vil gå glip af nogle hurtige og sjældne aktiviteter – men med henblik på “hvad brugte katten det meste af sin tid på” er disse hurtige og sjældne aktiviteter irrelevante.

  Sådan fungerer det (softwareudgave)

  Meget ligesom vores kat sampler Pyinstrument et Python-programs adfærd med intervaller: Hver 1 ms kontrollerer den, hvilken funktion der kører i øjeblikket. det betyder:

  • Hvis en funktion er kumulativt langsom, vil den dukke op ofte.
  • Hvis en funktion er kumulativt hurtig, vil vi normalt ikke se den overhovedet.

  Det betyder, at vores ydelsesoversigt har mindre støj: funktioner, der næsten ikke bruges, vil for det meste blive sprunget over.Men overordnet set er oversigten ret præcis med hensyn til, hvordan programmet brugte sin tid, så længe vi tog nok prøver.

  Eliot: Det løser de to andre problemer, som vi så med cProfile:

  • Logging kan bruges i produktion.
  • Logging kan registrere argumenter til funktioner.

  Som du vil se, giver Eliot nogle unikke muligheder, der gør det bedre til at registrere ydeevne end normale logningsbiblioteker.

Når det er sagt, kan du med lidt ekstra arbejde også få de samme fordele fra andre logningsbiblioteker.

Tilføjelse af logning til eksisterende kode

Se på følgende skitse af et program:

Vi kan tage denne kode og tilføje noget logning til den:

Specifikt gør vi to ting:

1. Fortælder Eliot, hvor logmeddelelserne skal udskrives (i dette tilfælde en fil kaldet “out.log”).
2. Vi dekorerer funktionerne med en @log_call dekorator.Dette vil logge det faktum, at funktionen blev kaldt, dens argumenter og returværdien (eller den udløste undtagelse).

Eliot har andre, mere finkornede API’er, men @log_call er tilstrækkeligt til at demonstrere fordelene ved logning.

Eliots output

Når vi har kørt programmet, kan vi se på logfilerne ved hjælp af et værktøj kaldet eliot-tree:

Bemærk, at vi, lidt ligesom i Pyinstrument, ser på et træ af handlinger.Jeg har forenklet outputtet en smule – oprindeligt for at det kunne passe på et dias, som jeg brugte i foredragsversionen af denne artikel – men selv i en prosaartikel lader det os fokusere på præstationsaspektet.

I Eliot har hver handling en start og en slutning, og kan starte andre handlinger – deraf det resulterende træ.Da vi ved, hvornår hver enkelt logget handling starter og slutter, ved vi også, hvor lang tid den tog.

I dette tilfælde er hver handling en-til-én-korrespondance med et funktionskald.Og der er nogle forskelle i forhold til Pyinstruments output:

1. I stedet for at kombinere flere funktionskald ser du hvert enkelt kald separat.
2. Du kan se argumenterne og returresultatet for hvert opkald.
3. Du kan se den forgangne vægurtid for hver handling.

For eksempel kan du se, at multiplysum() tog 10 sekunder, men langt størstedelen af tiden blev brugt i multiply() med indgangene 3 og 4.Så du ved straks, at du med henblik på ydelsesoptimering vil fokusere på multiply(), og du har nogle startinput (3 og 4) at lege med.

Begrænsningerne ved logning

Logning er ikke tilstrækkelig i sig selv som kilde til oplysninger om ydeevne.

For det første får du kun oplysninger fra kode, hvor du udtrykkeligt har tilføjet logningskald.En profiler kan køre på et vilkårligt stykke kode uden forudgående forberedelse, men med logning skal du gøre noget arbejde på forhånd.

Hvis du ikke har tilføjet logningskode, får du ingen oplysninger.Eliot gør dette lidt bedre, da tree-of-actions-strukturen giver dig en vis fornemmelse af, hvor tiden er blevet brugt, men det er stadig ikke tilstrækkeligt, hvis logningen er for sparsom.

For det andet kan du ikke tilføje logning overalt, fordi det vil gøre dit program langsommere. logning er ikke billigt – det er et højere overhead end cProfile. så du skal tilføje det med omtanke, på nøglepunkter, hvor det vil maksimere de oplysninger, det giver, uden at det påvirker ydelsen.

Valg af de rigtige værktøjer

Så hvornår skal du bruge hvert enkelt værktøj?

Altid tilføje logning

Altid tilføje logning

Alt ikke-trivielt program har sandsynligvis brug for noget logning, om ikke andet for at opdage fejl og mangler.Og hvis du allerede tilføjer logning, kan du gøre dig den ulejlighed at logge de oplysninger, du har brug for, for også at lave ydelsesdebugging.

Eliot gør det nemmere, da logning af handlinger i sagens natur giver dig forløbne tid, men du kan med lidt ekstra arbejde gøre dette med ethvert logningsbibliotek.

Logning kan hjælpe dig med at finde det specifikke sted, hvor dit program er langsomt, og i det mindste nogle input, der forårsager langsommelighed, men det er ofte utilstrækkeligt.Så det næste skridt er at bruge en profiler, og især en sampling-profiler som Pyinstrument:

• Den har lavt overhead, og endnu vigtigere forvrænger ikke resultaterne.
• Den måler wallclock-tid, så den antager ikke, at CPU er flaskehalsen.
• Den udsender kun de langsommere funktioner og udelader de irrelevante hurtige funktioner.

Brug cProfile, hvis du har brug for en brugerdefineret omkostningsmetrik

Hvis du nogensinde får brug for at skrive en brugerdefineret profiler, giver cProfile dig mulighed for at indsætte forskellige omkostningsfunktioner, hvilket gør det til et nemt værktøj til måling af mere usædvanlige metrikker.

Du kan måle:

• Not-CPU, al den tid, der bruges på at vente på ikke-CPU-hændelser.
• Antallet af frivillige kontekstskift, dvs. antallet af systemkald, der tager lang tid.
• Hukommelsesallokeringer.
• Mere bredt set, enhver tæller, der stiger.

TL;DR

Som et godt udgangspunkt for værktøjer til optimering af ydeevnen foreslår jeg, at du:

1. Logger de vigtigste ind- og udgange og den forløbne tid for de vigtigste handlinger ved hjælp af Eliot eller et andet logningsbibliotek.
2. Brug Pyinstrument – eller en anden prøveprofiler – som din standardprofiler.
3. Brug cProfile, når hvis du har brug for en brugerdefineret profiler.