AWS LambdaのJavaランタイムでミドルウェアのコネクションのリークでハマった件

AWS LambdaのJavaランタイムでミドルウェアのコネクションのリークでハマった件

  • Post Author:

今回はAWS LambdaでJava 8ランタイムを使った際に、Redis等のミドルウェアとのコネクションの管理関連でハマった点を備忘録として残しておきます。
AWS Lambdaを使う上では抑えておくべき点である基本的な内容の為、初心者向けの内容となっています。

アプリケーションの概要と発生していた現象

  • 言語はScala、ハンドラのタイプは com.amazonaws.services.lambda.runtime.RequestStreamHandler
  • 実行経路はCloudWatch Eventsで、3分間に一度実行
  • ミドルウェアとしてRDS (※), ElastiCache (Redisクラスタ), Amazon MQを使用
    • それぞれハンドラの中でコネクションを確立
    • RDSには org.scalikejdbc, Redisには org.redisson, Amazon MQには org.apache.activemq をそれぞれクライアントモジュールとして使用しています

現象:

  • 3分に1回実行はされているが、何回かに1度、アプリケーションが正常に終了しない
  • 正常に終了しない場合は、Lambdaからの終了ログ、およびレポートログすら表示されない
    • REPORT RequestId: XXX Duration: ??? ms Billed Duration: ??? ms Memory Size: ??? MB Max Memory Used: ??? MB Init Duration: ??? ms って奴
  • アプリの随所でログを流してみると、RDS、Amazon MQとのコネクションは確立できているが、Redisのコネクションが失敗時には流れていない

と言う訳でRedisへの接続の部分に問題がありそうと言う事はわかりました。


※昔はRDSのコネクションをLambda内で開くのはBad Practiceとされていましたが、今回は3分に1度しか起動されない事が保証されている為問題ないです。また、最近ではAmazon RDS Proxyの登場で不特定多数がLambdaを起動する様なワークロードでも問題が無くなるそうです。

アプリケーションの構成詳細

アプリケーションは、次のようにハンドラメソッド内で各種ミドルウェアに接続し、処理を実行する、と言う物でした。

import java.io.{InputStream, OutputStream}
import java.sql.DriverManager

import com.amazonaws.services.lambda.runtime.{Context, RequestStreamHandler}
import com.mysql.cj.jdbc.Driver
import grizzled.slf4j.Logging
import javax.jms.{DeliveryMode, Session}
import org.apache.activemq.ActiveMQConnectionFactory
import org.apache.activemq.pool.PooledConnectionFactory
import org.redisson.Redisson
import org.redisson.api.RedissonClient
import org.redisson.config.{Config, ReadMode}
import scalikejdbc.{ConnectionPool, DB, DBSession, GlobalSettings, LoggingSQLAndTimeSettings}

class App extends RequestStreamHandler with Logging {

  override def handleRequest(input: InputStream, output: OutputStream, context: Context): Unit = {
    logger.info("Execution start")
    
    val redissonClient = _redissonClient()
    val rdbConnection = _rdbConnection()
    val mqProducer = _mqProducer()
    
    // ...
    
    logger.info("Execution completed")
  }

  private def _redissonClient(): RedissonClient = {
    // prepare the Redis connection
    val config = new Config()
    config
      .useClusterServers()
      .setReadMode(ReadMode.MASTER_SLAVE)
      .addNodeAddress("redis://xxx")

    Redisson.create(config)
  }

  // RDBやAmazonMQ用のクライアントも同様にprivate defで定義していた

}

原因はコネクションのリークによる枯渇

勘の良い方ならお気づきかもしれませんが、Redissonを始めとする各種ミドルウェアのコネクションがハンドラ内で接続を確立し、処理を実行後に閉じていないのが原因でした。
この状態ですと、3分に一度アプリケーションが起動するたびに新しいコネクションが貼られ、その内に最大コネクション数に達してしまい、後のアプリケーションの実行が止まってしまっていたのです。

Lambdaが実行用のインスタンスを再利用する事はFAQにも書かれていますが、

Q: AWS Lambda は関数インスタンスを再利用しますか?
パフォーマンス向上のため、AWS Lambda は新しく関数のインスタンスを作成するのではなく、関数のインスタンスを保持してその後のリクエストに対応することがあります。

https://aws.amazon.com/jp/lambda/faqs/

Javaランタイムの場合、実行インスタンスだけでなく、Javaのプロセスその物(+ハンドラを実装しているJavaのクラスインスタンスさえも)も再利用されるみたいなのです。

試しに、コンストラクタに次のようなログを吐き出してみます:

class App extends RequestStreamHandler with Logging {

  logger.info(s"Instantiate handler with PID: ${hashCode().toString}")
  
  // ...
  
}

CloudWatch Logs上で確認してみると、次のように最初の1回だけ仕込んだログが吐き出され、以降はログが見られない事がわかります。

[main] INFO App - Instantiate handler: 211024580
START RequestId: xxx Version: $LATEST
[main] INFO App - Execution start
...
[main] INFO App - Execution completed
END RequestId: xxx
REPORT RequestId: xxx Duration: ??? ms Billed Duration: ??? ms Memory Size: ??? MB Max Memory Used: ??? MB Init Duration: ??? ms 
START RequestId: yyy Version: $LATEST
[main] INFO App - Execution start
...
[main] INFO App - Execution completed
END RequestId: yyy
REPORT RequestId: yyy Duration: ??? ms Billed Duration: ??? ms Memory Size: ??? MB Max Memory Used: ??? MB Init Duration: ??? ms 
...

※Lambdaの START ログよりも先に展開されるのは興味深いですね。

その後もログを追いかけてみると、大体2時間くらいは同じインスタンスが使われているようでした。

コネクションを使い回すよう変更して解決

元々は、Javaのプロセスそのものは毎回初期化されるだろうと言う先入観で、コネクションのクローズ処理を明示していなかったのですが、クラスインスタンスが再利用されるのであれば、コネクションの管理をクラスのメンバ変数で管理すれば良さそうです。
最終的には次のように、private lazy val なメンバ変数で管理する事にしました:

class App extends RequestStreamHandler with Logging {

  override def handleRequest(input: InputStream, output: OutputStream, context: Context): Unit = {
    logger.info("Execution start")
    
    // redissonClient変数などが使われる...
    
    logger.info("Execution completed")
  }

  private lazy val redissonClient: RedissonClient = {
    // prepare the Redis connection
    val config = new Config()
    config
      .useClusterServers()
      .setReadMode(ReadMode.MASTER_SLAVE)
      .addNodeAddress("redis://xxx")

    Redisson.create(config)
  }

  // RDBやAmazonMQ用のクライアントも同様にprivate lazy defで定義

}

因みにLambda内でのTCPコネクションの維持については、クラスメソッドさんの記事が詳しいです:

Lambda実行環境はフリーズしていると言いながら、実はTCPのKeepAliveパケットは送ってくれているようです。また、Lambda実行環境が破棄されるタイミングでも、マナー悪くブツ切りしている訳ではなくちゃんとFIN/ACKを送信してくれるようです。

https://dev.classmethod.jp/cloud/aws/lambda-tcp-keepalive/

現在このアプリケーションはまだ試験中なのですが、今の所は動作しているようなのでこのまま様子見をし、また何かあれば続報を書ければと思います。

まとめ

  • Lambdaは実行インスタンスだけでなく、リクエストハンドラのJavaクラスインスタンスも再利用する
  • 故にハンドラメソッド内でコネクションを開いた場合は、閉じるなりしないとコネクションのリークが発生する可能性がある
  • LambdaのTCPコネクションは維持されるので、クラスインスタンス初期化時にコネクションを確立するのが良い
we are hiring

優秀な技術者と一緒に、好きな場所で働きませんか

株式会社もばらぶでは、優秀で意欲に溢れる方を常に求めています。働く場所は自由、働く時間も柔軟に選択可能です。

現在、以下の職種を募集中です。ご興味のある方は、リンク先をご参照下さい。

コメントを残す