2 sekundy checkoutu, których nie było widać w kodzie: Postgres JIT w Medusa.js

Case study z produkcji Artovnii - jak domyślne ustawienie Postgresa, o którym nikt nie wiedział, że jest włączone, dokładało 2 sekundy do każdej mutacji koszyka.

TL;DR

Refaktor flow checkoutu w Artovnii, usunięcie manualnego potwierdzania każdego kroku, na rzecz zautomatyzowanego, reaktywnego działania, ujawnił, że był wolny na produkcji (dodanie do koszyka: 2,4–3,7 s, wybór dostawy: 2,5–2,8 s), a lokalnie te same operacje, te same dane poniżej pół sekundy. Winowajcą nie był kod, nie brakujący indeks i nie wolumen danych. Był nim Postgres JIT mechanizm kompilacji zapytań, który przy błędnej estymacji liczby wierszy potrafi kosztować więcej niż zyskuje. W moim przypadku: kompilacja trwała ~2 sekundy, a samo zapytanie wykonywało się w 1,4 milisekundy.

W dodatku nikt tego JIT-a świadomie nie włączył. To domyślne ustawienie Postgresa od wersji 12 i nie ma go gdzie zobaczyć, dopóki nie zapytasz bazy wprost. Poza tym lokalnie działam na Windows z wirtualnym obrazem linux, a produkcja to Railway (Linux, oficjalny obraz z llvmjit)

Objaw

Metryki z produkcji mówiły same za siebie:

• POST /store/carts/.../line-items (dodanie do koszyka) — 2,4–3,7 s
• POST /store/carts/.../shipping-methods (wybór dostawy) — 2,5–2,8 s
• POST /store/carts (utworzenie koszyka, bez promocji) — 255 ms, w tym baza: 11 ms

Ten ostatni wiersz jest kluczowy. Tworzenie koszyka, czyli operacja bez logiki promocyjnej, było szybkie. Wszystko, co dotykało przeliczenia promocji, było wolne. To zawęziło problem, zanim jeszcze uruchomiłem EXPLAIN.

Lokalnie te same żądania z tymi samymi (albo bardzo zbliżonymi) danymi wykonywały się poniżej pół sekundy. Ten sam kod. Ta sama liczba promocji, reguł, wartości. Więc to nie był algorytm ani N+1 w sensie klasycznym, to było coś środowiskowego.

Zanim trafiłem na właściwy trop

Zanim w ogóle sięgnąłem po EXPLAIN, zrobiłem to, co wydawało się najbardziej oczywiste: spróbowałem poprawić odczuwalną płynność checkoutu od strony frontu. Przycisk "Dodaj do koszyka" przestał czekać na pełną odpowiedź backendu i pokazywał potwierdzenie natychmiast, korzystając ze stanu, który i tak trafiał już do globalnego store koszyka. Przejście z sekcji adresu do sekcji dostawy zaczęło się dziać optymistycznie, zamiast czekać na twarde potwierdzenie zapisu. Sekcja dostawy dostała skeleton zamiast pustego ekranu na czas oczekiwania.

Te zmiany były warte zrobienia same w sobie, checkout przestał sprawiać wrażenie zawieszonego, użytkownik widział reakcję na swoje działanie od razu. Ale to były poprawki percepcji, nie rzeczywistego czasu. Krok odpowiedzialny za przeliczenie promocji nadal trwał te same ~2,5 sekundy po stronie serwera, obojętnie jak sprytnie interfejs to maskował. Optymistyczny UI skraca czas, w którym użytkownik czeka bezczynnie, nie skraca czasu, którego serwer faktycznie potrzebuje. To dwa osobne pomiary i łatwo je pomylić, jeśli patrzy się tylko na to, "jak szybko to teraz wygląda".

Dopiero kiedy przestałem próbować ukrywać wolność interfejsem i zacząłem ją mierzyć bezpośrednio na backendzie, problem przestał być tajemnicą.

Jak to namierzyłem

Mam w projekcie panel z instrumentacją per-krok (timeStep), który rozbija czas każdego żądania na etapy przetwarzania. Dla najbardziej dotkniętego endpointu wyglądało to tak:

POST /store/carts/.../shipping-methods    total 2.70s
  promotion_refresh   2.57s (95%)
  final_graph          50ms (2%)
  add_method           36ms (1%)
  resolve_cart         29ms (1%)
  loyalty                8ms (0%)

I kolejne dwa żądania, ten sam wzorzec:

total 2.79s → promotion_refresh 2.65s (95%)
total 2.53s → promotion_refresh 2.38s (94%)

Jeden krok, promotion_refresh, konsekwentnie zjadał 94–95% całego czasu żądania. Reszta procesu, rozwiązanie koszyka, dodanie metody dostawy, lojalność, budowa finalnego grafu, to razem kilkadziesiąt milisekund. Zero podejrzeń w tamtą stronę.

Krok niżej: telemetria zapytań SQL dla tego samego żądania pokazała db.query.count=75, db.query.total_ms≈2409, db.query.max_ms≈2068. Czyli spośród 75 zapytań wykonanych przy przeliczaniu promocji, jedno pojedyncze zapytanie odpowiadało niemal za cały czas.

Slow-query log wskazał je precyzyjnie, zapytanie ładujące promocje wraz z całym drzewem relacji: metodę aplikacji, reguły docelowe, reguły "kup X", wartości reguł, kampanię, budżet kampanii. Typowy, szeroki SELECT z kaskadą LEFT JOIN, jaki generuje MikroORM pod spodem Medusy przy ładowaniu grafu obiektów.

Wtedy sięgnąłem po EXPLAIN (ANALYZE, BUFFERS) bezpośrednio na produkcji i tu zaczyna się właściwa historia.

Winowajca: Postgres JIT

Plan zapytania pokazał na końcu sekcję, której nie widuje się w typowym debugowaniu:

JIT:
  Functions: 107
  Timing: Generation 8.7 ms, Inlining 23.1 ms,
          Optimization 1212.2 ms, Emission 810.3 ms,
          Total 2054.3 ms
Execution Time: 2056.2 ms

Z 2056 ms całkowitego czasu wykonania, 2054 ms to była sama kompilacja JIT. Rzeczywiste skanowanie tabel i joiny, widoczne w poszczególnych węzłach planu, zajmowały poniżej 2 ms. Innymi słowy: Postgres poświęcił 99,9% czasu na kompilowanie kodu do wykonania zapytania, które i tak było błyskawiczne.

Dla porównania, to samo zapytanie z wyłączonym JIT-em:

Settings: jit = 'off'
Execution Time: 1.453 ms

Ten sam plan zapytania. Te same węzły, te same koszty, te same bufory. Jedyna różnica: 2056 ms kontra 1,4 ms.

Dlaczego JIT się w ogóle uruchomił

Postgres nie kompiluje każdego zapytania, to by było bez sensu przy prostych operacjach. Odpala JIT dopiero, gdy szacowany koszt planu przekroczy próg (jit_above_cost, domyślnie 100 000). Jeśli koszt jest jeszcze wyższy, dokłada droższe warianty: optymalizację LLVM i inlining funkcji (progi jit_optimize_above_cost i jit_inline_above_cost, domyślnie po 500 000).

Problem w tym zapytaniu: planer estymował wynik pośredniego joina na 1 151 348 wierszy. Realnie wracało 103. Błąd rzędu jedenastu tysięcy razy. Estymowany koszt całego planu wyszedł na ponad 2,4 miliona, grubo ponad wszystkie trzy progi naraz, więc Postgres odpalił JIT na pełnej mocy: kompilację, optymalizację i inlining 107 funkcji, dla zapytania które realnie zwraca sto kilka wierszy w niecałą milisekundę.

Skąd tak absurdalnie zawyżona estymacja? Zapytanie ma kaskadę około dziesięciu LEFT JOIN, w tym kilka relacji jeden-do-wielu przechodzących przez tabele pomostowe, plus warunek WHERE z alternatywą po dwóch różnych kolumnach (code IN (...) OR id IN (...)). Model kosztu Postgresa zakłada niezależność statystyczną między kolejnymi joinami w łańcuchu, mnoży selektywności przez siebie zamiast liczyć ich faktyczną korelację. Im dłuższy łańcuch joinów, tym bardziej ten błąd narasta wykładniczo. To nie jest kwestia nieaktualnych statystyk, to fundamentalne ograniczenie planera przy szerokich, wielotabelowych zapytaniach, jakie regularnie generują ORM-y ładujące złożone grafy obiektów.

Dla niewtajemniczonych: czym właściwie jest ten JIT

Jeśli nie siedzisz w bazach danych na co dzień, warto rozjaśnić, o co tu w ogóle chodzi, bo na pierwszy rzut oka brzmi to jak coś, co powinno tylko przyspieszać.

Normalnie Postgres wykonuje zapytanie, interpretując jego plan krok po kroku, trochę jak ktoś czytający przepis na głos i wykonujący każdą instrukcję osobno, za każdym razem od nowa. JIT (Just-In-Time compilation) to próba przyspieszenia tego: zamiast interpretować powtarzalne fragmenty (np. warunki filtrowania, odczyt wartości z wiersza), Postgres kompiluje je do natywnego kodu maszynowego, korzystając z LLVM, tego samego frameworka kompilatorowego co Clang czy Rust.

To ma sens przy ciężkich, analitycznych zapytaniach: agregacjach na milionach wierszy, złożonych obliczeniach powtarzanych setki tysięcy razy. Tam koszt kompilacji (rzędu dziesiątek-setek milisekund) rozkłada się na ogromną liczbę wykonań i realnie się opłaca.

Problem: sam koszt kompilacji trzeba ponieść z góry, niezależnie od tego, ile faktycznie zapytanie robi. Jeśli Postgres źle oszacuje, że zapytanie będzie "ciężkie" tak jak w moim przypadku, gdzie spodziewał się miliona wierszy zamiast stu, kompiluje kod tak, jakby to była duża analityczna operacja. A potem to zapytanie i tak wykonuje się w mikrosekundach, bo w rzeczywistości nigdy nie było ciężkie. Zapłaciłem za budowę autostrady, żeby przejechać nią raz, dwadzieścia metrów.

Czemu tego nie widać "tak po prostu" w ustawieniach

Tu pojawia się pytanie, które nasuwa się samo: skoro to takie problematyczne, to po co ktoś to włączył?

Odpowiedź jest mniej satysfakcjonująca niż "ktoś popełnił błąd konfiguracyjny": nikt tego nie włączył. Postgres nie ma czegoś w rodzaju zakładki ustawień z przełącznikami. Cała konfiguracja żyje w płaskim pliku tekstowym (postgresql.conf) z kilkuset parametrami, bez interfejsu, bez opisów w UI, bez niczego, co powiadomiłoby administratora "hej, ta funkcja jest aktywna i może wpłynąć na twoje zapytania".

Do tego dochodzi dodatkowa pułapka przy czytaniu tego pliku. Zakomentowana linia w postgresql.conf:

#jit = on    # allow JIT compilation

nie oznacza "wyłączone". Oznacza: nikt tego nie nadpisał, więc obowiązuje wbudowana wartość domyślna, a tą wartością jest on. To akurat zmyliło nawet narzędzie diagnostyczne AI, którego użyłem po drodze do sprawdzenia configu na hostingu, odczytało #jit = on jako dowód, że JIT jest domyślnie wyłączony, bo linia jest zakomentowana. Jeśli nawet automatyczny agent wpadł w tę pułapkę interpretacji, tym bardziej nie jest to coś oczywistego dla człowieka przeglądającego plik pobieżnie.

Platformy hostingowe typu Railway świadomie nie owijają Postgresa w warstwę UI z ustawieniami, dostajesz "vanilla" obraz, zero konfiguracji na wierzchu, więc dziedziczysz każdy domyślny parametr projektu Postgres bez zmian, łącznie z tymi, które zmieniły się między wersjami. A JIT to dokładnie taki przypadek: w Postgresie 11 domyślnie było off (funkcja była nowa), od Postgresa 12 domyślnie jest on. Ja byłem na Postgresie 16. Dostałem fabryczne ustawienie z czterech kolejnych wersji major, bez żadnej ludzkiej decyzji po drodze.

Jedyny sposób, żeby się o tym dowiedzieć, to zapytać bazę wprost:

SELECT name, setting, source FROM pg_settings WHERE name = 'jit';

Kolumna source = 'default' mówi jasno: to wbudowana wartość, nikt jej nigdzie nie nadpisał.
Czy normalnie ktoś tam zagląda? Większość web developerów nigdy nie miała powodu, żeby myśleć o bazie inaczej niż jako o czarnej skrzynce za connection stringiem.
Tutaj wyjątkową koniecznością okazał się bardzo rozbudowany LEFT JOIN medusy.

Fix: jak wyłączyć JIT

Wyłączenie JIT-a na poziomie bazy:

ALTER DATABASE "nazwa_bazy" SET jit = off;

To nie jest zmiana pliku konfiguracyjnego, trafia do katalogu systemowego Postgresa i nie wymaga restartu samego serwera bazy. Działa jednak tylko dla nowych połączeń. Tu jest pierwsza pułapka wdrożeniowa: jeśli aplikacja trzyma pulę już otwartych połączeń (a każdy ORM to robi), te połączenia mają w sobie stare ustawienie do końca swojego życia w puli. Zmiana w bazie bez restartu backendu nic realnie nie zmienia, trzeba zredeployować albo zrestartować aplikację, żeby wymusić nowe połączenia.

Druga pułapka: ALTER DATABASE ... SET to ręczna zmiana na konkretnej instancji bazy, niezapisana nigdzie w kodzie ani migracjach. Jeśli baza kiedykolwiek zostanie odtworzona od zera, nowe środowisko, disaster recovery, migracja do innego hostingu, to ustawienie znika bez śladu. Bezpieczniejsza w dłuższej perspektywie jest wersja, która podróżuje razem z konfiguracją aplikacji, jako parametr startowy w connection stringu:

postgresql://user:pass@host:port/db?options=-c%20jit%3Doff

(czyli zakodowane w URL -c jit=off, przekazywane do libpq przy każdym połączeniu, niezależnie od tego, czy baza pamięta cokolwiek).

Jest jeszcze wariant pośredni, dla kogoś kto nie chce całkowicie rezygnować z JIT na wypadek prawdziwie ciężkich zapytań analitycznych w przyszłości: zamiast wyłączać, drastycznie podnieść próg aktywacji (jit_above_cost), tak żeby błędnie oszacowane zapytania transakcyjne nigdy go nie przekraczały, a faktycznie ciężkie zapytania owszem.

Efekt

Twardych liczb przed/po z ruchu produkcyjnego nie mam, po wdrożeniu poprawki czasy tych żądań spadły poniżej progu, przy którym mój panel w ogóle rejestruje żądanie jako "wolne". To akurat samo w sobie jest dość wymowne: endpoint, który wcześniej systematycznie trafiał na listę najwolniejszych żądań z czasem rzędu 2,5–3,7 sekundy, po fixie po prostu przestał się tam pojawiać.

To, co mam twardo zmierzone, to sam EXPLAIN na identycznym zapytaniu: 2056 ms z JIT-em, 1,4 ms bez. Reszta różnicy między lokalnym a produkcyjnym środowiskiem to już nie JIT, tylko realny round-trip sieciowy między aplikacją a bazą przy 75 zapytaniach składających się na przeliczenie promocji, osobny temat do optymalizacji.

Wnioski

Jeśli używasz ORM-a, który generuje szerokie zapytania z wieloma JOIN przy ładowaniu grafu obiektów (MikroORM, TypeORM, Prisma z zagnieżdżonym include), masz młodą bazę z niewielką liczbą wierszy w kluczowych tabelach i jesteś na Postgresie 12 lub nowszym, warto to sprawdzić, zanim spędzisz czas na szukaniu winy w indeksach czy N+1:

EXPLAIN (ANALYZE, BUFFERS) <twoje zapytanie>;

Jeśli w wyniku pojawia się sekcja JIT: z czasem porównywalnym albo większym niż realny czas wykonania zapytania widoczny w węzłach planu, to nie jest twoje zapytanie, które jest wolne. To kompilacja, która nie powinna była się w ogóle odpalić.

Ten problem był czysto infrastrukturalny/konfiguracyjny, nie wymagał zmiany ani jednej linijki logiki aplikacji. Czasem najdroższy bug w checkoucie nie jest w kodzie checkoutu.