Mój VPS był online. Potem Linux zaczął czekać 18 sekund na odczyt z dysku

Zanim przejdę do debugowania, chcę wyjaśnić jedną rzecz: ogólne wrażenie po FDCServers nie jest u mnie negatywne. To nie jest recenzja zachęcająca do unikania tego dostawcy ani ocena całej jego infrastruktury. Miałem jeden VPS, w jednym okresie, z jednym wyjątkowo trudnym problemem.

Przez dłuższy czas VPS działał normalnie i obsługiwał rzeczywisty ruch produkcyjny. Potem coś się zmieniło. Zwykłe requesty zaczęły trwać absurdalnie długo. Strony otwierały się powoli, a czasami przestawały otwierać się całkowicie. Innym razem maszyna wracała do normalnego stanu, zanim zdążyłem dobrze zbadać awarię.

W najgorszym momencie zanotowałem:

CPU iowait:       97–100%
I/O PSI full:     ~95–98%
read latency:     up to 18.7 seconds
flush latency:    up to 53.6 seconds
I/O queue depth:  128+

Nginx działał. Backend działał. VM była online. A mimo to prawie żadna użyteczna praca nie posuwała się naprzód.

Awaria produkcyjna była frustrująca, ale samo debugowanie naprawdę sprawiało mi przyjemność. Właśnie za takie sytuacje lubię Linuxa: maszyna może z zewnątrz wyglądać na żywą, a kilka niezależnych interfejsów kernela pokazuje, gdzie dokładnie zatrzymał się użyteczny postęp. Ten artykuł jest o podążaniu za tymi sygnałami, a nie o ocenianiu, czy FDCServers jest dobrym lub złym dostawcą.

active (running) okazało się znaczyć bardzo niewiele

Zacząłem od oczywistych kontroli:

top
free -h
df -h
systemctl status nginx

W zdrowych okresach widziałem mniej więcej:

D-state processes: 0
CPU iowait:        ~0%
disk latency:      ~2–4 ms
I/O PSI some:      0.04
I/O PSI full:      0.04

Gdybym połączył się tylko wtedy, łatwo uznałbym VPS za zdrowy. Potem wracał normalny ruch i stan maszyny mógł całkowicie się zmienić. Zdrowy snapshot systemu z problemem okresowym niewiele mówi o stanie podczas awarii. Musiałem zbierać dowody wtedy, gdy problem rzeczywiście występował.

Próbka iostat, która zmieniła kierunek śledztwa

r_await = 18744 ms
f_await = 53561 ms
aqu-sz  = 128.54
util    ≈ 100%
read    = 88 KB/s

Zakończone odczyty trwały około 18,7 sekundy. Operacje flush zajmowały około 53,6 sekundy. Średnia kolejka przekraczała 128, a użyteczny throughput odczytu wynosił tylko 88 KB/s.

Nie wyglądało to na storage, który jest po prostu zajęty, bo sprawnie obsługuje wymagający workload. Wirtualna ścieżka blokowa była praktycznie wysycona, a jednocześnie kończyła bardzo mało pracy. Wysoki utilization sam w sobie nie jest awarią, ale w połączeniu z ogromną latencją, dużą kolejką, zablokowanymi taskami, minimalnym throughputem i nieudanymi requestami daje zupełnie inny obraz.

Przestałem traktować iowait jako diagnozę

blocked processes: 4–9
CPU iowait:        97–100%
CPU idle:          0%

Kusi, by podsumować to jako „CPU spędzał 100% czasu na czekaniu na dysk”. Intuicyjnie jest to użyteczne, ale accounting Linuksa jest bardziej złożony, a iowait nie jest bezpośrednim pomiarem dysku. Traktowałem go więc jako jeden objaw i szukałem niezależnych dowodów.

PSI pokazało, że I/O zatrzymuje użyteczną pracę

cat /proc/pressure/io

Podczas jednego z ciężkich okresów:

some avg10=99.14
full avg10=95.55

W późniejszych reprodukcjach full zbliżało się do 98%. W I/O pressure some oznacza czas, kiedy co najmniej część niebezczynnej pracy jest zablokowana przez I/O, a full czas, kiedy wszystkie niebezczynne taski są jednocześnie zablokowane przez I/O. Wartość bliska 100% mówi znacznie więcej niż „dysk jest zajęty”: workload prawie nie dostaje okazji, by wykonać postęp.

D-state sprawił, że przestałem obwiniać jeden proces

ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'

Krótka obecność jednego procesu w D-state nie dowodzi problemu ze storage. Ważne było, które procesy blokowały się razem. Widziałem niezależne komponenty, między innymi jbd2, systemd-journald, workery Nginx, procesy cache Nginx i inną aktywność filesystemu.

Jeśli blokuje się tylko backend, sprawdzam backend. Jeśli tylko Nginx, sprawdzam Nginx. Ale gdy Nginx, system journal i thread journalu EXT4 jednocześnie przestają robić postęp, znacznie ciekawsza staje się ich wspólna zależność. W tym przypadku był to filesystem i ścieżka storage poniżej niego.

Stosy kernela pokazały kolejną warstwę

Thread journalu EXT4 pojawiał się w ścieżkach:

wait_on_buffer
jbd2_log_wait_commit
jbd2_journal_commit_transaction

Workery Nginx pojawiały się w zwykłych ścieżkach odczytu filesystemu:

folio_wait_bit_common
filemap_read
generic_file_read_iter
ext4_file_read_iter
vfs_read
pread64

W pewnym momencie kernel zgłosił:

INFO: task nginx blocked for more than 122 seconds.

systemctl status nginx wciąż mógł pokazywać active (running). Obie informacje były prawdziwe: proces istniał, ale task Nginx przez ponad dwie minuty nie potrafił zakończyć użytecznej pracy. Działający proces nie oznacza zdrowej usługi.

Najczystszy eksperyment trwał około trzech milisekund

Request przez Nginx nie dochodził:

HTTP=000
SSL connection timeout

Potem ominąłem Nginx i połączyłem się bezpośrednio z lokalnym backendem:

connect = 0.000423 s
TTFB    = 0.003063 s
total   = 0.003139 s

Około 3 ms. Dokładny status HTTP nie miał w tym teście znaczenia. Backend przyjmował połączenie, wykonywał request i niemal natychmiast zwracał odpowiedź. W tym samym czasie workery Nginx były widoczne w ścieżkach odczytu EXT4.

application execution       → progressing normally
filesystem-backed web path  → not progressing normally

Im głębiej patrzyłem, tym mniej wiarygodne było wyjaśnienie na poziomie aplikacji.

Ten sam VPS potrafił załamać się w około 30 sekund

Przed jedną reprodukcją:

HTTP:          200
D-state:       0
CPU iowait:    3%
r_await:       ~1.18 ms
I/O PSI full:  ~2.95%

Około pół minuty później:

D-state:       4
CPU iowait:    91%
CPU idle:      0%
I/O PSI some:  86.11%
I/O PSI full:  78.02%
r_await:       236.50 ms
HTTP:          000

Później jeszcze gorzej:

CPU iowait:    96–100%
I/O PSI full:  ~98%
HTTPS queue:   512
HTTP:          000

Po zdjęciu workloadu odwrotne przejście mogło nastąpić szybko:

D-state:      0
CPU iowait:   6%
r_await:      ~0.98 ms
queue depth:  ~0.07
HTTP:         200

Dlatego okresowe problemy infrastrukturalne są tak trudne. Dziesięć minut później ktoś może na tej samej VM uczciwie zmierzyć latencję poniżej milisekundy. Nie musi się mylić; patrzy po prostu na inny stan.

Zerowa latencja może być zaskakująco mało pomocna

Widziałem także interwał iostat z r_await = 0, mimo że system był ewidentnie niezdrowy: wysokie iowait, procesy w D-state, oczekujące I/O, prawie brak zakończonych odczytów i niemal zerowy throughput.

Średnie liczone z zakończonych operacji stają się mniej informacyjne, gdy w oknie pomiarowym prawie nic się nie kończy. Zero nie musi oznaczać, że odczyty skończyły się natychmiast; może po prostu brakować wystarczającej liczby zakończonych operacji, by opisać te, które nadal wiszą.

Od tego czasu patrzę razem na latency, IOPS, throughput, queue depth, in-flight I/O, D-state, PSI i rzeczywiste kończenie requestów.

Jeden incident zamienił się w znacznie dłuższe śledztwo z supportem

Pierwszy ciężki przypadek pokrył się z zaplanowanym backupem na pierwotnej infrastrukturze, a FDCServers potwierdził, że backup działał. To było rozsądne możliwe wyjaśnienie. Później jednak odtworzyłem ten sam rodzaj storage stall już po zakończeniu backupu i poza jego pierwotnym oknem.

Problem wracał przez kilka dni. Podczas jednego incidentu VPS był później niedostępny przez 4 godziny, 41 minut i 15 sekund według moich logów. Nie mogę udowodnić, że storage stall sam spowodował wejście VM w ten stan; wymagałoby to informacji host-side, których nie miałem.

application
    ↓
Linux VFS
    ↓
EXT4
    ↓
virtual block device
    ↓
?

Za znakiem zapytania mogą znajdować się wirtualizacja, kolejki hosta, sieć storage, distributed storage, fizyczne nośniki, schedulery i inne systemy niewidoczne z guest. Mogłem zobaczyć, gdzie problem się ujawniał, ale nie jego fizyczną root cause.

FDCServers eskalował sprawę wewnętrznie i ostatecznie przeniósł VPS na inny node. Po migracji zarejestrowałem kolejny ciężki storage stall z poziomu guest. To nie dowodzi, że każdy node FDCServers miał problem ze storage. Dowodzi tylko, że z mojego punktu widzenia problem mojego VPS nie został wyeliminowany.

Dlaczego nadal nie uważam tego za negatywną historię o FDCServers

Łatwo zamienić incident infrastrukturalny w wyrok na całego dostawcę. Nie chcę tego robić.

Rozróżniam usługę, której normalny model działania jest fundamentalnie niezgodny z moim workloadem, od okresowego problemu infrastrukturalnego, który trudno odtworzyć i długo izolować. Moje doświadczenie z FDCServers wyglądało bardziej jak ten drugi przypadek.

Przed awarią VPS działał normalnie i obsługiwał rzeczywisty ruch produkcyjny. Support badał problem i próbował go rozwiązać. W końcu miałem wystarczająco dużo dowodów, by zdecydować, że nie chcę dalej uzależniać produkcji od tego konkretnego VPS.

Poprosiłem FDCServers o anulowanie usługi i refund. Zwrócili mi pieniądze. To ma znaczenie dla mojego ogólnego wrażenia.

Nie testowałem ponownie ich obecnej infrastruktury, więc nie mogę powiedzieć, jak VPS FDCServers działa dzisiaj. Nie mam też dowodów, że problem mojej instancji był reprezentatywny dla całej platformy. Infrastruktura stale się zmienia. Nie zamieniam jednego trudnego incidentu na jednym VPS w trwałą ocenę całego providera. Nie rekomenduję też tutaj FDCServers; po prostu opisuję, co mi się wydarzyło.

Najbardziej podobał mi się sam Linux

Downtime był frustrujący, ale samo śledztwo było ciekawe. Naprawdę podobało mi się odnajdywanie granicy problemu.

Nie miałem wystarczającej widoczności, by znaleźć fizyczną root cause. Pytanie, na które chciałem odpowiedzieć, było prostsze: na której warstwie przestaje kończyć się użyteczna praca?

Backend odpowiadał w około trzy milisekundy. Nginx raportował stan active, a kernel stacks pokazywały oczekiwanie w odczytach EXT4. vmstat pokazywał zablokowane procesy i ekstremalny I/O wait. PSI pokazywało, że I/O stalls pochłaniają niemal cały workload. iostat pokazywał ogromną latencję i queueing. D-state pokazywał niezwiązane ze sobą procesy czekające jednocześnie. Kernel zgłosił nawet task Nginx zablokowany przez ponad 122 sekundy.

Żadna pojedyncza metryka nie rozwiązała incidentu. Zrobiła to zgodność między nimi. To jeden z powodów, dla których lubię Linuxa: można zacząć od czegoś nieprecyzyjnego, jak „moja strona czasami się nie otwiera”, i stopniowo dojść do precyzyjnego opisu warstwy, na której użyteczna praca przestaje postępować.

Workflow debugowania, którego używam teraz

top
free -h
df -h

date -u
uptime
cat /proc/pressure/io
cat /proc/pressure/memory
cat /proc/pressure/cpu
vmstat 1 10
iostat -x 1 10
ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'
ss -lntp
journalctl -k --since "30 min ago" --no-pager

Jeśli to możliwe, testuję także każdy element ścieżki requestu osobno:

public request
      ↓
reverse proxy
      ↓
direct backend
      ↓
filesystem
      ↓
block device

Nie pytam już tylko, dlaczego serwer jest wolny. Pytam: na której warstwie przestaje kończyć się użyteczna praca? To pytanie prowadzi do znacznie lepszych eksperymentów.

Ostatnia zasada: zbierz dowody przed rebootem

Reboot może być dokładnie tym, czego potrzebuje produkcja, ale może też usunąć najcenniejszy stan diagnostyczny, jaki kiedykolwiek zobaczysz.

Before reboot:
D-state:     high
I/O PSI:     ~97%
iowait:      ~100%
queues:      large
requests:    failing

After reboot:
D-state:     0
latency:     milliseconds
requests:    healthy

Jeśli dostępność i wpływ biznesowy na to pozwalają, najpierw zapisuję timestamp UTC, PSI, vmstat, iostat, D-state, wchan, komunikaty kernela, socket queues i czasy requestów. Dopiero potem przywracam maszynę.

Serwer działał. Workload nie.

Nigdy nie dowiedziałem się, który host-side component ostatecznie spowodował incident. Nie mogę powiedzieć, że zepsuł się konkretny SSD, wskazać konkretnego storage node ani udowodnić, co działo się za wirtualnym urządzeniem blokowym.

To, co mogłem ustalić z poziomu Linuksa, było wystarczające:

read latency:       up to 18.7 s
flush latency:      up to 53.6 s
I/O PSI full:       almost 100%
iowait:             almost 100%
I/O queue:          128+
Nginx:              blocked in filesystem reads
EXT4/jbd2:          blocked waiting for I/O
direct backend:     ~3 ms
HTTP through Nginx: timing out

To wystarczyło, by oddzielić moją aplikację od wadliwej warstwy i podjąć decyzję operacyjną. FDCServers zwrócił pieniądze za VPS, ja przeniosłem się dalej i nie traktuję jednego trudnego incidentu infrastrukturalnego jako wyroku na providera.

Ważniejsza lekcja została ze mną: proces może być running, usługa active, VM online, ping może działać, a mimo to maszyna może prawie nie wykonywać użytecznej pracy.

Linux daje wystarczająco dużo dowodów, by zobaczyć różnicę. Trzeba tylko zadawać właściwe pytania, dopóki awaria wciąż jest widoczna.