Počasna stran v CRM-ju: najprej jo izmerimo, nato jo (morda) optimiziramo

V našem CRM-ju je bila stran, pri kateri je bilo ob odpiranju treba čakati. Ne toliko, da bi to ustavilo delo, a dovolj, da je bilo vsakič opazno. V poslovnem sistemu, ki ga uporabljamo ves dan, stran, ki okleva, hitro postane nadloga, o kateri govorijo vsi.

Sum je takoj padel na neko poizvedbo. V njej je bila korelirana podpoizvedba, exists, ki je za vsako vrstico preverjala nekaj v drugem delu podatkov. V mislih smo jo že prepisovali.

Nismo je prepisali. Najprej smo merili, in meritev nam je pokazala, da bi se lotili napačne stvari.

Popoln krivec

Korelirane podpoizvedbe imajo slab sloves, in to ne povsem nezasluženo: na papirju opisujejo delo, ki se ponavlja vrstico za vrstico, in kdor je prebral nekaj nasvetov o zmogljivosti podatkovnih baz, se jih nauči gledati z nezaupanjem. Ko je stran počasna in v kodi najdeš takšno podpoizvedbo, se zdi, da je primer rešen sam od sebe.

Prav v tem je težava. Poizvedba, ki je videti sumljiva, je priročna razlaga, ker nam da nekaj konkretnega za postoriti. Toda »zdi se počasna« ni meritev. Je vtis, vtisi o zmogljivosti pa so napačni pogosteje, kot bi radi priznali.

Kaj smo v resnici izmerili

Metoda, ki jo uporabljamo zdaj, je preprosta in jo uporabimo, še preden se dotaknemo ene same vrstice kode.

Prvič: zabeležimo vse poizvedbe, ki jih pool izvede med nalaganjem strani. Ne le sumljive: vse. Stran pogosto pošlje podatkovni bazi več zahtev, kot se jih spomnimo, in že popoln seznam je koristna informacija.

Drugič: vsako posebej ponovno izvedemo z explain analyze. Za razliko od navadnega explain, ki pokaže le predvideni načrt, explain analyze poizvedbo dejansko izvede in vrne načrt z dejanskimi časi vsakega koraka. To je razlika med tem, da Postgres vprašamo, kaj namerava narediti, in tem, da ga opazujemo, medtem ko to počne.

Rezultat nas je presenetil. Obtoženo poizvedbo, tisto z exists, je Postgres opravil v enem samem pregledu. Nobenega ponavljanja vrstico za vrstico: načrtovalnik je sam našel učinkovito pot. Prepis, ki smo ga imeli v mislih, ne bi pridobil ničesar.

Od kod je torej prihajalo skoraj tisoč milisekund čakanja?

Podatkovna baza, ki je spala

Prihajalo je od tam, kamor nismo pomislili: naša podatkovna baza je serverless in po obdobju nedejavnosti preide v mirovanje. Počasnost, ki smo jo opažali, je bilo prebujanje. Kdor je v tistem trenutku odprl stran, je plačal čakanje na ponovni zagon baze in ga pripisal prvi stvari, ki mu je prišla na misel.

Vredno se je ustaviti pri tem, kaj bi se zgodilo, če bi sledili nagonu. Porabili bi čas za prepisovanje poizvedbe, ki je delovala dobro, in tvegali napako v delu sistema, ki ni imel težav. In najhuje: novo različico bi lahko preizkusili v trenutku, ko je bila baza že budna, videli, da se stran odziva hitro, in se prepričali, da smo težavo rešili. Lažen uspeh je nevarnejši od neuspeha, ker zaključi iskanje.

Ta napaka nas je naučila največ, in prav zato jo pripovedujemo.

Drugo vprašanje: je čas porabljen v podatkovni bazi ali zunaj nje?

Počasnost ni vedno v podatkovni bazi, in metoda pomaga tudi to ugotoviti. Primerjamo dve številki: skupni čas nalaganja strani in čas, porabljen v podatkovni bazi, torej vsoto zabeleženih poizvedb.

Če sta časa blizu, je delo treba opraviti pri poizvedbah, in explain analyze nam pove, kje. Če pa je skupni čas precej višji od časa v bazi, je ozko grlo drugje: skoraj vedno gre za sinhrono kodo JavaScript, ki blokira nit. Zahteven izračun, zanka čez preveč podatkov, preoblikovanje, opravljeno naenkrat: dokler ta koda teče, se nič drugega ne premakne.

Da ga najdemo, uporabimo zelo obrtniški trik: za vsako čakanje postavimo štoparico. Vsakič, ko koda na nekaj čaka, zabeležimo, koliko časa je minilo. Intervali, ki vsebujejo resnično čakanje, se razložijo sami; tisti, ki raste, ne da bi bilo na kaj čakati, pokaže na del kode, ki zaseda nit. Ni elegantno, a pripelje naravnost do bistva, in ko krivca najdemo, štoparice odstranimo.

Metoda na kratko

To je vrstni red, ki mu sledimo vsakič, ko se nam zdi kakšna stran počasna:

1. Zabeležimo vse poizvedbe, ki jih pool izvede med nalaganjem.
2. Ponovno jih izvedemo z explain analyze, da vidimo dejanske čase, ne namišljenih.
3. Primerjamo skupni čas strani s časom, porabljenim v podatkovni bazi.
4. Če je razlika velika, poiščemo sinhrono kodo s štoparico za vsakim čakanjem.
5. Šele tedaj se odločimo, kaj optimizirati.

Nobeden od teh korakov ne zahteva posebnih orodij. Zahteva le potrpežljivost, da se ne lotimo takoj rešitve.

Kaj odnesemo domov

Nauk je na koncu v eni vrstici: optimizira se tisto, kar smo izmerili, ne tisto, kar se zdi počasno.

Tako povedano se zdi samoumevno, v praksi pa gre proti nagonu. Ko je nekaj počasno, se želimo tega lotiti, in skušnjava, da gremo naravnost nad najverjetnejšega osumljenca, je močna, zlasti če je osumljenec videti kot krivec iz učbenika. V našem primeru je bil krivec iz učbenika nedolžen, pravi odgovorni pa sploh ni bil v kodi, ki smo jo napisali.

Odtlej je odgovor, kadar kdo od nas reče »ta stran je počasna, po mojem je kriva tista poizvedba«, vedno enak: prav, izmerimo jo.