LambdaでJavaを使ってDynamoDBを呼び出した際に、初回起動にとても時間が掛かったという話を書きました。http://d.hatena.ne.jp/cero-t/20160101/1451665326今回は、この辺りの原因をもう少し追求してみます。Lambdaの中身はよく知りませんが、おそらく、アップロードしたモジュールをTomcatみたいなコンテナとして起動させて、外部からコールしているんだろうと予想しました。それであれば、2回目以降のアクセスが早くなることは理解ができます。1回目と3回目だけが極端に遅くて、2回目、4回目以降は早くなるというところは腑に落ちません。その辺りを調べるべく、staticなカウンタを使って、値がどんな風に変化するかを調べてみました。こんなソースコードです。}}出力された結果は、次のようになりました。回数NameCount1回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal12回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal23回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal14回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal25回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal36回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal47回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal58回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal39回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal410回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal511回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal612回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal7サーバのIPアドレスが2種類あり、それぞれのサーバで、1から順番にカウントアップしていることが分かります。2台のサーバでロードバランシングしているのだと。そのため、それぞれのサーバの初回起動である、1回目と3回目の処理に時間が掛かるのですね。ちなみにロードバランシングは毎回このような結果になるわけではなく、1回目と2回目がそれぞれ別のサーバに行く(=処理に時間が掛かる)こともあります。どんなコンテナを使っているのか?先ほど「Tomcatみたいなコンテナ」を使っているんじゃないかと推測しましたが、実際、どんなコンテナを使っているのでしょうか。スレッドダンプを取って、確かめてみました。}}結果、こうなりました。cero.ninja.aws.analyze.StackTrace.myHandler(StackTrace.java:9)(略)何やらシンプルな独自コンテナを使っているみたいです。何度か実行してみても結果は同じでした。ソースコードがないので推測になりますが、アップロードされたzipをロードして起動する独自コンテナがあり、外部からAPIコールされた際にAWSLambdaクラスあたりが処理を受け取って、zip内のハンドラを呼び出しているのでしょう。コンストラクタで処理すると早いの?そういえば、もう一つ、謎な挙動がありました。それは、Credentialsを取るという重めの処理をコンストラクタで実行すれば、処理時間がかなり短くなるというものです。ハンドラの中でCredentialsを取ると、実測値で24秒ぐらい、課金対象値で22秒ぐらいでした。コンストラクタでCredentialsを取っておくと、実測値で8秒ぐらい、課金対象値で6秒ぐらいでした。ここでいう実測値とは、手元のストップウォッチを使って計測したという意味です。ここから推測できることは、コンストラクタは事前に処理されていて、そこは課金対象外になるのかも知れません。・・・あれ、それなら、コンストラクタで重い処理をがっつり走らせて、ハンドラでその結果を取り出せば、課金額を抑えられるじゃないですか?ということで、ハンドラの中で10秒スリープする場合と、コンストラクタでスリープした場合の比較をしてみました。こんな2つのクラスで試してみます。wait課金対象値実測値1回目3901039010100ms10秒2回目3871038710100ms10秒3回目209173091710100ms10秒4回目688527885210100ms10秒きっちり10秒sleepして、課金対象値もそのオーバーヘッド分ぐらい。ストップウォッチで計測した値も同じく10秒ぐらいになりました。wait課金対象値実測値1回目3381033814800ms25秒2回目--100ms1秒以下3回目2611035814800ms25秒4回目--100ms1秒以下えーっ、sleepは10秒だったのに、なぜか15秒分ぐらい課金されてしまい、ストップウォッチで計測すると25秒と、えらく時間が掛かりました。waitが出力されず、処理がすぐに終わるというのは納得ですが。して、こんなことが起きるんでしょうか。waitした後に、4秒ほど待ってから、ハンドラ処理が実行されてCalledが呼ばれていました。コンストラクタが実行され、10秒sleepした。Lambda内の処理か何かで4秒ぐらい処理が掛かった。ハンドラが実行された。2〜4の間が課金対象となり、15秒弱となった。ストップウォッチで計測した時間は1から5までの間なので、25秒弱となった。要するに、コンストラクタで重い処理を行うような悪いことを考える人への対策として、コンストラクタは一定時間で(おそらく10秒きっかりで)タイムアウトして、いったんプロセスは破棄される。Lambdaの内部処理と、ハンドラ処理が行われ、すべての処理が課金対象となる、ということころでしょうか。コンストラクタの処理が短い場合は、どうなるの?ということで、sleepの時間を短くして、再挑戦してみます。waitも出力され、ハンドラ処理のみが課金対象となっていました。複数台のサーバで処理されるため、それぞれのサーバでの初回起動時には処理時間が掛かる。独自のコンテナを利用して、モジュールをデプロイしている。コンストラクタの処理が軽い場合は、ハンドラ内の処理だけが課金対象となる。ハンドラ内の処理が課金対象となる。・・・とは言え、Credentialsの処理をコンストラクタで行った場合に、実測値まで早くなる辺りは、少しだけ不可解です。いうか、Credentialsの取得処理が重いこと自体が不可解なのですが。この辺りはもう少し追試験をしてみれば解析できそうですが、長くなるので、今回はこの辺りまでにしたいと思います。LambdaでJavaとNode.jsとGoの簡易ベンチマークをしてみた。あけましておめでとうございます!現場でいつも締め切りに追われデスマーチ化している皆様方におかれましては、年賀状がデスマーチ化していたのではないかと憂慮しておりますが、いかがお過ごしですか。Lambdaのソースコードを書いていました。いうことで、Lambda。Lambdaを書く時に最初に悩むのは、どの言語を選択するか、なのです。手を出すのは、サクッと書けるNode.js。Node.jsの非同期なプログラミングになかなか馴染めず、わからん殺しをされてうんざりしていました。Promiseを使うべしと教わり、なるほど確かにこれは便利ですナと思いつつも、これが標準で使えないぐらいLambdaのNode.jsが古いところにまたうんざりしました。手に馴染んでるJavaを使ってみたらどうかと思ったら、メモリイーターだし、なんとなくパフォーマンスが悪い感じでした。詳しいことは後ほどベンチマーク結果で明らかになるわけですが。それなら消去法で残ったPythonなのですが、僕マジPython触ったことないレベルであり、これは若者たちに任せることにしているので、Pythonも選択肢から消えて。本来、Lambdaみたいな用途にはGoが向いているはずなのだけど、いつ使えるようになるんだろうなぁなどと思って調べてみたら、Node.jsからGoを呼び出すというテクを見つけて、こりゃいいやとなりました。http://blog.0x82.com/2014/11/24/aws-lambda-functions-in-go/ただGoを呼ぶにしてもNode.jsを経由するためのオーバーヘッドはあるわけで、じゃぁ実際にどれぐらいパフォーマンス影響があるのか、調べてみることにしました。簡単に試したいだけだったので、数行で済む程度のごく簡単な処理を書いてベンチマークすることにしました。DynamoDBから1件のデータを取得する当初は1だけだったのですが、あまり性能に差が出なかったので2を追加した感じです。そんな経緯のベンチマークなので、実装も雑ですが、とりあえずソースをGitHubに置いておきました。