Produkcja się dławiła, a serwera nie dało się podejrzeć

Prawdziwa praca produkcyjna, opisana bez podawania nazwy klienta. Wynik: nieregularne zwieszki pod obciążeniem → stabilnie.

Serwis społecznościowy z realnym ruchem od czasu do czasu zwieszał się pod obciążeniem — nieregularnie, tylko gdy wiele rzeczy działo się naraz, i nie do odtworzenia na żądanie. Do tego zero dostępu do shella i logów produkcji. Najtrudniejszy rodzaj awarii. Zbudowałem narzędzia, które złapały to na gorącym uczynku, a potem rozbroiłem źródła zatorów jedno po drugim.

Krótka wersja — dla każdego

Zbudowałem tę platformę od zera do produkcji i dziś ją utrzymuję. W pewnym momencie zaczęła się nieregularnie zwieszać — nie zawsze, tylko wtedy, gdy dużo aktywności nakładało się na siebie. Chwilę wisiała, potem wracała do normy. To najgorszy możliwy rodzaj problemu: nie da się go odtworzyć na żądanie, więc nie da się go złapać, patrząc w kod.

Przyczyną nie była jedna zepsuta rzecz. Było kilka zupełnie zwyczajnych operacji, które stawały się problemem dopiero, gdy zderzały się w czasie — sprzątanie w tle zakładające blokady akurat wtedy, gdy użytkownicy byli aktywni; ciężkie zapytanie, które na spokojnej bazie jest niegroźne, a na obciążonej rozciąga się do 25 sekund. Osobno — niewidoczne. Razem — zator.

Nie mogłem po prostu zajrzeć do środka — serwer był czarną skrzynką — więc zbudowałem własny rentgen: narzędzia, które nie tylko mierzą wolne akcje, ale robią zdjęcie całej sytuacji współbieżnej w momencie incydentu, pokazując, kto kogo blokuje. Dopiero to pokazało prawdę.

Z danymi na stole rozbroiłem wzmacniacze jeden po drugim, żeby nakładające się procesy przestały wywracać system: zbiłem zapytanie przy rejestracji z około 2 250 odpytań do jednego, zdjąłem ciężkie sprzątanie z żywej ścieżki, dołożyłem brakujący indeks, a resztę — blokady, brakujące limity czasu, pulę połączeń — ująłem w priorytetyzowany plan. Zostawiłem też spisany runbook, żeby następne spowolnienie było diagnozą na 10 minut zamiast tygodnia zgadywania.

To nie jest historia o jednym błędzie. To normalny etap w życiu każdego systemu, który urósł: rzeczy, które świetnie działały przy małym ruchu, zaczynają na siebie nachodzić przy dużym. Moja robota to sprawić, żeby to było widać, i to rozbroić — bez zgadywania i bez paniki.

Najtrudniejsze awarie to nie błędy w kodzie — to zachowania, które wychodzą dopiero, gdy wszystko dzieje się naraz. Moja robota to sprawić, żeby dało się je zobaczyć.

Pod maską — dla programistów

Django/ASGI (Channels) za PgBouncerem w trybie transaction, na managed Postgresie. Zero shella i czytelnych logów na produkcji, więc jedynym czytelnym sinkiem jest baza: cała diagnostyka pisze do tabeli DiagnosticLog, dostępnej po HTTPS dla superusera. Kluczowe — to nie były wolne pojedyncze requesty, tylko zatory przy współbieżności, więc narzędzia musiały łapać stan całego systemu w momencie incydentu, nie tylko czas jednego żądania.

Narzędzia, które zbudowałem, żeby cokolwiek zobaczyć

• Middleware wolnych requestów — loguje każdy request powyżej 1000 ms z duration_ms, liczbą zapytań i db_time_ms, więc od razu wiadomo, czy wąskim gardłem jest DB, czy Python. Wyłączony to MiddlewareNotUsed: zero narzutu.
• Dekoratory mierzące etapy — na ścieżce wysyłki obrazków (ruch WebSocket nie przechodzi przez HTTP middleware); zapisują etapy trwające 100 ms lub dłużej, albo błędy. Nagrywanie nigdy nie może zepsuć mierzonej ścieżki.
• Minutowy sampler pg_stat_activity — zadanie celery beat, które łapie łańcuchy blokad z zablokowanym zapytaniem i PID-em blokującego, oldest_xact_s, idle_in_tx. Plus raport zdrowia: odsetek martwych krotek, autovacuum, statement_timeout, top pg_stat_statements.
• Runbook — workflow na pierwszy dzień i ranking ryzyk poza tym incydentem (limity czasu w Celery i Postgresie, pula PgBouncera), żeby następny incydent był procedurą, a nie śledztwem od zera. Nie chodziło o załatanie jednego zapytania — chodziło o zmapowanie całej powierzchni awarii.

Co pokazały dane (współbieżność, nie pojedyncze zapytania)

• Sprzątanie w tle — niebatchowany delete wszystkich wiadomości pokoju z kaskadami oraz godzinny reconcile z podzapytaniami COUNT(*) — trzymało blokady na messenger_message i chatroom dokładnie wtedy, gdy użytkownicy byli aktywni. Stąd brały się losowo wieszające się wysyłki.
• N+1 przy rejestracji: .exists() na każdego kandydata w pętli = około 2 250 zapytań. Znośne na spokojnej bazie, 25 s pod obciążeniem. Zbite do jednego zapytania membership plus przecięcie zbiorów.
• Autovacuum nigdy nie odpalił się na największych tabelach. Raport zdrowia pokazał last_autovacuum = NEVER od czerwcowego resetu statystyk na tabeli akcji (5,1 GB), wiadomości (3 GB) i kilku kolejnych. Mechanizm: progi autovacuum są procentowe (tu 5% tabeli), więc przy dziesiątkach milionów wierszy sprzątanie czekało na miliony martwych krotek — a codzienny delete() całej tabeli powiadomień dokładał ich co noc. Efekt: sama tabela akcji generowała 87% odczytów z dysku na produkcji. Wyłapał to agent, któremu dałem do przejrzenia raporty zdrowia z samplera — ja patrzyłem w łańcuchy blokad i tego nie zauważyłem. Do kompletu z tego samego raportu: 157 GB plików tymczasowych od czerwca (za małe work_mem), idle_in_transaction_session_timeout ustawiony na 24 godziny, czyli żaden, i statement_timeout równy zero.

Poprawki

Ciężkie delete’y zbatchowane i przeniesione do Celery; pokrywający indeks na photo_request; N+1 zbite do jednego zapytania; wyszukiwarka ofert przeniesiona na Postgres full-text (GIN) plus trigram fuzzy zamiast LIKE. Na tabelę akcji: retencja zamiast wiecznego wzrostu — archiwum bez relacji dla raportów, przenoszenie partiami po 5 tysięcy wierszy z pauzą, wznawialne, z osłoną na wiersze, do których odwołuje się księga transakcji (klucze obce znalezione, jak to zwykle bywa, w trakcie). Na klonie produkcji: 79% tabeli do zdjęcia. Osobne, niższe progi autovacuum dla tych tabel ustawiłem z konsoli bezpośrednio na produkcyjnej bazie — od tej pory sprzątanie na nich faktycznie się odpala.

Masz system, który zwiesza się pod obciążeniem? Napisz.