Myšlenky dne otce Fura

V rámci zátěžových testů, které jsem v minulém týdnu prováděl jsem přišel na jednu zajímavou věc. Při velké zátěži došlo k „zaseknutí“ Tomcatu, ze kterého se systém již nedokázal zotavit. Průvodním jevem byly otevřené konekce na databázi, přes které neprocházely žádné dotazy (tj. databáze nic nedělala), nulové zatížení procesoru Tomcatem, žádné Exception v logu. Příznaky nasvědčovaly tomu, že problém vězel v nějakých deadloccích – buď při práci s konekcemi do databáze nebo mezi aplikačními vlákny.

Po nějaké době nikam nevedoucího pátrání v našem kódu jsem si napsal jednoduché wrappery nad DBCP DataSourcem a vracenou Connection, ve kterých jsem si ukládal stacktrace threadu i odkaz na vlastní thread, který si konekci z DataSourcu vybíral. Dál jsem zavedl monitor toho, zda thready používají vždy pouze jedinou connection a nesnaží se získat další, pokud ještě tu původní nevrátily (to by mohla být cesta k deadlockům).

Při opětovném nasimulování problému mi monitor vypsal krásných 50 (tj. maximum poolu) vláken čekajících na uvolnění zámku s nasledujícím stacktracem (uvádím pouze pár nejdůležitějších řádků):

at org.apache.commons.pool.impl.GenericKeyedObjectPool.returnObject (GenericKeyedObjectPool.java:870)
at org.apache.commons.dbcp.datasources.KeyedCPDSConnectionFactory.connectionClosed (KeyedCPDSConnectionFactory.java:268)
at com.mysql.jdbc.jdbc2.optional.MysqlPooledConnection.callListener (MysqlPooledConnection.java:209)
at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close (ConnectionWrapper.java:857)
at com.mysql.jdbc.jdbc2.optional.ConnectionWrapper.close (ConnectionWrapper.java:480)

Žádná chyba v našem kódu tedy nebyla – při vracení konekce zpátky do DBCP poolu docházelo k deadlockům. Po tomto překvapivém zjištění jsem začal pátrat po zkušenostech s DBCP a ouha – Google mi vrátil celou řádku článků, které narážejí na to, že v DBCP skutečně k deadlockům dochází. Je to o to překvapivější, že jsem dosud Commons DBCP považoval za odladěný industriální standard (integrovaný např. v Tomcatu). Pátrání mě navedlo k již hlášeným (a opraveným chybám).

Podobné dotazy proběhly i Tomcat Dev mail konferencí. Velmi zajímavá je reakce jednoho z ?vývojářů? Tomcatu z července 2009:

I encountered an issue that looks similar to Bug DBCP-270.

1) Is it the same bug or a new one?
Yes, that is DBCP-270

2) Which patch can I apply and how to apply it?
You’d need to apply the patch for DBCP-270 to a local copy of DBCP and then
build Tomcat with your modified DBCP sources.

3) Will setting testWhileIdle=“false“ avoid the problem?
No. You’d need to completely disable the evictor thread. Note that there are
other potential deadlocks not related to the evictor that you may still hit.

Nakonec jsme z aplikace vypárali DBCP a vyzkoušeli implementaci nad C3P0. Při obodbných nastaveních a stejném zátěžovém testu jsme k deadlocku již nedošli. Aplikace se z přetíženého stavu po nějakém čase zotavila a standardně procesila požadavky dál.

Přestože je tedy C3P0 podle zdrojů, které jsme našli na internetu pomalejší než DBCP, stabilita a spolehlivost aplikace je pro nás výrazně důležitější, než pár milisekund při práci s poolem. Diagnostika zatuhlého Tomcatu a následný restart stojí totiž výrazně větší „service leak“ než drobné navýšení zátěže.

Reference

• Porovnání C3P0 a DBCP – především s ohledem na rychlost
• StackOverflow Q&A – názory zmiňující deadlocky při práci s DBCP
• Jeden z nejnovějších connection poolingů BareCP – ačkoliv asi nejrychlejší, prozatím nedostatečně prověřený praxí
• Další pojednání o rychlosti a deadloccích v DBCP
• Diskuse na fóru SpringSource na téma Connection poolingu

Související články:

1. Trápení s MySql JDBC driverem
   MySql databázi používáme jako standardní řešení datové vrstvy už hodně let. Prošli jsme si už pěknou řádku verzí JDBC ovladačů, ale jedna věc mě dostala vážně do kolen. Tak se... MySql databázi používáme jako standardní řešení datové vrstvy už hodně let. Prošli jsme si už pěknou řádku verzí JDBC ovladačů, ale jedna věc mě dostala [...]...