谷本 心 in せろ部屋 このページをアンテナに追加 RSSフィード Twitter

2016-07-31

[]Day -1 : ラスベガスに来ました。

SpringOneに登壇するため、ラスベガスにやってきました @ です。

なんか「ラスベリガス」とか言う人が後を絶たなくて困るのですが、滑りに来たわけではありません、むしろ統べに来たという方が近く、「ラ統べガス」ですかね。

はい早速すべりました。


さてラスベガス、とても暑いです。事前調査で最高気温が40℃を越えることは知っていましたが、まぁ暑いです。ただ先週は46℃にも達したらしいですが、今週はせいぜい40℃程度なので、外にいても死ぬほどではない感じです。

よく「海外の夏は、暑くてもカラッとしてるから、日本ほど暑く感じない」とか言う人がいて、子供の頃はそれでも「んなわけない、暑いよ」とか思ってたのですが、最近ではその感覚が分かるようになりました。老けるとそういうのが分かるようになるんですかね。


なおSpringOneは8/1(月)から8/4(木)の4日間ですが、土曜日着の飛行機で来たので、土日はちょっと時間がありました。それで少しだけラスベガスらしくない観光をしてきたので、その辺りをお伝えします。


まず何はなくともSIM購入

海外に着いたらまずやるのがSIM購入ですよね? SIMないと死んでしまいますよね? アメリカではだいたいT-Mobileを使っているので、今回もT-Mobileを選びます。


事前に調べてラスベガス宿泊先の近くにはT-Mobileがないことを知っていたため、空港に着いたらホテルに向かわず、そのままT-Mobileに向かいました。Uberで$10ぐらいの所にあります。

なにげに空港の無料WiFiだけでUberを呼ぶという、ちょっと難易度高めのことをやりましたが、特に問題ありませんでした。

T-Mobileでは旅行者向けのプランとして、$30で2GB、通話1000分まで、SMSし放題のプランがあったので、迷わずこれを選びました。僕にとって最高にちょうどいいやつです。


そしてT-MobileからふたたびUberを呼び、ホテルに向かいます。僕がデカいスーツケースを持っているのを見た運転手に「ホテルに行かずに電話を買いに来たのか、良い選択だな!」って言われました。俺を誰だと思ってるんだ、せろさんだぞ。

T-Mobileからホテルまでは$8ぐらいでした。

空港からホテルまで$30ぐらいだったと言っていた人がいたのですが、空港からホテルと同じぐらいの距離にあるT-Mobileまで$10、そこからホテルまで$8の、合計$18だったことを考えると、Uberってとんでもなく安いなと思わされます。


開幕、当たり

ラスベガスと言えば、カジノ。空港にもスロットマシンがあるぐらい、カジノの町です。僕も過去にはちょっと言えないぐらいの額を貯金してきていて、いつか利子つきで引き出せると信じています。

今回はあまりカジノに興じるつもりはないのですが、一方で、手持ちの現金がほとんどなくて困っているという問題もあります。誰かと一緒にご飯に行って、まとめてカード払いして現金を集める方法も考えましたが、まだ日本にいる人も多く、めどが立ちません。

であれば仕方ないですよね、現金を増やすために、なけなしの$20をつっこんで勝負することにしました。


・・・その結果、3ターン目でヒットしました!

f:id:cero-t:20160801021242j:image

これで何とか、ハンバーガーぐらいなら食いつなげるぐらいの現金を手に入れることができました。今回はもうカジノでは遊びません!


ニャースマンキー、そしてガーディの巣

最近の話題と言えば、ポケモンGoですよね。仕事と資料作り をサボりながら の合間を縫って、僕も少しプレイしています。

それでラスベガスポケモン事情ですが、とにかくニャースがよく出ます。空港でもホテルでも、ニャースがポッポと同じぐらいの感覚で出てきます。マンキーも同じぐらい出て、その半分ぐらいガーディが出てきます。この3種類の巣になってる感じですね。

ホテルに着いて、ものの数十分でこうなってました。

f:id:cero-t:20160801021240j:image


もしかすると別のホテルに行けば違うポケモンの巣になってるのかも知れませんが、ちょっとそこまで歩く気力はありませんでした。

それよりも北米限定のケンタロスを捕まえたいのですが、残りの期間に手に入るのでしょうか。どっかにケンタロスの巣ないかな。


ボルダリングジムもありますよ

日曜にはボルダリングに行きました。ホテルからUberで30分程度、$20弱で行けるところにあるRed Rock Climbing Centerというところです。

ラスベガスにはRed Rock Canyonというグランドキャニオンの小規模版のような公園があって、クライミングも盛んらしく、その名前にあやかったクライミングジムです。


中はこんな感じ。ボルダリングよりロープクライミング主体なので、全体的に壁が高くなっています。

f:id:cero-t:20160801021241j:image

見てのとおりあまり広くないのですが、そんなに人も多くなく(十数人程度でした)、登るのを待たされることはほとんどありませんでした。


コースはとにかく力、技より力、力こそパワーという感じで、1時間で腕がパンパンになりました。V3〜V5ぐらいを攻略してましたが、これ日本で言うところの3級から1級ぐらいなのですよね。僕、日本だと5級(簡単な所なら4級も)ぐらいなので、あまりにも感覚が違う感じです。

アメリカだと体格の差が激しいためか、様々な体格の人に合うよう足場が多めに設定されていた感覚があります。そのおかげで攻略しやすかった気がします。


コースはあまり豊富ではないのでボルダリングガチ勢には物足りないかも知れませんが、僕には良い感じのトレーニングになりました。


そんなわけで資料づくりに戻りますね

はい、まだ1ページもできてません。

日本にいるうちにデモはおおよそできたので、進捗30%てところでしょうか。前回のJavaOneの時に比べれば、随分進んでますね!


それなのになんか明日の夕方、リハーサルらしいんですよね。いえ、PCの接続チェックなどが主なので、資料ができあがっている必要はないですが。

せめて表紙と、自己紹介と、導入ぐらいは作っておかないとね、てへぺろ

ということで、頑張ってきます。


モンテカルロより、愛を込めて。

f:id:cero-t:20160801021243j:image

@cero_t でした!

2016-01-06

[]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";
    }
}

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

回数NameCount
1回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal1
2回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal2
3回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal1
4回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal2
5回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal3
6回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal4
7回目1@ip-10-0-aaa-bbb.ap-northeast-1.compute.internal5
8回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal3
9回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal4
10回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal5
11回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal6
12回目1@ip-10-0-xxx-yyy.ap-northeast-1.compute.internal7

サーバ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 waitAftre wait課金対象値実測値
1回目3901039010100ms10秒
2回目3871038710100ms10秒
3回目209173091710100ms10秒
4回目688527885210100ms10秒

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


Wait2(コンストラクタでsleep)

回数Before waitAftre wait課金対象値実測値
1回目3381033814800ms25秒
2回目--100ms1秒以下
3回目2611035814800ms25秒
4回目--100ms1秒以下

えーっ、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 WaitAfter wait課金対象値実測値
1回目--100ms3秒
2回目--100ms1秒以内
3回目--100ms1秒以内

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さん、なかなかよく考えられてますね!

2016-01-04

[]続けて、JavaNode.jsとGoで外部ライブラリを使わないベンチマークをしてみた。

前回の記事では、DynamoDBを呼び出す処理の簡単なベンチマークを行いました。

http://d.hatena.ne.jp/cero-t/20160101/1451665326


ライブラリを伴ったときの初回起動ではJavaが不利な感じの結果になりましたが、ライブラリを使わなければどのような差が出るのか、改めて確認してみました。


今回のベンチマークは、フィボナッチ数列の38番目を取るというものです。

ソースコードは前回と同じリポジトリに追加しています。

https://github.com/cero-t/lambda-benchmark


結果
回数JavaNode.jsGo
1回目2.9199.284.14
2回目2.6789.3024.141
3回目2.5799.3964.14

時間はいずれも秒。ミリ秒より下の精度は切り捨て。


今回はいずれもメモリ128MBで、同じ性能の環境で実施しました。

なおBilled Durationは、ほぼこの結果の2倍程度(=ウォームアップのための実行分)になっていて、オーバーヘッドはあまり感じられませんでした。


メモリの実使用量は

Java : 12MB

Node.js : 9MB

Go : 10MB

でした。


Python書けないマンなので、Pythonは計測していません。

他のサイトのベンチマークを見る限りは、数十秒から数分ぐらい掛かりそうな気がします。

考察

Javaが一番早く、Goはその1.5倍ぐらい、Node.jsJavaの3倍ぐらい時間が掛かるという結果でした。

ウォームアップをもうちょっと取ればJavaJITコンパイルが効くのかも知れませんが、Lambdaで動かすという性質上、本来ならウォームアップなしで動かしたいぐらいなので、これぐらいの比較で十分かと思います。


ちなみに僕の手元のMacBook Pro(Late 2013 / Core i5 2.4GHz)だと、Javaで0.28秒ぐらい、Goで0.33秒ぐらいでしたから、メモリ128MBのLambdaの性能はその1/10ぐらいということになりますね。


もちろん今回は対象がフィボナッチ数の計算という一つの処理なので、結果的にJavaが良かっただけかも知れません。様々なアルゴリズムで言語のベンチマークを行っているサイトでは、Goの方が有利な結果もいくつか出ています。

https://benchmarksgame.alioth.debian.org/u64q/go.html


ということで、ライブラリのローディングさえなければ、Javaだって悪くないということが分かりました。

まぁ実際、ライブラリを使わないことなんて、ほぼ考えられないですけどね!

2016-01-01

[]AWS LambdaでJavaNode.jsとGoの簡易ベンチマークをしてみた。

あけましておめでとうございます!

現場でいつも締め切りに追われデスマーチ化している皆様方におかれましては、年賀状デスマーチ化していたのではないかと憂慮しておりますが、いかがお過ごしですか。

エンジニアの鑑みたいな僕としましては、年始の挨拶はSNSでサクッと済ませ、年末年始は紅白など見ながらAWS Lambdaのソースコードを書いていました。


ということで、Lambda。

Lambdaを書く時に最初に悩むのは、どの言語を選択するか、なのです。


まず手を出すのは、サクッと書けるNode.js

ただNode.jsの非同期なプログラミングになかなか馴染めず、わからん殺しをされてうんざりしていました。みんなどうしているのよとtwitterで問いかけたところ @ から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を経由するためのオーバーヘッドはあるわけで、じゃぁ実際にどれぐらいパフォーマンス影響があるのか、調べてみることにしました。


処理の中身

簡単に試したいだけだったので、数行で済む程度のごく簡単な処理を書いてベンチマークすることにしました。


1. 引数で渡されたJSONパースして、中身を表示する

2. DynamoDBから1件のデータを取得する


当初は1だけだったのですが、あまり性能に差が出なかったので2を追加した感じです。そんな経緯のベンチマークなので、実装も雑ですが、とりあえずソースをGitHubに置いておきました。

https://github.com/cero-t/lambda-benchmark


実行結果
回数Java(1)Java(2)Node.jsGo
1回目218006700900600
2回目13007300800500
3回目19000500200500
4回目10001300200400
5回目500200400500
6回目400100200500
7回目400300400500

時間はいずれもミリ秒のBilled duration。


Java(1) : メモリ192MB。処理中にAmazonDynamoDBClientを初期化

Java(2) : メモリ192MB。処理前に(コンストラクタで)AmazonDynamoDBClientを初期化

Node.js : メモリ128MB

Go : メモリ128MB


メモリの実使用量は

Java : 68MB

Node.js : 29MB

Go : 15MB

でした。


考察など

正味の話、Lambdaで行っている処理などほとんどないので、性能的には大差ないかと思っていたのですが、思ったより特性が出ました。これは処理時間というよりは、関連ライブラリのロード時間な気がしますね。


Javaは最初の数回が20秒、実装を改善しても7秒とかなり遅かったのですが、ウォーミングアップが終わった後は200msぐらいまで早くなりました。呼ばれる頻度が高い処理であれば良いのでしょうけど、たまに呼ばれるような処理では、この特性はネックになる気がします。


ちなみにJavaだけは192MBで計測しましたが、最初にメモリ128MBで試したところ、30秒ぐらいで処理が強制的に中断されたり、60秒でタイムアウトするなど、計測になりませんでした。こういう所を見ても、Javaを使う時にはメモリを多め(CPU性能はメモリと比例して向上)にしなくてはいけない感じでした。


Node.jsも少しはウォーミングアップで性能が変わりますが、最初から性能は良い感じです。


Goを使った場合は性能が安定しており、ウォーミングアップしても性能が変わりません。メモリ使用量が少ないのも良いですね。Node.jsから呼び出す際のオーバーヘッドがあるせいか、性能的にはウォーミングアップ後のJavaNode.jsに一歩劣る感じでした。


なお、Pythonの実装をしてくれる人がいらっしゃれば、プルリクしていただければ、データを追加したいと思います。


結論

繰り返しになりますが、雑なベンチマークなので特性の一部しか掴んでないと思います。

そもそもJavaだけメモリが1.5倍になっている(=CPU性能も1.5倍になっている)ので公平ではないですし。


ただ「たまに行う処理」を「少ないリソース」で行うという観点では、Goで実装するのが良さそうです。GoはそのうちLambdaでも正式サポートされそうですしね。

きちんとしたベンチマークは、また別の機会にじっくり行ってみたいと思います。


ということで、Goを使う大義名分ができたベンチマークでした!

See you!

2015-12-24

[][]JMXで情報を取得する時のベンチマーク

JMHを使って、JMX経由でMBeanの情報を取る際のパフォーマンスを測定してみた。

ベンチマークソースコードはこちら。

https://github.com/cero-t/Benchmarks/blob/master/src/main/java/ninja/cero/benchmark/JmxBenchmark.java


ベンチマーク環境はMacBook Pro Late 2013 (Core i5 2.4GHz) で、

他のアプリなども立ち上げっぱなしの環境なのでノイズは多めでだけど、

傾向を見たいだけなのであまり気にせず。


VirtualMachine.attachのパフォーマンス

VMオンデマンドアタッチする際のパフォーマンス。


No1 : VirtualMachine.attacheしてからシステムプロパティを取ってdetachする

No2 : キャッシュしていたVirtualMachineを使ってシステムプロパティを取得する

@Benchmark
public void no1_vmAttach() throws Exception {
    VirtualMachine vm = VirtualMachine.attach(PID);
    vm.getSystemProperties();
    vm.detach();
}

@Benchmark
public void no2_vmCachedGetProperties() throws Exception {
    vm.getSystemProperties();
}

結果

BenchmarkModeCntScoreErrorUnits
JmxBenchmark.no1_vmAttachthrpt10653.834± 108.790ops/s
JmxBenchmark.no2_vmCachedGetPropertiesthrpt102330.529± 270.268ops/s

アタッチありは1.5msec程度、キャッシュした場合は0.4msec程度。

ということで、アタッチに掛かる時間は1msec程度と推定。割とでかい。


JMXConnectorFactory.connectのパフォーマンス

続いて、VMに対するJMX接続を行う際のパフォーマンス。


No3 : JMXConnectorの取得処理と、クローズ処理をする

No4 : キャッシュしていたJMXConnectorを使って、MBeanServerConnectionの取得とMbean情報を取得する

public JMXConnector no3_vmCachedGetConnector() throws Exception {
    String connectorAddress = vm.getAgentProperties().getProperty("com.sun.management.jmxremote.localConnectorAddress");

    if (connectorAddress == null) {
        String agent = vm.getSystemProperties().getProperty("java.home") + File.separator + "lib" + File.separator + "management-agent.jar";
        vm.loadAgent(agent);
        connectorAddress = vm.getAgentProperties().getProperty("com.sun.management.jmxremote.localConnectorAddress");
    }

    JMXServiceURL serviceURL = new JMXServiceURL(connectorAddress);
    JMXConnector jmxConnector = JMXConnectorFactory.connect(serviceURL);
    jmxConnector.close();
}

@Benchmark
public void no4_connectorCachedGetMBeanCount() throws Exception {
    MBeanServerConnection connection = connector.getMBeanServerConnection();
    connection.getMBeanCount();
}

結果

BenchmarkModeCntScoreErrorUnits
JmxBenchmark.no3_vmCachedGetConnectorthrpt10612.652± 95.547ops/s
JmxBenchmark.no4_connectorCachedGetMBeanCountthrpt109047.803± 1480.741ops/s

JMXの接続と切断は1.6msec程度。おおまかVMに対するアタッチと同じぐらい。

接続したあとの、MBeanServerへの接続とMBean情報取得は0.1msecぐらいで、これは無視できる小さい。


ThreadMXBeanからThreadCountを取るパフォーマンス

今回の主目的はこれ。

ThreadMXBeanを使って情報を取るのと、

MBeanServerConnection.getAttributeで名前を指定して情報を取るのと、どっちが早いか。


No5 : MBeanServerConnection.getAttributeの名前指定でThreadCountを取得する

No6 : ThreadMXBeanを取得してから、getThreadCountで取得する

No7 : キャッシュしていたThreadMXBeanから、getThreadCountで取得する

@Benchmark
public void no5_connectorCachedThreadCount() throws Exception {
    MBeanServerConnection connection = connector.getMBeanServerConnection();
    Object count = connection.getAttribute(new ObjectName(ManagementFactory.THREAD_MXBEAN_NAME), "ThreadCount");
    sum += (Integer) count;
} 

@Benchmark
public void no6_connectorCachedGetThreadCount() throws Exception {
    MBeanServerConnection connection = connector.getMBeanServerConnection();
    ThreadMXBean threadBean = ManagementFactory.newPlatformMXBeanProxy(
            connection, ManagementFactory.THREAD_MXBEAN_NAME, ThreadMXBean.class);
    sum += threadBean.getThreadCount();
}

@Benchmark
public void no7_beanCachedGetThreadCount() throws Exception {
    sum += threadMXBean.getThreadCount();
}

結果

BenchmarkModeCntScoreErrorUnits
JmxBenchmark.no5_connectorCachedThreadCountthrpt108199.887± 1269.164ops/s
JmxBenchmark.no6_connectorCachedGetThreadCountthrpt102662.147± 585.627ops/s
JmxBenchmark.no7_beanCachedGetThreadCountthrpt108148.967± 1705.518ops/s

ThreadMXBeanを毎回取る(No6)は明らかにパフォーマンスが悪いけど、

ThreadMXBeanをキャッシュしている限りは、ThreadMXBeanから情報を取るのと、

MBeanServerConnection.getAttributeで取ることに性能差はなし。


まとめ

1. VirtualMachineへのattach/detachは時間が掛かるので、キャッシュすべき

2. JMX接続の確立/切断は時間が掛かるので、キャッシュすべき

3. MBeanServerへの接続は時間が掛からないので、無理にキャッシュしなくてよい(close処理もないのでリソース管理もしてない?)

4. MBeanServerConnection.getAttributeでもThreadMXBeanを使っても性能差はないので、ThreadMXBeanを無理にキャッシュしなくてよい


ベンチマークソースコード

https://github.com/cero-t/Benchmarks/blob/master/src/main/java/ninja/cero/benchmark/JmxBenchmark.java


現場からは以上です。