Jak jsme ladili problém s pamětí v Java aplikaci:

Každý, kdo někdy vyvíjel větší Java aplikaci, se s tím setkal. Aplikace běží stabilně, až jednoho dne přestane reagovat. Logy nic neukazují, restart pomůže, ale důvod zůstává nejasný. Tento článek popisuje, jak jsme podobný incident řešili v praxi, od prvního výpadku až po nalezení skutečné příčiny problému s pamětí.

_________________________________________________________________________

Problémy s přílišnou konzumací paměti se dříve či později objeví v téměř každé aplikaci. Tentokrát jsme se s nimi setkali u naší aplikace EnergoSync, moderní cloudové platformy pro správu a zpracování energetických dat, kterou využívají především provozovatelé lokálních distribučních soustav (LDS). Každý den zpracovává velké množství dat s čtvrthodinovou granularitou, která po vyhodnocení odesílá do dalších systémů nebo z nich generuje reporty pro regulační úřady.

Před několika dny se nám přihodil incident, kdy aplikace přestala odpovídat a byla restartována. Nastala otázka, co výpadek způsobilo a jak zamezit dalším. Problém byl, že po restartu aplikace nebylo mnoho dat, ze kterých by se dala příčina vyvodit. Aplikační logy neobsahovaly nic podezřelého. Jediná indicie byla vysoká utilizace CPU hlášená metrikami v AWS. Z naší dlouholeté zkušenosti víme, že pokud je CPU utilizace po delší dobu vysoká a aplikace přestane reagovat, obvykle to značí problémy s nadměrnou spotřebou paměti. V takové situaci běží JVM (Java Virtual Machine) Garbage Collector naplno a snaží se uvolnit prostor.

Kvůli těmto případům je ideální Java aplikaci spouštět s parametry -XX:+HeapDumpOnOutOfMemoryError -XX:+ExitOnOutOfMemoryError. Pokud se aplikace do takových problémů dostane, je nejlepší ji restartovat. O to se postará -XX:+ExitOnOutOfMemoryError. Lépe řečeno, tento argument způsobí, že se aplikace ukončí. O její opětovný start se pak typicky postará service manager, například Kubernetes. Druhý argument -XX:+HeapDumpOnOutOfMemoryError způsobí, že aplikace za sebou zanechá heap dump. To je velmi užitečné pro zkoumání příčin a zamezení tomu, aby se incident opakoval. K analýze heap dumpu vřele doporučujeme Eclipse Memory Analyzer (https://eclipse.dev/mat/).

Bohužel aplikace s těmito argumenty před incidentem spuštěna nebyla, proto jsme postupovali tak, že jsme je přidali a navíc jsme k nim doplnili argument -XX:StartFlightRecording:filename=recording.jfr,dumponexit=true.
Java Flight Recorder (JFR) je monitorovací nástroj, který je součástí JVM. Jak název napovídá, autoři se inspirovali černými skříňkami v letadlech. Stejně jako ty, i záznam, který JFR vytváří, je velmi užitečný při monitorování a zkoumání příčin incidentu.

Po několika hodinách provozu aplikace jsme udělali dump záznamu vytvořeného JFR. To lze učinit příkazem jcmd <pid> JFR.dump, kde <pid> je ID procesu aplikace.

Při zkoumání záznamu v Java Mission Control (nástroj pro analýzu dat z JFR) bylo očividné, že zvýšená spotřeba paměti nebyla ojedinělý úkaz:

I když je Java Flight Recorder užitečný nástroj pro monitorování paměti, většinou nedokáže poskytnout odpověď na to, co zvýšenou spotřebu paměti způsobuje. V tom se nic nevyrovná možnosti prozkoumat heap dump získaný v době, kdy ke zvýšené spotřebě došlo.

Rozhodli jsme se proto nečekat na další incident, při kterém bychom heap dump získali díky parametru -XX:+HeapDumpOnOutOfMemoryError, ale udělat ho proaktivně. Ideálně jsme chtěli vytvořit heap dump ve chvíli, kdy využití paměti dosáhne například 70 %. Pokud je nám známo, JVM takovou možnost přímo neposkytuje. Na druhou stranu to lze snadno vyřešit několika řádky kódu. Vydali jsme se tedy touto cestou a napsali komponentu, která vytvoří heap dump v okamžiku, kdy využití paměti poprvé překročí tuto hranici.

Na následujících řádcích popíšeme dvě nejdůležitější části této komponenty.

Získat utilizaci paměti v JVM je velmi jednoduché:

Udělat heap dump je podobně jednoduché:

A nyní, když jsme rozebrali ty nejdůležitější stavební prvky, kód celé komponenty:

‍

Komponenta byla přidána do aplikace, nová verze nasazena a výsledek na sebe nenechal dlouho čekat. Po dvou dnech provozu nové verze jsme zaznamenali hlášení od zákazníka, že je aplikace pomalejší než obvykle. Vše nasvědčovalo tomu, že se opět jedná o problémy s pamětí. Skutečně tomu tak bylo a naše nová komponenta udělala přesně to, co jsme požadovali a vytvořila heap dump při zvýšené spotřebě paměti.

Heap dump jsme analyzovali v nástroji Eclipse Memory Analyzer a příčina byla překvapivá.

Problém byl v tomto SQL dotazu vyjádřeném v Hibernate Query Language:

Tento SQL dotaz hledá elektroměry, které mají záznam o naměřené hodnotě s příznakem verified nastaveným na false. Jak ale může takto nevinně vypadající dotaz způsobovat problémy s výkonem aplikace nebo dokonce její pád? EnergoSync nespravuje miliony elektroměrů, takže na první pohled nešlo o objem dat. Problém byl v operaci JOIN s naměřenými hodnotami. I když dotaz vrací pouze elektroměry, každý elektroměr se ve výsledku objevil tolikrát, kolik měl záznamů s příznakem verified nastaveným na false. Během analýzy heap dumpu byl nalezen jeden výsledek tohoto dotazu, který obsahoval více než čtyři miliony řádků a zabíral přibližně 1,4 GB paměti aplikace.

Zde je pro ilustraci ukázán tento Java objekt v aplikaci Eclipse Memory Analyzer: 

I když se nám takové chování dotazu může zdát nelogické, z pohledu sémantiky JOIN operace je správné. To, že byl tento dotaz problematický, bylo maskováno frameworkem Hibernate, který aplikace používá jako ORM. Hibernate v tomto případě na úrovni svého API vrací každý elektroměr pouze jednou. Pokud by tomu tak nebylo, naše testy by samozřejmě odhalily, že se elektroměr ve výsledku opakuje vícekrát.

Oprava byla velmi jednoduchá. Původní dotaz by šlo optimalizovat, ale protože šlo o rychlou opravu v produkci, zvolili jsme cestu nejmenší změny a doplnili jen klíčové slovo DISTINCT, které odstraňuje duplicity z výsledku:

Po úpravě dotazu se aplikace vrátila k normálnímu chodu. Poučné na tom všem je, že příčina nakonec ležela úplně jinde, než jsme očekávali. Mysleli jsme si, že k nadměrné spotřebě paměti dochází při stahování a zpracování dat z elektroměrů nebo při generování a odesílání reportů. Ukázalo se však, že hlavním viníkem byl jediný SQL dotaz. Celá situace potvrdila, jak důležité je hledat skutečnou příčinu a jak zásadní roli v tom sehrál získaný heap dump.

‍