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

2017-01-11

TT-BA09で、テレビの音声をBluetoothで無線化してみた(成功編)

BABYMETALのライブが放送される時期だけWOWOWを契約する、ちょっとWOWOWにとっては迷惑気味なメイトのCERO-METALデス!


さて、普段ヘッドホンで音楽を聴くようになってから、テレビでもライブなどを観る時にはテレビのスピーカーでは物足りなくなり、ヘッドホンで聴くようになりました。ただ3mぐらいのケーブルを使ってもテレビまで近いですし、キッチンで料理や洗い物をしながらテレビを観る時になんかには使えません。

そんな背景から、テレビの音声をワイヤレスにしてヘッドホンで聴きたいなーと思っていました。


ちょうどWOWOWBABYMETAL東京ドームライブが放送される年末年始のこのタイミングで、テレビの音声をBluetoothで飛ばして、ヘッドホンで聴ける環境を作ることにしました。


何がいるの?

そもそも、テレビの音声をBluetoothで飛ばすには何が必要か、という整理からです。接続の流れはこんな感じになります。


テレビ → Bluetoothトランスミッター → Blueotoothレシーバー → ヘッドホン


テレビからの音声入力を受けてBluetoothで飛ばすものを「トランスミッター」と呼び、Bluetoothで受信をする方を「レシーバー」と呼びます。ITエンジニアの皆様方にも分かりやすく説明すると、トランスミッターがWi-Fiルーターに相当し、レシーバーWi-Fi子機に相当します。

またレシーバーとヘッドホンをケーブルで繋ぐものもあれば、ヘッドホン自体がレシーバーになるワイヤレスヘッドホンなどもあります。


製品の選び方

Bluetoothトランスミッターやレシーバーを選ぶ際の観点になるのが、次の2つです。

  • 音声入力の方式(ヘッドホンジャック、赤と白のRCAピンプラグ、光デジタルなど)
  • 対応コーデックSBCAACapt-X、LDACなど)

音声入力の方式はまぁ分かるので割愛するとして、よく分からないのがコーデックです。

ざっくり調べた感じ、次のような違いがあるようです。

  • SBC: ほとんどの機器が対応するけど、音質が悪い。
  • AAC: 主にApple製品で使われる。SBCより音質が良い。
  • apt-X: Androidや多くの機器で使われる。AACより遅延が少ない。
  • apt-X HD: apt-Xをさらに高音質にしたもの。まだ対応製品が少ない。
  • LDAC: ハイレゾ音源に対応するもの。音質は一番良いがソニー製品でしか採用されていない。

対応製品が多いapt-Xが、現在ではほぼスタンダードになってるようです。apt-Xに対応したトランスミッターはいくつかあるのですが、AACやLDACに対応した単体のトランスミッターというのは、ちょっと見つけられませんでした。


実際に買った製品

それで今回用意したのは、次の製品です。

この組み合わせで、ばっちりワイヤレスで視聴できる環境が整いました。


TT-BA09

音声のトランスミッター、レシーバーの両方に使える製品です。TaoTronics社からは似たような製品がいくつか出ているのですが、このTT-BA09は光音声入力があったので、これを選びました。ちなみにTT-BA09には音量を調整する機能がありません。


TT-BA08

上の製品と同じく音声のトランスミッター、レシーバーの両方に使える製品です。TT-BA09よりも一回り小さな製品です。

こちらはレシーバーとして使う際に音量の調整ができるようになっています。通常、光音声入力では出力側での音量調整ができず、レシーバーで音量調整する必要があるため、これを選びました。


それで、繋いでみると。

さすがは同じメーカーの同一シリーズの製品でしょうか、全く何の問題もなく接続できました。

接続はこんな流れです。


テレビ → (光音声出力) → TT-BA09 → (Bluetooth/apt-X) → TT-BA08 → (ケーブル) → ヘッドホン


Bluetoothを切断/再接続をしても、全く問題なく音声を聞くことができます。

また、テレビの音量を変えてもヘッドホンから聞こえる音量は変わらないため、テレビは消音にし、音量をTT-BA08で調整するような使い方になります。音量を調整できないレシーバーだと、こういう事ができないんですよね。


遅延とか音質は?

Bluetoothでよく言われるのが音声の遅延。

apt-Xでは40msほどの遅延があると言われており、口と声がズレるのを気にする僕としては、遅延があるのははっきり分かります。遅延があまり分からない人でも、テレビとヘッドホンの音を両方出せば、はっきりとズレていることは分かるでしょう。

ただ、そうは言っても40msですから、ズレを検出しようとしない限りは、さほど気にならない程度でした。


そして気になる音質ですが、これはとても良いです。

ショボいテレビのスピーカーに比べれば音声はクリアに聞こえ、特に海外映画などの英語もだいぶ聞き取りやすくなりました。音楽番組などもしっかり低音が聞こえるのは、さすがヘッドホンですね。

音楽番組を流しっぱなしにしながらリビングキッチンでウロウロしても、ヘッドホンで聴けるのは最高です。


・・・ということで、特にトラブルも起きることないつまらない話になったのですが、実はこの前に、別メーカーの製品との組み合わせでトラブルがありました。せっかくなので、それについては、また改めて書きたいと思います。


See you!

2016-12-08

Optimizing JavaというJavaパフォーマンス系の書籍が面白そう

急激な冷え込みのせいで「寒い!」というつぶやきがTLに散見されるこの頃ですが、皆さんお風邪など召していらっしゃらないでしょうか。

否応なしに寒いという言葉に反応してしまう、けなげなエンジニアの @ です。


このエントリーは Java Advent Calendar 2016 の8日目です。

昨日は @ さんの「Java Stream APIでハマったこと」で、

明日は @ さんの「マイクロベンチマークツール、JMHについて」でした。


今日のエントリーでは、Javaのパフォーマンス系書籍を紹介したいと思います。

Optimizing Java - O’Reilly Media

URLを見るにつけ、あのオライリー様のサイトですら拡張子が由緒正しい .do なのですから、日本のSIerStrutsを使うことをどうして否定できましょうか。

いえ、今日はそんな話題ではありません。


紹介したいのは上のリンク先の本、「Optimizing Java - Practical Techniques for Improved Performance Tuning」です。名前の通り、Javaのパフォーマンスに関する書籍です。まだEarly Releaseの段階で、全体の1/3ほどしか書かれていませんが、現状の版を入手したので紹介したいと思います。


ここまでで、「あれ、なんか似たような本がなかったっけ」と思った方がいらっしゃるかも知れません。そう、オライリー社からは2015年に「Javaパフォーマンス」という書籍が出版されています。

Javaパフォーマンス - O’Reilly Japan

こちらの日本語版では、私も監訳者まえがきを書かせて頂き、Java Day Tokyoで寺田佳央さんと共にサイン会を行いました。

当時はきっと「この寺田さんの横にいて本に落書きしてる人、誰なんだろう」と思われていたかも知れませんが、私を誰だと思ってるんでしょう、せろさんだぞ?


この2冊について、比較しながら紹介しましょう。


目次

Javaパフォーマンス」の目次は、次の通りです。

1章イントロダクション
2章パフォーマンステストのアプローチ
3章Javaパフォーマンスのツールボックス
4章JITコンパイラのしくみ
5章ガベージコレクションの基礎
6章ガベージコレクションアルゴリズム
7章ヒープのベストプラクティス
8章ネイティブメモリのベストプラクティス
9章スレッドと同期のパフォーマンス
10章Java EEのパフォーマンス
11章データベースのベストプラクティス
12章Java SEAPIのパフォーマンス

JavaのメモリやGCスレッドに関する紹介から、SE / EEやデータベースのパフォーマンスに広げた話をしています。


一方、「Optimizing Java」の目次は次の通りです。

Chapter 1Optimization and Performance Defined
Chapter 2Overview of the JVM
Chapter 3Hardware and Operating Systems
Chapter 4Performance Testing
Chapter 5Measurement and Bottom-Up Performance
Chapter 6Monitoring and Analysis
Chapter 7Hotspot GC Deep Dive
Chapter 8Garbage Collection Monitoring and Tuning
Chapter 9Hotspot JIT Compilation
Chapter 10Java Language Performance Techniques
Chapter 11Profiling
Chapter 12Concurrent Performance Techniques
Chapter 13The Future

うん、ほとんど一緒やん?


「Optimizing Java」には、「Javaパフォーマンス」では触れられていたSEやEEの話などはないため、そこが差分になりそうにも見えます。ただ正直、「Javaパフォーマンス」の10章以降はちょっと薄口な感じでしたので、そこを飛ばせばほとんど同じ内容を網羅していると言えます。


では、何が違うんでしょうか。


Javaパフォーマンス vs Optimizing Java

僕が見た限りでは「Javaパフォーマンス」は教科書に近い内容、「Optimizing Java」はやや読み物寄りの内容になっています。

「Optimizing Java」は、現在執筆されているChapter 5までしか読めていませんが、「Javaパフォーマンス」には書かれていなかったOSJVM周りのレイヤーの話や、テスト戦略の話など、少し目線が違った内容を書いていました。


たとえば、Javaのクラスファイルが「0xCAFEBABE」から始まっていることは、Javaに詳しい方なら既にご存じかと思います。ただ、その先はどうなっているのか。

書籍では次のように紹介されています。

  • Magic Number (0xCAFEBABE)
  • Version of Class File Format
  • Constant Pool
  • Access Flags
  • This Class Name
  • Super Class Name
  • Interfaces
  • Fields
  • Methods
  • Attributes

この先頭を取って

M V C A T S I F M A、

語呂合わせして

My Very Cute Animal Turn Savage In Full Moon Areas

なんて紹介されています。


「僕のとってもかわいい猫は、満月のエリアで凶暴になる」

・・・覚えやすいんですかね、これ?


あ、なんかふざけた本だなと思ったかも知れませんが、もちろん技術的な面もきちんと紹介されています。

あくまで上に書いたようなウィット(?)も挟みながら、Javaの領域だけでなく、必要に応じて低レイヤーにも触れて紹介する本となっているわけです。そのため、「Javaパフォーマンス」を読んだ方でも楽しめる本になるのではないかと思います。


で、いつ出るの? 日本語版は?

この本は2017年3月に出版予定となっています。


また、皆さん気になる日本語版ですが、残念ながらまだ翻訳されることは決まっていないようです。

ただ原著の人気が高かったり、この後に公開される6章以降の内容が「Javaパフォーマンス」とはまた違った切り口であり楽しめるのであれば、翻訳される可能性も十分にあるんじゃないかなと思っています。


そんなわけで、日本語版が出ることを祈りながら、このエントリーを書きました。

Stay tuned, see you!

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だって悪くないということが分かりました。

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