Három szám, amit félreolvasol az EXPLAIN ANALYZE kimenetéből

Múltkor egy nested loop join belső Index Scan sorát bámultam vagy tíz percig, mert az actual time=0.002..0.003 alapján az volt az érzésem, hogy az a sor gyakorlatilag ingyen van. Aztán észrevettem a loops=1639 részt a sor végén, és hirtelen már nem volt annyira ingyen. Egy jó félórát a rossz csomóponton töltöttem, mert az EXPLAIN ANALYZE kimenetét úgy olvastam, mint egy számlát, ahol minden sor a végösszeget mutatja. Nem azt mutatja.

Ez a cikk arról szól, hogy az EXPLAIN ANALYZE három ponton vezet félre – nem szándékosan, csak a dokumentáció ezt sosem magyarázza el az első olvasásra, a legtöbb tutorial pedig annyit mond: „futtasd le, és nézd meg, hol lassú”. A számok nem a levegőből jöttek: felhúztam egy Postgres 17-es konténert, betöltöttem 20 ezer rendelést és 80 ezer rendeléssort, és valódi EXPLAIN (ANALYZE, BUFFERS) kimeneteket futtattam le, hogy legyen mihez viszonyítani.

Diagram egy Postgres EXPLAIN ANALYZE plan fáról: a Nested Loop szülő csomópont Buffers értéke a két gyermek csomópont (Seq Scan és Index Scan) összegzett buffer- és időadataiból áll össze, az Index Scan 1639 futásának átlagideje pedig a lekérdezés futásidejének több mint felét teszi ki

Az actual time egy átlag, nem összeg

A tesztlekérdezés egyszerű: az utolsó 30 nap rendeléseit összekapcsoltam a rendeléssorokkal. Nested loopot kényszerítettem ki (SET enable_hashjoin = off, SET enable_mergejoin = off – csak a plan megnézéséhez, produkcióban persze nem hagyod bekapcsolva), hogy legyen egy csomópont, amit sokszor hív meg a motor:

Nested Loop  (actual time=0.032..8.380 rows=6556 loops=1)
  Buffers: shared hit=9822 read=121
  ->  Seq Scan on orders o  (actual time=0.006..3.021 rows=1639 loops=1)
        Filter: (created_at > (now() - '30 days'::interval))
        Rows Removed by Filter: 18361
        Buffers: shared hit=109
  ->  Index Scan using idx_order_items_order_id on order_items oi
        (actual time=0.002..0.003 rows=4 loops=1639)
        Index Cond: (order_id = o.id)
        Buffers: shared hit=9713 read=121
Planning Time: 1.325 ms
Execution Time: 8.625 ms

Az Index Scan sor loops=1639-et ír ki, mert a nested loop minden külső sorra (minden megfelelő rendelésre) újra lefuttatja a belső index-keresést. A PostgreSQL dokumentáció pontosan leírja, mit jelent ilyenkor az actual time: „a loops érték a csomópont végrehajtásainak teljes számát adja meg, az actual time és rows értékek pedig egy végrehajtásra vonatkozó átlagok […] Szorozd meg a loops értékkel, hogy megkapd a csomópontban tényleg eltöltött teljes időt.” Tehát a 0,003 ms nem az, amit hittem: 0,003 ms × 1639 ≈ 4,92 ms – ez a teljes 8,625 ms futásidő több mint fele. Pont az a sor volt a bűnös, amit én a legkevésbé gyanúsítottam, mert a kiírt szám alapján nullának tűnt.

A Buffers szám nem csak a sajátod

Nézd meg még egyszer a fenti kimenetet: a gyökér Nested Loop csomópont Buffers: shared hit=9822 read=121-et mutat. A Seq Scan gyereke hit=109-et, az Index Scan gyereke hit=9713 read=121-et. Nem véletlen, hogy 109 + 9713 = 9822, és 0 + 121 = 121 – a dokumentáció szerint „a kiírt buffer-számok a csomópont és minden gyermek-csomópontjának nem különálló (non-distinct) hit/read/dirtied/written értékeit mutatják” (using-explain.html). Minden szülő automatikusan magába szívja az összes leszármazottja buffer-forgalmát.

Ez pontosan úgy működik, mint egy profiler flame graph-jában a total time egy hívási csúcson: a kiírt szám a teljes részfát tartalmazza, nem a csomópont saját, egyedi munkáját. Ha egy bonyolultabb terven össze akarod hasonlítani, melyik csomópont „csinálta a piszkos munkát”, a gyerekek összegét ki kell vonnod a szülő számából – különben egy tíz szintes plan tetején mindig azt fogod hinni, hogy a legfelső csomópont a felelős mindenért, miközben az valójában csak összeadja, amit alatta mindenki elvégzett.

Amit a sima EXPLAIN ANALYZE egyáltalán nem mér

A harmadik, és talán a legmeglepőbb pont: az Execution Time alapból nem tartalmazza azt az időt, amíg a Postgres a sorokat szövegre vagy bináris formátumra alakítja, és elküldi a kliensnek. Ugyanazt a lekérdezést lefuttattam egy nagyobb, 80 ezer soros eredménnyel, előbb sima EXPLAIN (ANALYZE, BUFFERS)-szel, majd a Postgres 17-ben megjelent SERIALIZE opcióval:

-- EXPLAIN (ANALYZE, BUFFERS)
Execution Time: 24.533 ms

-- EXPLAIN (ANALYZE, BUFFERS, SERIALIZE TEXT)
Serialization: time=31.097 ms  output=4915kB  format=text
Execution Time: 63.283 ms

Ugyanaz a lekérdezés, ugyanaz a plan – csak az egyik mérés 24,5 ms-nál lezárja a történetet, a másik megmutatja, hogy a sorok szövegessé alakítása önmagában 31 ms, ami több, mint a teljes join végrehajtása. A SERIALIZE opció pontosan ezt méri: „a lekérdezés kimeneti adatainak szerializálási költségét, azaz azt, hogy szöveg- vagy bináris formátumra alakítva elküldje a kliensnek”. Ez a PostgreSQL 17-ben jelent meg – ha régebbi verziót futtatsz, ezt a részt egyszerűen nem látod az EXPLAIN-ben, csak kívülről, az alkalmazásod oldaláról mérve. Ez a klasszikus „a lekérdezés 25 ms az adatbázisban, de az endpoint 90 ms” érzés egyik valódi, mérhető oka – és semmi köze a hálózati késleltetéshez.

Bónusz: maga a mérés sem ingyenes

Van egy negyedik csavar is, amiről a dokumentáció Caveats szakasza ír: az ANALYZE minden csomópont-belépésnél és -kilépésnél lekérdezi a rendszerórát, és ez „jelentős overheadet adhat, különösen azokon a gépeken, ahol a gettimeofday() hívás lassú” (using-explain.html). A mi 1639-szer meghívott index-keresésünknél ez 1639 óralekérdezést jelent – egyenként elhanyagolható, összesítve már nem feltétlenül. A pg_test_timing eszközzel megmérheted, mennyibe kerül ez a saját gépeden; ha sokat, a TIMING off opcióval kikapcsolhatod az időmérést, és csak a sorszámokra, buffer-adatokra hagyatkozol.

Mikor számít ez neked

Ha egy nested loop belsejében kis actual time-ot látsz, mindig nézd meg a loops-t is, és szorozz – főleg ha a szám tízezres nagyságrendű.
A BUFFERS-t érdemes majdnem mindig bekapcsolni (az ANALYZE ezt implicit módon meg is teszi), de a „self time” gondolkodáshoz neked kell kivonni a gyerekek értékeit.
A SERIALIZE-t nem automatizmusba tenném, mert minden futásra extra overheadet jelent – de amikor egy „gyors lekérdezés, lassú endpoint” jelenséget vizsgálok nagy result setekkel (riportok, exportok, ORM ami mindent egyszerre lehúz), az első dolog, amit bekapcsolok.

Ezt a hármat érdemes megtanulni, mert semelyiket nem lehet kitalálni, csak elolvasni vagy kipróbálni – és ha egyszer tudod, soha többé nem fogsz ujjal mutatni egy 0,003 ms-os sorra, mielőtt megnézed, hányszor futott le.