WordPress: 502 na load-scripts.php i Critical error. Przyczyna w opcache i JIT

Panel WordPressa bez stylów, w konsoli jQuery is not defined, a przy pliku load-scripts.php błąd 502 to w dwóch naszych przypadkach był problem z opcache w PHP-FPM, a nie z wtyczką: w pierwszym zawinił JIT, w drugim przepełniony cache razem z JIT. Podobnie wygląda ekran „Critical error” na całym sklepie, gdy opcache się przepełni. Poniżej: jak odczytać core dump, jak odróżnić crash JIT od crasha rozszerzenia i które ustawienia opcache zmieniamy w sklepach z kilkudziesięcioma wtyczkami.

Dlaczego load-scripts.php zwraca 502, a front działa?

W panelu brakowało ustawień wtyczek, w konsoli pojawiał się 502 na /wp-admin/load-scripts.php, a zaraz potem jQuery is not defined w każdym kolejnym skrypcie. Front odpowiadał 200 i load-styles.php też. Różnica: load-scripts.php wykonuje znacznie więcej kodu PHP niż load-styles.php, więc trafia w skompilowane przez JIT ścieżki i pada wcześniej.

Drugi ślad dawał wzorzec czasowy. Awarie przychodziły falami, gdy ktoś pracował w panelu, a potem było cicho. JIT kompiluje funkcje dopiero po przekroczeniu progu (jit_hot_func=127, jit_hot_loop=64). Rozgrzewa się podczas pracy w panelu, wywala worker, nowy worker zaczyna z pustym JIT i przez chwilę jest dobrze.

Jak odczytać core dump php-fpm w kontenerze?

Obraz produkcyjny nie miał gdb, a instalowanie go w działającym kontenerze nie wchodziło w grę. Używamy jednorazowego kontenera obok, z dumpami zamontowanymi tylko do odczytu:

IMG=nazwa-obrazu-wordpress          # obraz, z którego działa kontener
DUMP=/var/coredumps/core.php-fpm.123.1790000000   # wybrany plik z dumpem
docker run --rm -d --name gdbdbg -v /var/coredumps:/var/coredumps:ro \
  --entrypoint sleep "$IMG" 3600
docker exec gdbdbg sh -c 'apt-get update -qq && apt-get install -y -qq gdb'
docker exec gdbdbg gdb -q /usr/local/sbin/php-fpm "$DUMP" -ex 'bt 30' -ex quit
docker rm -f gdbdbg

Backtrace kończył się tak:

#0  execute_ex ()
#1  zend_execute ()
#2  zend_execute_scripts ()
#3  php_execute_script ()

Bez symboli debug nazwy funkcji wystarczyły, żeby postawić hipotezę. Reguła robocza: execute_ex na szczycie stosu to maszyna wirtualna Zenda albo JIT, a nie rozszerzenie. Sam backtrace tego nie dowodzi, dlatego sprawdziliśmy to próbą: po wyłączeniu JIT segfaulty ustały, a instalacja z tym samym obrazem, która miała JIT wyłączony wcześniej, nie miała ich wcale. Crash w redisie lub imagicku pokazałby w ramce #0 funkcję typu php_redis_* albo Magick*. Rejestry rsp i rbp w normie i płytki stos wykluczały przepełnienie stosu. Wcześniejsze hipotezy o rozszerzeniach redis, imagick i igbinary okazały się błędne.

Jak wyłączyć JIT, zostawiając opcache?

Konfiguracja opcache była wypalona w obrazie, więc nadpisujemy ją osobnym plikiem, który ładuje się alfabetycznie po opcache.ini. Plik montujemy z hosta:

; php/zz-jit-off.ini
opcache.jit=off
opcache.jit_buffer_size=0

# docker-compose.yml, volumes serwisu wordpress
- ./php/zz-jit-off.ini:/usr/local/etc/php/conf.d/zz-jit-off.ini:ro

Potem docker compose up -d wordpress. Opcache zostaje włączony, wyłączona jest tylko kompilacja JIT, a zysk z niej w WordPressie jest marginalny, bo czas strony to baza i dysk. Po zmianie load-scripts.php odpowiadał 200, segfaulty ustały i jQuery wróciło. Na drugiej instalacji, która miała JIT włączony i zero crashy w 48 godzin, wyłączyliśmy go prewencyjnie: nikt tam nie pracował w panelu, więc nic się jeszcze nie rozgrzało.

Masz ten sam problem? Panel WordPressa pada falami, a logi nic nie mówią? Zdiagnozujemy to z core dumpa i ustawimy PHP tak, żeby nie wracało. Opisz sytuację →

Dlaczego core dumpy zapełniły dysk?

Pułapkę na dumpy (kernel.core_pattern=/var/coredumps/core.%e.%p.%t) włączono przy poszukiwaniu przyczyny i nikt jej potem nie pilnował. Po kilku tygodniach katalog miał 99 plików i 46 GB, a dysk 87% zajętości. Każdy dump ważył około 480 MB, a crash przychodził co kilka sekund, więc około 40 plików wystarczyłoby, żeby zapełnić dysk i zatrzymać wszystkie 44 kontenery na maszynie. Po usunięciu starych plików (poza najnowszym) zajętość spadła z 87% do 56%.

Wniosek: pułapkę na dumpy ustawia się razem z limitem miejsca i datą, kiedy ją wyłączamy, a po ustaleniu przyczyny przywraca się oryginalny core_pattern. Ustawienie jest globalne dla hosta, nie dla kontenera.

Dlaczego sklep zwraca Critical error kilka godzin po restarcie?

To drugi obraz tego samego typu problemu. Na sklepie z WooCommerce i około 78 wtyczkami od pewnej chwili każde żądanie zwracało 500. WordPress pokazywał stronę „critical error”, a w logu PHP-FPM stało:

PHP Fatal error: Allowed memory size of 268435456 bytes exhausted
(tried to allocate 4295229440 bytes) in /var/www/html/wp-includes/theme.php on line 325

Próba alokacji około 4 GB w stałej linii nie wynikała z kodu strony. Polecenie PHP w wierszu poleceń działało bez błędu, opcje szablonu w bazie były poprawne, a wyczyszczenie Redisa nic nie zmieniło. Rozjazd między CLI a WWW wskazuje na opcache, bo CLI ma osobny, często wyłączony.

Log FPM leżał w /tmp/fpm-php-errors.log wewnątrz kontenera, a nie w debug.log, i znika przy restarcie, bo /tmp w kontenerze to tmpfs. Dowody sprzed incydentu przepadły, więc przyczynę odtworzyliśmy z pomiarów po restarcie. Najpewniej łańcuch wyglądał tak:

1. po około godzinie od restartu wykorzystane było 202 z 256 MB pamięci opcache i około 4800 skryptów, a bufor interned_strings_buffer (16 MB) był pełny w 100%,
2. przepełniony cache restartuje się w locie pod ruchem,
3. JIT w trybie tracing z restartem w locie zepsuł skompilowany kod,
4. przy opcache.validate_timestamps=Off skorumpowany wpis nigdy się nie odświeżył. Pomógł dopiero restart kontenera.

Wyzwalaczem była praca w panelu: o 8:52 ktoś edytował produkty, a kompilacja plików panelu dopchnęła cache. Ten łańcuch to hipoteza z pomiarów po restarcie. Potwierdza go licznik restartów w opcache_get_status() oraz logi opcache z chwili awarii, a tych po restarcie już nie było.

Zmiany trzymamy w trzech miejscach: w repozytorium (plik zz-opcache-override.ini, mount w compose i wartości w Dockerfile na przyszłe budowanie obrazu) oraz na serwerze. Po utworzeniu kontenera od nowa front odpowiadał 200, a panel 302.

Jak rozpoznać ten problem u siebie?

• 502 na load-scripts.php przy działającym froncie,
• awarie falami, gdy ktoś pracuje w panelu, i cisza poza tym,
• 500 na całym sklepie, a polecenia PHP w CLI działają,
• alokacja kilku gigabajtów w stałej linii kodu,
• w opcache_get_status() wolny bufor interned_strings równy zero.

Kiedy zlecić to specjalistom?

Gdy awarie wracają, a w logach nie ma śladu rozszerzenia, które mogłoby je powodować. W ASAPDevs czytamy dumpy, dobieramy ustawienia opcache do liczby wtyczek i pilnujemy dysku, w ramach optymalizacji WooCommerce albo stałej opieki nad WordPressem. O dysku zapełnionym przez backup i logi piszemy w artykule o sklepie offline przez pełny dysk.

Źródła: dokumentacja PHP, konfiguracja OPcache (opcache.jit, interned_strings_buffer, validate_timestamps).