2018/09/03

MySQLのJDBCドライバでメモリリークがあった話

どうも、CTO(Chief Troubleshooting Officer)の石田です。

最近新たに作った Java/Tomcat/MySQL な構成の環境で、Tomcatを長時間動かしているとヒープサイズが肥大化する現象が発生。そこで、jmapでヒープダンプ(hprof)を取得し、Eclipse Memory Analyzer でメモリリークを起こしている箇所を探してみた。

 

リーク箇所

MySQLのJDBCドライバである Connector/J の com.mysql.jdbc.NonRegisteringDriver というクラスの、connectionPhantomRefs という ConcurrentHashMap が大量のエントリを保持していることが判明。

このMapは、MySQLサーバーからの切断や、ネットワークのエラーなどで明示的なクローズがなかったコネクションを自動的に解放できるように、接続済みの Connection を保持しておくためのものだということがソースコードからわかった。

リソースの解放は、AbandonedConnectionCleanupThread が引き受けている。ReferenceQueue と PhantomReference を使った仕組みで、Java側のGCで消滅した com.mysql.jdbc.ConnectionImpl のインスタンスが使っていた各種リソースが開きっぱなしになっていたときにそれを自動的に解放してくれる。

解放されれば、connectionPhantomRefs からもエントリが削除されるのでリークは発生しない。

はずだった。Connector/J の 5.1.40 までは。

ところがリークが発生していた環境では、いるはずの AbandonedConnectionCleanupThread がスレッドダンプに存在しない。当然、connectionPhantomRefs のエントリと、恐らくはソケットなどのCヒープを徐々に食いつぶしていく。

 

なぜこうなるのか

Connector/J 5.1.41 において、Tomcat で webapp の再読込などが起きたときに、この AbandonedConnectionCleanupThread が止まらずリークが起きるというバグが修正された。(https://bugs.mysql.com/bug.php?id=69526

それまでは各 webapp で起動していたこのスレッド。修正後はシングルトン化され、同時に Tomcat で webapp の交代が発生した場合など、クラスローダーが変わると AbandonedConnectionCleanupThread が自動的に終了するようになった。
https://github.com/mysql/mysql-connector-j/commit/cd38fe0fdeba0cd105bd7bf7bfbd8a30a59dff5d

「MySQL JDBC メモリリーク」などで検索してひっかかるページのほとんどは、これが問題となっているものだ。

問題のあった環境のサーバーは、mysql-connector-java-{version}-bin.jar を、Tomcat の $CATALINA_HOME/endorsed の下に配置して読み込んでいた。

そして endorsed に mysql-connector-java-{version}-bin.jar があると、Webアプリがロードされる前にすでに、この jar のなかのクラスがロードされてしまう。endorsed の仕組みは本来、JVMで提供される標準クラスをオーバーライドするためのものだからである。

こういう状態だと、サーブレットの起動時に Class.forName(“com.mysql.jdbc.Driver”)を呼んでも、その時点ですでに endorsed でロード済みになっている。だが、Webアプリとしてのクラスローダーは、endorsed のロード時のものとは違うので AbandonedConnectionCleanupThread は自滅して消えてしまう。

そして、リソースを片付けるスレッドがいないため、connectionPhantomRefs と、コネクションが使っていたリソースはリークしていく。

このアプリは、Tomcatの JNDI Datasource を使わず、自前でコネクションプールを構成し、サーブレットの起動時に Class.forName(“com.mysql.jdbc.Driver”)
で MySQL のドライバをロードするように作られていた。そのため、Class.forName() の前にロード済みのドライバをログに出力するように改造して様子を見てみた。

この実行結果は以下のとおりである。

Class.forName() の前でもすでにドライバは読み込み済みなので間違いない。

 

解決法

JDBCドライバのロードは、Webアプリごとに実施すべきで、アプリが関与できない段階でロードされないようにしなければならない。つまり $CATALINA_HOME/endorsed ではなく、$CATALINA_HOME/lib に置くべきである。

さらに、MySQLの場合はきちんとスレッドが動いていることを確認し、動いていなければ起動自体を失敗させるようにしておけば、なおよし。