AWS Lambda + Javaは、なぜ1回目と3回目の処理が重いのか？

以前のエントリーで、AWS LambdaでJavaを使ってDynamoDBを呼び出した際に、初回起動にとても時間が掛かったという話を書きました。
http://d.hatena.ne.jp/cero-t/20160101/1451665326

今回は、この辺りの原因をもう少し追求してみます。

なぜ1回目と3回目のアクセスが遅いのか？

AWS Lambdaの中身はよく知りませんが、おそらく、アップロードしたモジュールをTomcatみたいなコンテナとして起動させて、外部からコールしているんだろうと予想しました。それであれば、2回目以降のアクセスが早くなることは理解ができます。
ただ、1回目と3回目だけが極端に遅くて、2回目、4回目以降は早くなるというところは腑に落ちません。

その辺りを調べるべく、staticなカウンタを使って、値がどんな風に変化するかを調べてみました。
こんなソースコードです。

public class Pid {
    static AtomicLong counter = new AtomicLong();

    public String myHandler() {
        long count = counter.incrementAndGet();
        String name = ManagementFactory.getRuntimeMXBean().getName();
        System.out.println("Name: " + name);
        System.out.println("Count: " + count);
        return "SUCCESS";
    }
}

出力された結果は、次のようになりました。

回数	Name	Count
1回目	1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal	1
2回目	1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal	2
3回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	1
4回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	2
5回目	1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal	3
6回目	1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal	4
7回目	1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal	5
8回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	3
9回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	4
10回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	5
11回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	6
12回目	1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal	7

サーバのIPアドレスが2種類あり、それぞれのサーバで、1から順番にカウントアップしていることが分かります。
なるほど、2台のサーバでロードバランシングしているのだと。そのため、それぞれのサーバの初回起動である、1回目と3回目の処理に時間が掛かるのですね。なかなか納得いく結果でした。
ちなみにロードバランシングは毎回このような結果になるわけではなく、1回目と2回目がそれぞれ別のサーバに行く（＝処理に時間が掛かる）こともあります。

どんなコンテナを使っているのか？

先ほど「Tomcatみたいなコンテナ」を使っているんじゃないかと推測しましたが、実際、どんなコンテナを使っているのでしょうか。スレッドダンプを取って、確かめてみました。

こんなコードです。

public class StackTrace {
    public String myHandler() {
        new Exception("For stack trace").printStackTrace();
        Arrays.stream(ManagementFactory.getThreadMXBean().dumpAllThreads(true, true))
                .forEach(System.out::println);
        return "SUCCESS";
    }
}

結果、こうなりました。

java.lang.Exception: For stack trace
	at cero.ninja.aws.analyze.StackTrace.myHandler(StackTrace.java:8)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at lambdainternal.EventHandlerLoader$PojoMethodRequestHandler.handleRequest(EventHandlerLoader.java:434)
	at lambdainternal.EventHandlerLoader$PojoHandlerAsStreamHandler.handleRequest(EventHandlerLoader.java:365)
	at lambdainternal.EventHandlerLoader$2.call(EventHandlerLoader.java:967)
	at lambdainternal.AWSLambda.startRuntime(AWSLambda.java:231)
	at lambdainternal.AWSLambda.<clinit>(AWSLambda.java:59)
	at java.lang.Class.forName0(Native Method)
	at java.lang.Class.forName(Class.java:348)
	at lambdainternal.LambdaRTEntry.main(LambdaRTEntry.java:93)

"Signal Dispatcher" Id=4 RUNNABLE

"Finalizer" Id=3 WAITING on java.lang.ref.ReferenceQueue$Lock@19bb089b
	at java.lang.Object.wait(Native Method)
（略）

"Reference Handler" Id=2 WAITING on java.lang.ref.Reference$Lock@4563e9ab
	at java.lang.Object.wait(Native Method)
（略）

"main" Id=1 RUNNABLE
	at sun.management.ThreadImpl.dumpThreads0(Native Method)
	at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:446)
	at cero.ninja.aws.analyze.StackTrace.myHandler(StackTrace.java:9)
（略）

何やらシンプルな独自コンテナを使っているみたいです。何度か実行してみても結果は同じでした。
ソースコードがないので推測になりますが、アップロードされたzipをロードして起動する独自コンテナがあり、外部からAPIコールされた際にAWSLambdaクラスあたりが処理を受け取って、zip内のハンドラを呼び出しているのでしょう。

なぜコンストラクタで処理すると早いの？

そういえば、もう一つ、謎な挙動がありました。
それは、Credentialsを取るという重めの処理をコンストラクタで実行すれば、処理時間がかなり短くなるというものです。

ハンドラの中でCredentialsを取ると、実測値で24秒ぐらい、課金対象値で22秒ぐらいでした。
コンストラクタでCredentialsを取っておくと、実測値で8秒ぐらい、課金対象値で6秒ぐらいでした。
ここでいう実測値とは、手元のストップウォッチを使って計測したという意味です。

ここから推測できることは、コンストラクタは事前に処理されていて、そこは課金対象外になるのかも知れません。

・・・あれ、それなら、コンストラクタで重い処理をがっつり走らせて、ハンドラでその結果を取り出せば、課金額を抑えられるじゃないですか？
ということで、ハンドラの中で10秒スリープする場合と、コンストラクタでスリープした場合の比較をしてみました。

こんな2つのクラスで試してみます。

public class Wait1 {
    static long origin = System.currentTimeMillis();

    public String myHandler() {
        try {
            System.out.println("Before wait: " + (System.currentTimeMillis() - origin));
            Thread.sleep(10000);
            System.out.println("After wait: " + (System.currentTimeMillis() - origin));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return "SUCCESS";
    }
}

public class Wait2 {
    static long origin = System.currentTimeMillis();

    public Wait2() {
        try {
            System.out.println("Before wait: " + (System.currentTimeMillis() - origin));
            Thread.sleep(10000);
            System.out.println("After wait: " + (System.currentTimeMillis() - origin));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    public String myHandler() {
        System.out.println("Called: " + (System.currentTimeMillis() - origin));
        return "SUCCESS";
    }
}

結果は、、、

Wait1（ハンドラの中でsleep）

回数	Before wait	Aftre wait	課金対象値	実測値
1回目	390	10390	10100ms	10秒
2回目	387	10387	10100ms	10秒
3回目	20917	30917	10100ms	10秒
4回目	68852	78852	10100ms	10秒

きっちり10秒sleepして、課金対象値もそのオーバーヘッド分ぐらい。ストップウォッチで計測した値も同じく10秒ぐらいになりました。

Wait2（コンストラクタでsleep）

回数	Before wait	Aftre wait	課金対象値	実測値
1回目	338	10338	14800ms	25秒
2回目	-	-	100ms	1秒以下
3回目	261	10358	14800ms	25秒
4回目	-	-	100ms	1秒以下

えーっ、sleepは10秒だったのに、なぜか15秒分ぐらい課金されてしまい、ストップウォッチで計測すると25秒と、えらく時間が掛かりました。これは謎な挙動です。
2回目や4回目ではインスタンス生成が終わっているので、Before waitやAfter waitが出力されず、処理がすぐに終わるというのは納得ですが。

どうして、こんなことが起きるんでしょうか。
不思議に思って、CloudWatch Logsのログを確認してみると・・・

Before wait: 17 
START RequestId: 34ae18c3-b47b-11e5-858f-272ee689265f Version: $LATEST 
Before wait: 249 
After wait: 10250 
Called: 14408
END RequestId: 34ae18c3-b47b-11e5-858f-272ee689265f 
REPORT RequestId: 34ae18c3-b47b-11e5-858f-272ee689265f	Duration: 14531.57 ms	Billed Duration: 14600 ms Memory Size: 128 MB Max Memory Used: 27 MB	

最初のBefore waitの後にAfter waitがなく、Lambdaの処理がSTARTした後に再度Before waitが呼ばれ、After waitした後に、4秒ほど待ってから、ハンドラ処理が実行されてCalledが呼ばれていました。
なるほど、つまりこういうことでしょうか。

1. コンストラクタが実行され、10秒sleepの途中でタイムアウトして強制的に処理が止められ、インスタンス生成を諦めた（プロセスごと破棄された？）
2. 改めてコンストラクタが実行され、10秒sleepした。
3. AWS Lambda内の処理か何かで4秒ぐらい処理が掛かった。
4. ハンドラが実行された。
5. 2〜4の間が課金対象となり、15秒弱となった。
6. ストップウォッチで計測した時間は1から5までの間なので、25秒弱となった。

要するに、コンストラクタで重い処理を行うような悪いことを考える人への対策として、コンストラクタは一定時間で（おそらく10秒きっかりで）タイムアウトして、いったんプロセスは破棄される。
その後、改めてコンストラクタの処理がタイムアウト関係なく実行されたうえで、AWS Lambdaの内部処理と、ハンドラ処理が行われ、すべての処理が課金対象となる、ということころでしょうか。

コンストラクタの処理が短い場合は、どうなるの？

ということで、sleepの時間を短くして、再挑戦してみます。

public class Wait3 {
    static long origin = System.currentTimeMillis();

    public Wait3() {
        try {
            System.out.println("Before wait: " + (System.currentTimeMillis() - origin));
            Thread.sleep(2000);
            System.out.println("After wait: " + (System.currentTimeMillis() - origin));
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    public String myHandler() {
        System.out.println("Called: " + (System.currentTimeMillis() - origin));
        return "SUCCESS";
    }
}

結果。

回数	Before Wait	After wait	課金対象値	実測値
1回目	-	-	100ms	3秒
2回目	-	-	100ms	1秒以内
3回目	-	-	100ms	1秒以内

CloudWatch Logsでの出力

Before wait: 25 
After wait: 2026 
START RequestId: xxx Version: $LATEST 
Called: 2389 
END RequestId: xxx 
REPORT RequestId: xxx	Duration: 97.52 ms	Billed Duration: 100 ms Memory Size: 128 MB	Max Memory Used: 27 MB	 
START RequestId: yyy Version: $LATEST 
Called: 16385 
END RequestId: yyy 
REPORT RequestId: yyy	Duration: 6.04 ms	Billed Duration: 100 ms Memory Size: 128 MB	Max Memory Used: 27 MB	

今度はSTARTの前に、きちんとBefore waitもAfter waitも出力され、ハンドラ処理のみが課金対象となっていました。

まとめ

ここまでの話をまとめると、AWS Lambdaは・・・

1. 複数台のサーバで処理されるため、それぞれのサーバでの初回起動時には処理時間が掛かる。
2. 独自のコンテナを利用して、モジュールをデプロイしている。
3. コンストラクタの処理が軽い場合は、ハンドラ内の処理だけが課金対象となる。
4. コンストラクタの処理が重い場合は、コンストラクタの処理 + 5秒弱 + ハンドラ内の処理が課金対象となる。

ということですね。

・・・とは言え、Credentialsの処理をコンストラクタで行った場合に、実測値まで早くなる辺りは、少しだけ不可解です。というか、Credentialsの取得処理が重いこと自体が不可解なのですが。
この辺りはもう少し追試験をしてみれば解析できそうですが、長くなるので、今回はこの辺りまでにしたいと思います。

いやー、Lambdaさん、なかなかよく考えられてますね！