cProfiilin ulkopuolella:

Huomautus: Tämä artikkeli perustuu PyGotham 2019 -tapahtumassa pitämääni puheenvuoroon. Voit katsoa videon täältä.

Python-ohjelmasi on liian hidas.

Ehkä verkkosovelluksesi ei pysy vauhdissa mukana, tai tietyt kyselyt vievät paljon aikaa.

Ehkä sinulla on eräohjelma, jonka suorittaminen kestää tunteja tai jopa päiviä.

Miten voit nopeuttaa?

Perusprosessi, jota todennäköisesti noudatat, on seuraava:

1. Valitse oikea työkalu nopeuden mittaamiseen.
2. Käytä työkalua pullonkaulan selvittämiseen.
3. Korjaa pullonkaula.

Tässä artikkelissa keskitytään ensimmäiseen vaiheeseen: oikean työkalun valintaan.Ja erityisesti käsitellään:

• cProfiili: Pythonin standardikirjaston deterministinen profiloija.
• Pyinstrument: Näytteenottoprofiloija.
• Eliot: A logging library.

En aio mennä valtavan yksityiskohtaisesti näiden työkalujen käyttöön, koska tavoitteena on auttaa sinua valitsemaan oikea työkalu. Selitän kuitenkin, mitä nämä työkalut tekevät ja milloin ja miksi kannattaa valita toinen toisen sijaan.

cProfile: Se toimii jäljittämällä jokaisen funktiokutsun ohjelmassa.Siksi se on deterministinen profiloija: jos suoritat sen samoilla syötteillä, se antaa saman tuloksen.

Oletusarvoisesti cProfile mittaa prosessin suorittimen (CPU) – kuinka paljon CPU:ta prosessi on käyttänyt tähän mennessä.Kannattaa aina kysyä, mitä profiloijasi mittaa, koska eri mittaukset voivat havaita erilaisia ongelmia.CPU:n mittaaminen tarkoittaa, että et voi havaita muista syistä johtuvaa hitautta, kuten tietokantakyselyn vastauksen odottamista.

Vaikka cProfile on aina saatavilla Python-asennuksessasi, sillä on myös joitain ongelmia – ja kuten tulet näkemään, suurimman osan ajasta et halua käyttää sitä.

Käyttämällä cProfilea

CProfilen käyttäminen on melko helppoa.Jos sinulla on skripti, jonka suoritat yleensä suoraan näin:

$ python benchmark.py7855 messages/sec

Tällöin voit vain laittaa etuliitteen python -m cProfile ajamaan sen profiloijan alaisuudessa:

On olemassa myös Python-profilointirajapinta, joten voit profiloida tietyt funktiot Python-tulkin kehotteessa tai Jupyter-muistikirjassa.

Tulostusmuoto on taulukko, joka ei ole ihanteellinen: jokainen rivi on funktiokutsu, joka suoritettiin profiloidun ajanjakson aikana, mutta et tiedä, miten kyseinen funktiokutsu liittyy muihin funktiokutsuihin.Jos sinulla on siis funktio, johon pääsee useista koodipoluista, voi olla vaikeaa selvittää, mikä koodipolku oli vastuussa hitaan funktion kutsumisesta.

Mitä cProfile voi kertoa sinulle

Jos katsot yllä olevaa taulukkoa, näet, että:

• _output.py(__call__) kutsuttiin 50 000 kertaa. Se on parillinen luku, koska tämä on benchmark-skripti, joka ajaa samaa koodia silmukassa 10 000 kertaa.Jos et tarkoituksella kutsunut funktiota monta kertaa, tämä voi olla hyödyllistä havaita suuri määrä kutsuja on hyödyllistä tunnistaa kiireiset sisäiset silmukat.
• _output.py(send) käytti 0,618 CPU-sekuntia (mukaan lukien kutsuttujen funktioiden CPU-aika) ja 0,045 CPU-sekuntia (ilman kutsuttuja funktioita).

Tämän tiedon avulla voit havaita hitaita funktioita, joita voit optimoida – hitaita ainakin CPU:n suhteen.

Miten se toimii

cProfile mittaa jokaisen yksittäisen funktiokutsun.Erityisesti jokainen funktiokutsu ajossa kääritään näin:

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

Profileroija kirjaa CPU-ajan alkuunsa ja loppuunsaattoonsa, ja erotus kohdennetaan ko. funktiokutsun tilille.

CProfiilin ongelmat

Vaikka cProfile on aina saatavilla missä tahansa Python-asennuksessa, se kärsii myös muutamista merkittävistä ongelmista.

Obgelma #1: Suuri yleiskustannus ja vääristyneet tulokset

Kuten voit kuvitella, ylimääräisen työn tekeminen jokaista funktiokutsua varten aiheuttaa kustannuksia:

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

Huomaa, kuinka paljon hitaampi cProfile-ajo on.Ja mikä vielä pahempaa, hidastuminen ei ole tasaista koko ohjelmassasi: koska se on sidottu funktiokutsujen määrään, koodisi osat, joissa on enemmän funktiokutsuja, hidastuvat enemmän. tämä yleiskustannus voi siis vääristää tuloksia.

Obgelma #2: Liian paljon tietoa

Jos muistat edellä näkemämme cProfile-tulosteen, se sisältää rivin jokaisesta funktiosta, jota kutsuttiin ohjelman suorituksen aikana. suurin osa näistä funktiokutsuista on suorituskykyongelmamme kannalta epäolennaisia: ne suoritetaan nopeasti ja vain kerran tai kahdesti.

Lukiessasi cProfile-tulostetta joudut siis kamppailemaan monien ylimääräisten kohinatekijöiden kanssa, jotka peittävät signaalin.

Obgelma #3: Suorituskyvyn offline-mittaus

Hyvin usein ohjelmasi on hidas vain silloin, kun sitä ajetaan reaalimaailman olosuhteissa, reaalimaailman syötteillä.Ehkä vain tietyt käyttäjien tekemät kyselyt hidastavat web-sovellustasi, etkä tiedä, mitkä kyselyt.Ehkä panoslähetysohjelmasi on hidas vain todellisen datan kanssa.

Mutta cProfile, kuten näimme, hidastaa ohjelmaasi melkoisesti, joten et todennäköisesti halua ajaa sitä tuotantoympäristössäsi. cProfile siis auttaa sinua vain kehitysympäristössäsi, vaikka hitaus on toistettavissa vain tuotannossa.

Obgelma #4: Suorituskykyä mitataan vain funktioiden osalta

cProfile voi kertoa sinulle ”slowfunc() on hidas”, jolloin se laskee keskiarvon kaikista tuon funktion syötteistä.Ja se on hyvä, jos funktio on aina hidas.

Mutta joskus sinulla on jotain algoritmista koodia, joka on hidasta vain tietyille syötteille.On täysin mahdollista, että:

• slowfunc(100) on nopea.
• slowfunc(0) on hidas.

cProfile ei pysty kertomaan, mitkä syötteet aiheuttivat hitauden, mikä voi vaikeuttaa ongelman diagnosointia.

cProfile: Sen sijaan seuraavaksi puhumme kahdesta vaihtoehdosta:

• Pyinstrument ratkaisee ongelmat #1 ja #2.
• Eliot ratkaisee ongelmat #3 ja #4.

Pyinstrument: näytteenottoprofiloija

Pyinstrument ratkaisee kaksi edellä käsittelemäämme ongelmaa:

• Sen yleiskustannukset ovat pienemmät kuin cProfile:lla, eikä se vääristä tuloksia.
• Se suodattaa pois epäolennaiset funktiokutsut, joten kohinaa on vähemmän.

Pyinstrument mittaa kulunutta seinäkelloaikaa, ei suorittimen aikaa, joten se voi havaita verkkopyyntöjen, levykirjoitusten, lukitusriitojen ja muiden vastaavien aiheuttaman hitauden.

Käyttötapa

Pyinstrumentin käyttö on samanlaista kuin cProfile:n; lisäät vain skriptiin etuliitteen:

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

Huomaa, että sillä on jonkin verran yleiskustannuksia, mutta ei niin paljon kuin cProfile:lla – ja yleiskustannukset ovat tasaisia.

Pyinstrumentilla on myös Python API, joten voit käyttää sitä tiettyjen koodinpätkien profilointiin vuorovaikutteisessa Python-tulkissa tai Jupyter notebookissa.

Tuloste

Pyinstrumentin tuloste on kutsujen puu, joka mittaa seinäkelloaikaa:

Toisin kuin cProfilen rivi per funktio, Pyinstrument antaa sinulle funktiokutsujen puun, joten näet hitauden asiayhteyden.Funktio saattaa esiintyä useita kertoja, jos hitaus johtuu useista koodipoluista.

Tuloksena Pyinstrumentin tulosteet ovat paljon helpommin tulkittavissa ja antavat sinulle paljon paremman käsityksen ohjelmasi suorituskykyrakenteesta kuin cProfilen oletustulosteet.

Miten se toimii (kissapainos)

Kuvittele, että sinulla on kissa.Haluat tietää, miten tuo kissa viettää aikaansa.

Voisit vakoilla sen jokaista hetkeä, mutta se olisi paljon työtä.Sen sijaan päätät ottaa näytteitä: 5 minuutin välein työnnät pääsi huoneeseen, jossa kissa on, ja kirjoitat ylös, mitä se tekee.

Esimerkiksi:

• 12:00: Nukkuu 💤
• 12:05: Nukkuu 💤
• 12:10: Syö 🍲
• 12:15: Käyttää pönttöä 💩
• 12:20: Nukkuu 💤
• 12:25: Nukkuu 💤
• 12:30: Nukkuu 💤

Pari päivää myöhemmin voit tiivistää havaintosi:

• 80%: Nukkuu 💤
• 10%: Syöminen 🍲
• 9%: Pönttölaatikon käyttö 💩
• 1%: Tuijottaa kaihoisasti ikkunasta lintuja 🐦

Kuinka tarkka tämä yhteenveto on?Sikäli kuin tavoitteenasi on mitata, missä kissa vietti suurimman osan ajastaan, se on luultavasti tarkka. ja mitä useammin havaintoja (==näytteitä) ja mitä enemmän havaintoja teet, sitä tarkempi yhteenveto on.

Jos kissa viettää suurimman osan ajastaan nukkuen, odotat useimpien otantahavaintojen osoittavan, että se nukkuu. ja kyllä, sinulta jää huomaamatta joitain nopeita ja harvinaisia aktiviteetteja – mutta ”mihin kissa vietti suurimman osan ajastaan” -tarkoituksen kannalta nuo nopeat ja harvinaiset aktiviteetit ovat epäolennaisia.

Miten se toimii (ohjelmistopainos)

Niin kuin kissamme, Pyinstrument ottaa näytteitä Python-ohjelman käyttäytymisestä tietyin väliajoin: 1 ms:n välein se tarkistaa, mikä funktio on parhaillaan käynnissä.Tämä tarkoittaa:

• Jos funktio on kumulatiivisesti hidas, se näkyy usein.
• Jos funktio on kumulatiivisesti nopea, emme yleensä näe sitä lainkaan.

Tämä tarkoittaa, että suorituskykyyhteenvedossamme on vähemmän kohinaa: funktiot, joita käytetään tuskin lainkaan, useimmiten ohitetaan.Kaiken kaikkiaan yhteenveto on kuitenkin melko tarkka siitä, miten ohjelma käytti aikaansa, kunhan otimme tarpeeksi näytteitä.

Eliot: Lokikirjasto

Viimeinen työkalu, jota käsittelemme yksityiskohtaisesti, on kirjoittamani lokikirjasto Eliot, joka ratkaisee kaksi muuta ongelmaa, jotka näimme cProfile-ohjelmassa:

• Lokikirjastoa voidaan käyttää tuotannossa.
• Lokikirjastolla voidaan tallentaa funktioiden argumentit.

Kuten huomaat, Eliot tarjoaa joitakin ainutlaatuisia ominaisuuksia, jotka tekevät siitä paremman suorituskyvyn tallentamisessa kuin tavalliset lokikirjastot.Tästä huolimatta voit pienellä lisätyöllä saada samat edut myös muista lokikirjastoista.

Loggauksen lisääminen olemassa olevaan koodiin

Asettele seuraava luonnos ohjelmasta:

Voisimme ottaa tämän koodin ja lisätä siihen jonkin verran loggausta:

Kohtaisesti teemme kaksi asiaa:

1. Kertoa Eliotille, minne lokiviestit tulostetaan (tässä tapauksessa tiedostoon nimeltä ”out.log”).
2. Koristelemme funktiot @log_call-dekoraattorilla.Tämä kirjaa lokiin sen, että funktiota kutsuttiin, sen argumentit ja paluuarvon (tai herätetyn poikkeuksen).

Eliotilla on muitakin, hienojakoisempia API:ita, mutta @log_call riittää lokituksen hyötyjen esittelyyn.

Eliotin tuotos

Kun ajamme ohjelman, voimme tarkastella lokitietoja eliot-tree-nimisellä työkalulla:

Huomaa, että hieman Pyinstrumentin tapaan tarkastelemme toimintojen puuta.Olen yksinkertaistanut tulostusta hieman – alun perin siksi, että se mahtuisi diaan, jota käytin tämän artikkelin puheversiossa – mutta jopa proosa-artikkelissa sen avulla voimme keskittyä suorituskykyyn.

Eliotissa jokaisella toiminnolla on alku ja loppu, ja se voi käynnistää muita toimintoja – näin syntyy puu.Koska tiedämme, milloin kukin kirjattu toiminto alkaa ja päättyy, tiedämme myös, kuinka kauan se kesti.

Tässä tapauksessa jokainen toiminto vastaa yksi yhteen funktiokutsua.Ja on joitakin eroja Pyinstrumentin tulosteeseen verrattuna:

1. Monien funktiokutsujen yhdistämisen sijaan näet jokaisen yksittäisen kutsun erikseen.
2. Näet kunkin kutsun argumentit ja palautustuloksen.
3. Näet kunkin toiminnon kuluneen wallclock-ajan.

Näet esimerkiksi, että multiplysum() kesti 10 sekuntia, mutta suurin osa ajasta kului multiply():ssa, jonka syötteet olivat 3 ja 4.Tiedät siis heti, että suorituskyvyn optimoimiseksi haluat keskittyä multiply():een, ja sinulla on joitain lähtösyötteitä (3 ja 4), joiden kanssa voit leikkiä.

Loggauksen rajoitukset

Loggaus ei yksinään riitä suorituskykytiedon lähteenä.

Ensinnäkään saat tietoa vain koodista, johon olet lisännyt eksplisiittisesti loggauksen kutsuja.Profiloija voi ajaa minkä tahansa mielivaltaisen koodinpätkän ilman etukäteisvalmisteluja, mutta lokitiedostojen kanssa sinun on tehtävä jonkin verran työtä etukäteen.

Jos et ole lisännyt lokitiedostokoodia, et saa mitään tietoa.Eliot tekee tästä hieman paremman, koska toimintojen puu -rakenne antaa jonkinlaisen käsityksen siitä, mihin aika on kulunut, mutta se ei silti riitä, jos lokitiedostoja on liian vähän.

Toiseksi, et voi lisätä lokitusta kaikkialle, koska se hidastaa ohjelmaasi.Lokitus ei ole halpaa – sen yleiskustannukset ovat suuremmat kuin cProfiilin.Joten sinun täytyy lisätä sitä harkiten, keskeisiin kohtiin, joissa se maksimoi antamansa informaation vaikuttamatta suorituskykyyn.

Oikeiden työkalujen valinta

Milloin siis kannattaa käyttää kutakin työkalua?

Loggauksen lisääminen aina

Jokainen ei-triviaali ohjelma tarvitsee luultavasti jonkin verran lokitusta, jo pelkästään vikojen ja virheiden havaitsemiseksi.Ja jos lisäät lokitusta jo nyt, voit nähdä vaivaa lokitellaksesi myös suorituskyvyn virheenkorjausta varten tarvittavan tiedon.

Eliot tekee siitä helpompaa, koska toimintojen kirjaaminen antaa luonnostaan kuluneen ajan, mutta voit tehdä tämän pienellä lisätyöllä millä tahansa kirjauskirjastolla.

Loggaaminen saattaa auttaa sinua havaitsemaan tietyn paikan, jossa ohjelmasi on hidas, ja ainakin joitain syötteitä, jotka aiheuttavat hitautta, mutta se on usein riittämätöntä.Joten seuraava askel on käyttää profiloijaa, ja erityisesti Pyinstrumentin kaltaista näytteenottoprofiloijaa:

• Sen yleiskustannus on pieni, ja mikä tärkeämpää, se ei vääristä tuloksia.
• Se mittaa wallclock-aikaa, joten se ei oleta CPU:n olevan pullonkaula.
• Se antaa tulokseksi vain hitaammat funktiot jättäen pois merkityksettömät nopeat funktiot.

Käytä cProfilea, jos tarvitset mukautetun kustannusmetriikan

Jos sinun on joskus kirjoitettava mukautettu profiloija, cProfile mahdollistaa erilaisten kustannusfunktioiden liittämisen, mikä tekee siitä helpon työkalun epätavallisempien metriikoiden mittaamiseen.

Voit mitata:

• Ei CPU:ta, kaikkea aikaa, joka kuluu muiden kuin CPU:n tapahtumien odottamiseen.
• Vapaaehtoisten kontekstinvaihtojen määrän, eli sellaisten järjestelmäpuhelujen määrän, jotka kestävät kauan.
• Muistin allokaatiot.
• Laajemmin kaikki laskurit, jotka nousevat.

TL;DR

Suorituskyvyn optimointityökalujen hyvänä lähtökohtana ehdotan, että:

1. Loggaa keskeiset syötteet ja lähdöt sekä keskeisten toimintojen kulunut aika käyttäen Eliotia tai jotain muuta lokikirjastoa.
2. Käytä Pyinstrumentia – tai jotain muuta näytteenottoprofiilintarkistinta – oletusprofiilintarkistajana.
3. Käytä cProfilea, jos tarvitset mukautetun profiilintarkistajan.