Play! framework při zátěži

Jak identifikovat nadměrné zatížení aplikace napsané v Play! frameworku a jak se aplikace při přetížení chová? Podívejme se na to prakticky při zátěžovém testu jednoduché aplikace.

Chování aplikace otestujeme při výchozí konfiguraci Thread Poolů frameworku, která je vhodná pro asynchronní zpracování requestů. Na ThreadPooly a jejich konfiguraci jsme se blíže podívali v článku Thread pooly v Play! frameworku, šité aplikacím na míru.

Pokusil jsem se položit Play! framework na kolena velkým množstvím requestů a vysledovat chování frameworku při zátěži. Zajímavé je zejména, jaké výjimky začne framework v této situaci produkovat a jaké objekty se přitom budou množit v paměti.

Za tímto účelem jsem provedl orientační měření zpracování velkého množství requestů pomocí JMeteru a přetížení aplikace JMeterem pomocí rychlého sledu požadavků, které nečekaly na response (ten může od přetížené aplikace dorazit až za dlouhou dobu nebo také vůbec).

Testovaná Play! aplikace

Aplikace je velmi jednoduchá - controller, který obsahuje blokující operaci vykonávanou X milisekund (thread sleep o konfigurovatelné délce X), přitom operace je volána z controlleru buď synchronně nebo asynchronně při výchozím nastavení default thread dispatcheru:

Kontext testování

Aplikace byla spouštěna v produkčním režimu na konfiguraci Intel Core i7, 2.4 GHz, 4 GB RAM, 8 jader/vláken (parametry mého notebooku). K sestavení byl použit Simple Build Tool (příkaz sbt dist) a spouštění probíhalo přes Javu (JDK 7) následujícím příkazem:

java -Xmx100m -XX:MaxPermSize=128m 
  -Dlogger.file=/path/to/dist/conf/logger.xml 
  -Dconfig.file=/path/to/dist/conf/prod.conf 
  -Dhttp.port=9100
  -cp /path/to/dist/lib/* play.core.server.NettyServer /path/to/dist

Na stejném stroji byl spouštěn JMeter. Byla použita výchozí konfigurace Thread Poolů v Play! 2.1 (parallelism-factor = 1.0, tj. běh na  všech 1.0 x 8 dostupných vláknech; parallelism-max = 24, tj. hypoteticky max. 24 vláken).

Standardní doba trvání zpracování requestů za běžných podmínek bez zátěže byla při testování nastavena vždy na 1000 milisekund pro synchronní i asynchronní akci.

Chování při zátěži

Z testování obecně vyplynulo, že se při velké zátěži prodlužuje doba zpracování requestů, nicméně do fronty jsou zařazovány stále další a další příchozí požadavky. Klient musí na vrácení response poté dlouho čekat, což může snadno skončit timeoutem při čekání na response, nebo při vlastním připojování k serveru (pokud klient nečeká nekonečně dlouhou dobu).

Při kritické zátěži dochází k plnění fronty tasků, což nakonec vede k OutOfMemoryError: Výjimku vyvolává vlákno play-scheduler-<X>: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "play-scheduler-<X>", nebo samotný Netty server, nad kterým Play! běží: Exception in thread "netty-worker-<X>" java.lang.OutOfMemoryError: Java heap space. Podobně může výjimku vyvolat jakékoliv další vlákno, ve kterém nastává potřeba alokovat další paměť.

Může pak docházet k dalším výjimkám: play-internal-execution-context-<X> java.lang.OutOfMemoryError: GC overhead limit exceeded; netty-worker-<X> java.lang.NoClassDefFoundError: Could not initialize class XYZ. Aplikace může nadále přijímat a zpracovávat další requesty, ale celý proces může vlivem OutOfMemoryError spadnout. Ke stejným problémům dochází při zpracování synchronní i asynchronní akce v Play! controlleru.

Při spuštění Play! aplikace voláním programu java se vstupním bodem play.core.server.NettyServer se vše loguje do konzole, standardní a chybový výstup z procesu (konzole) může být případně v příkazu pro spouštění rovnou přesměrován do "out" souboru na filesystém. Do application.log se logují standardně jenom hlášení od samotné Play! aplikace, výjimky z vláken Netty serveru (nebo např. MongoDB procesu kontrolujícího stav replikace databáze) se do něj nedostanou. Je tedy potřeba správně nakonfigurovat logování, aby byly zachytávány také např. výjimky z vláken Netty serveru.

Statistiky z vytěžování JMeterem

Nastavení vláken v JMeteru bylo následující:

Při Rump-Up periodě (době náběhu) 10 s a počtu vláken 2000 pošle JMeter každých 10/2000 sekund 1 request (vytváření vláken se rovnoměrně rozloží na dobu náběhu). Toto můžeme chápat jako jeden cyklus requestů. Po získání odpovědi (nebo nastání timeoutu) se ve stejných časových prodlevách posílají další requesty (díky parametru Loop count nastavenému na "Forever" cykly posílání requestů nikdy neskončí).

Nejdříve jsem provedl zatížení aplikace požadavky, které neměly v JMeteru nastaveny connection a read timeout (Connect, Response Timeouts). JMeter čeká na vyřízení takových požadavků a neposílá další, dokud neskončí jejich obsluha. I díky tomu se s takovou zátěží 2000 požadavků Play! aplikace vypořádala bez problémů, doba obsluhy requestů ale odpovídajícím způsobem narostla.

Přibližná doba zpracování requestů pro synchronní případ (volání sync): Průměrně 166000 ms, max. 419000 ms, throughput 11,9 req./s

Přibližná doba zpracování requestů pro asynchronní případ (volání async): Průměrně 153000 ms, max. 395000 ms, throughput 4 req./s

Poté jsem nastavil requestům Connect timeout 3000 ms a Reponse timeout 1000 ms. Play! aplikace po rychlém sledu requestů, kdy klient díky timeoutům nečekal na odpověď, a pokračoval v generování dalších requestů, začala po nějaké době produkovat výše zmiňované OutOfMemoryError výjimky. V tomto případě JMeter produkuje poměrně nezajímavé doby zpracování requestů od 1000 ms až po zhruba 3000 ms, což odpovídá minimální možné době zpracování requestu a nastavenému timeoutu 3000 ms.

Využití paměti při přetížení

Nástrojem jvisualvm (Java VisualVM), který je součástí JDK 7, jsem poté, co aplikace začala vyvolávat OutOfMemoryError, vygeneroval heap dump. Z něj je vidět, že většinu paměti zabírá scala.concurrent.forkjoin.ForkJoinPool$WorkQueue, fronta, která se plní instancemi ForkJoinTask (požadavky přijímanými ke zpracování). Jedná se o fork-join-pool konfigurovaný pro jednotlivé dispatchery Play! aplikace.

Vlivem velkého množství requestů se fronty plní příchozími tasky ke zpracování, což může vést k OutOfMemoryError. WorkQueue má dle konstanty MAX_QUEUE_CAPACITY max. kapacitu 67108864 (min. kapacitu 8192), ale Fork-join pool obsahuje front více a max. kapacitu fronty nejde konfiguračně přenastavit a zdá se, že ani nijak jinak přímo ovlivnit počet front ve fork-join poolu. Fork-join pool Play! frameworku je podle Scalability of Fork Join Pool velmi výkonnou implementací poolu vláken, která prošla oproti java.util.concurrent.ForkJoinPoolu pro Javu dalšími vylepšeními.

Statistika zaplnění paměti z heap dumpu v jvisualvm:

Aby byla Play! aplikace vysoce výkonná, je důležité věnovat pozornost nastavení jednotlivých (i uživatelsky definovaných) thread poolů, ve kterých se vykonávají jednotlivé operace - odladit rozložení operací na jednotlivé pooly a vhodně nastavit parametry jako výchozí a maximální počet vláken dostupných pro jednotlivé pooly.

Zdroje

Článek obsahuje 2 komentáře

  • Milan

    1
    Dobry clanok, ale chyba mi tam este:

    - Na kolko bol nastaveny Thread.sleep(durationMs)? 1000ms?
    - Preco bolo pouzite Thread.sleep(durationMs)?
    - Nebolo by lepsie pouzit nejaky cyklus s generovanim nahodnych cisel ako simulacia generovania responsu/zataze?
    - Neviem ako presne funguje thread interruption ak jmeter dropne connection pri sleep a pri running threade.
    - Bol pouzity servlet 3.0?
    - Po kolkych requestoch ste dostali OOM exception?
    - Kolko threadov bolo vytvorenych? Aku maly priemernu velkost? 32 alebo 64 java?
    - Ako vysledok by sa mi viac pacila tabulka kde bude korelacia medzi xmx, pocet threadov alebo waiting_queue_size a oom, kedy to zacne kolabovat.

    Len tak dalej :) Paci sa mi ked niekto ide pod kapotu :)
  • Radek Beran

    2
    Thread.sleep byl nastavený na 1000 ms a byl použitý pro pevné nastavení doby zpracování requestu bez zátěže (ta se pak při zátěži prodlužuje). Nějaký kód (třeba cyklus) prováděný při generování response by byl pro realističtější simulování činnosti aplikace užitečný. Pokud by však byl prováděný v jednom vlákně a vedl by jen k vyššímu zatížení CPU, nevedlo by to k podstatně jinému chování aplikace.

    Play! aplikace není standardní servletovou aplikací (nepotřebuje servletový kontejner a běží jako klasická Java aplikace), pro spouštění byl použit vestavěný server JBoss Netty 3.5.9. Je však možné díky pluginu https://github.com/dlecan/play2-war-plugin distribuovat Play! aplikaci i jako WAR, který pak běží na servletových kontejnerech podporujících servletové API v 2.5 nebo 3.0.

    OOM exception nastávala po cca 6000 requestech. Bylo použito JDK 7 update 13, 64 bit. Navrhovaná tabulka by byla zajímavá hlavně pro odladění parametrů nastavovaných nějaké reálné aplikaci, ale účelem prováděného zatěžování na testovací aplikaci byla hlavně identifikace výjimek, které je framework při zátěži schopen produkovat, a popis obecného chování frameworku při zátěži.