Tweet
Tweet

Slide 1

Slide 1 text

Java でつくる 低レイテンシ実装の技巧 〜GCはさだめ、さだめは死〜 JJUG CCC 2016 Fall (2016/12/04) Ryosuke Yamazaki

Slide 2

Slide 2 text

自己紹介 • 山崎良祐 (やまざき・りょうすけ) • Twitter: nappa • ソネット・メディア・ネットワークス所属 (プロバイダの So-net の子会社) • 本日の発表および発言は個人の見解であり、 所属する組織の公式見解ではありません。

Slide 3

Slide 3 text

いちおう Oracle Contributor • mysql-connector-java のバグ修正に貢献 • 詳しくは 2016年10月リリースの 5.1.40 の ChangeLog 参照 • Tシャツもらった! • PostgreSQLのイベントに 行くときに着ようと思ってる

Slide 4

Slide 4 text

この枠のハッシュタグ #ccc_m3

Slide 5

Slide 5 text

レイテンシ とは

Slide 6

Slide 6 text

パフォーマンスの評価基準 • 「スループット」とは… • 「レイテンシ」とは… 単位時間あたりの処理能力 要求してから結果が 返ってくるまでの時間

Slide 7

Slide 7 text

人間に例えると • わんこそば１杯を 食べるのに必要な時間 = レイテンシ • わんこそばを1時間に 何杯食べられるか = スループット わんこそば1杯を早く食べられるからといって、 わんこそばを大量に食べられるわけではない 私の場合… レイテンシ: 平均8秒/杯 スループット: 151杯/時間

Slide 8

Slide 8 text

例題 • 車の自動ブレーキ制御のソフトウェアを 作るとしたら、要件は…… • 検知してから○ミリ秒以内に反応する • ○ミリ秒を絶対に超えない • 他の操作(アクセル) より優先 レイテンシが絶対的に重要 (遅れたら人が死ぬ)

Slide 9

Slide 9 text

レイテンシが非常に重要なアプリ • ロケット・人工衛星の姿勢制御 • 医療関係 (MRI、CTスキャン etc) • 防衛関係 (レーダー、ミサイル etc) • 航空機 (航法・誘導・制御 etc) • 自動車 (ブレーキ・エアバッグ etc ) 時間内にタスクが終了しないと、タスク処理結果の 価値がなくなる = ハードリアルタイムシステム 専用OSがないと作れない

Slide 10

Slide 10 text

レイテンシがわりと重要なアプリ • LINE のメッセージ • ニコニコ生放送のコメント • ゲーム • バナー広告の配信 時間内にタスクが終了しないと、タスク処理結果の 価値が時間の経過によって減少する = ソフトリアルタイムシステム 特殊な OS がなくとも実装次第でなんとかできる

Slide 11

Slide 11 text

当社サービス: Logicad • 広告プラットフォーム • 月間1500億回、広告を表示 • ピークで1秒あたり 100,000 回 オークションに参加している …オークション？

Slide 12

Slide 12 text

ネット広告 のしくみ ※私の勤務先が扱っているものの場合。他にもいろいろある。

Slide 13

Slide 13 text

オークションで枠の価格が決まる

Slide 14

Slide 14 text

オークションで枠の価格が決まる

Slide 15

Slide 15 text

オークションで枠の価格が決まる

Slide 16

Slide 16 text

中身はシステム A社 B社 C社

Slide 17

Slide 17 text

入札は JSON API • ユーザID • User-Agent • サイトURL • IPアドレス • Referer • etc… • 入札額 • 表示したいタグ • リンク先URL • etc… 入札リクエスト ( HTTP Request ) 入札レスポンス (HTTP Response)

Slide 18

Slide 18 text

実装 JSON 受信 JSON を返す ????????????? オークション開始 オークション終了 100ミリ秒 の さだめ

Slide 19

Slide 19 text

イメージ レスポンス数 レスポンスタイム 100 ms 多少は 超過しても OK

Slide 20

Slide 20 text

新機能を追加する→処理時間増加 レスポンス数 レスポンスタイム 100 ms 超過 増加

Slide 21

Slide 21 text

増えたらダイエット レスポンス数 レスポンスタイム 100 ms なんとか して ダイエット

Slide 22

Slide 22 text

やらかすと レスポンス数 レスポンスタイム 100 ms 会社の 存続に関わる レベルに…

Slide 23

Slide 23 text

真空中の光速 = 秒速30万キロ https://www.flickr.com/photos/walterpro/15373174944/ • 正確には299279458m/s • 100ミリ秒では太平洋すら往復できない • 光ファイバー中だと2/3 = 秒速約20万キロ • 意外に遅い

Slide 24

Slide 24 text

電気信号の速度 = 光速の6割 • 2.4GHz の CPU = 1秒間に24億サイクル • CPU の1サイクルは… = 1 / (2.4 * 1000 * 1000 * 1000) = 0.000000000416 秒 →0.416 ナノ秒 • 299279458(m/s) * 0.000000000416 * 0.6 = 0.0747 (m/サイクル) →1サイクルにつき電気信号は 7.4cm しか 進めない

Slide 25

Slide 25 text

光速が遅い

Slide 26

Slide 26 text

東京からの ネットワークレイテンシ (往復時間) 通信相手 往復時間 東京〜東京 約1〜2ミリ秒 東京〜大阪 約5〜10ミリ秒 東京〜台湾 約65ミリ秒 東京〜西海岸 100ミリ秒以上

Slide 27

Slide 27 text

東京からの ネットワークレイテンシ (往復時間) 通信相手 往復時間 東京〜東京 約1〜2ミリ秒 東京〜大阪 約5〜10ミリ秒 東京〜台湾 約65ミリ秒 東京〜西海岸 100ミリ秒以上 弊社の取引先の1つがココ

Slide 28

Slide 28 text

JSON 受信 JSON を返す ????????????? オークション開始 オークション終了 32ミリ秒 ( ´_ゝ｀) 32ミリ秒 ( ´_ゝ｀) ( ´_ゝ｀) ( ´_ゝ｀)

Slide 29

Slide 29 text

JSON 受信 JSON を返す オークション開始 オークション終了 ( ´_ゝ｀) ( ´_ゝ｀) 100ミリ秒の半分以上が 光ファイバーに もってかれる ( ´_ゝ｀) 32ミリ秒 ( ´_ゝ｀) 32ミリ秒 ( ´_ゝ｀)

Slide 30

Slide 30 text

disk disk レイテンシ源あれこれ ルータ スイッチ アプリサーバ DBサーバ スイッチ

Slide 31

Slide 31 text

レイテンシ源 (1ms = 1,000,000ns) 操作 レイテンシ LAN 上サーバ間のパケット往復 150,000 ns〜 4KbytesをSSDから読む 150,000ns HDD のシーク 10,000,000ns (10ms) 出典: https://gist.github.com/jboner/2841832

Slide 32

Slide 32 text

ハードウェア的な制約 • HDD 遅い = 最新のものでも針が動くだけで約5ms = 使えない • SSD 遅い = マイクロ秒単位 → アクセスは最小限に • LAN 遅い = 早くとも 100マイクロ秒単位 → 最小限に

Slide 33

Slide 33 text

CPUの中身にもレイテンシ源 インテル® 64 アーキテクチャーおよびIA-32 アーキテクチャー最適化リファレンス・マニュアルより抜粋

Slide 34

Slide 34 text

レイテンシ源 (1ms = 1,000,000ns) 操作 レイテンシ L1 キャッシュ上のデータ参照 0.5ns 分岐予測ミス 5ns L2 キャッシュ上のデータ参照 7ns メインメモリ上のデータ参照 100ns 出典: https://gist.github.com/jboner/2841832 https://www.quora.com/Linux-Kernel-How-much-processor-time-does-a-process-switching-cost-to-the-process-scheduler 何千回・何万回・何十万回と発生するもの ↓ 削減するには 低レベルを意識してコードを最適化する

Slide 35

Slide 35 text

レイテンシ源 (1ms = 1,000,000ns) 操作 レイテンシ Full GC (-Xmx16g –XX:UseParallelGC -XX:+UseParallelOldGC) 1,500ms〜 (1.5秒〜) Full GC (-Xmx24g -XX:+UseG1GC) 16,000ms〜 (16秒〜) young GC Stop the world (G1 GC) 80ms〜400ms 出典: 独自測定

Slide 36

Slide 36 text

今日の話 コードを最適化しよう GC の悪影響をなんとかしよう

Slide 37

Slide 37 text

今日の話 コードを最適化しよう GC の悪影響をなんとかしよう

Slide 38

Slide 38 text

基本的なこと • 「Javaパフォーマンス」を読もう Scott Oaks 著 牧野 聡 訳 Acroquest Technology株式会社 監訳 寺田 佳央 監訳 2015年04月 発行 448ページ ISBN978-4-87311-718-8

Slide 39

Slide 39 text

プロファイラで測定 • 早すぎる最適化は悪 • まずはプロファイリング • Netbeans Profilter , jprof など • 負荷をかけて測定 – なるべく本番に近い負荷をかける – しばらく放置して十分に JIT Compile させる – CPU使用率 100% に達する程度にかける – CPU使用率 100% に達しなかったら 何かが間違ってる

Slide 40

Slide 40 text

perf • Linux 向けプロファイラ • C, C++ で書いたプログラムの プロファイリングに使う • 本来 Java 向けのツールではない、が どうしても使わねばならんのだ • 実行例 perf record -F 99 -a -g -- sleep 30 && perf report

Slide 41

Slide 41 text

# Overhead Command # ........ ............... ..................................................... # 91.61% java perf-22349.map | |--13.64%-- 0x7f855ae9857b | 0xa06e0019b7d8 | |--10.68%-- 0x7f855ae98497 | | | |--99.78%-- 0xa06e0019b7d8 | --0.22%-- [...] | |--4.24%-- 0x7f855ae98380 | 0xa06e0019b7d8 | |--4.13%-- 0x7f855ae985f7 | 0xa06e0019b7d8 | |--4.11%-- 0x7f855ae98617 | 0xa06e0019b7d8 | |--2.11%-- 0x7f855ae984bf | | | |--99.36%-- 0xa06e0019b7d8 | --0.64%-- [...] | |--1.49%-- 0x7f855ae985dd 実行結果 (※壊れてます)

Slide 42

Slide 42 text

JVM による最適化の問題点(1) • Hotspot VM の生成した機械語では frame pointer が使われない (使う必要が無い) (frame pointer 用のレジスタ (x86_64 なら rbp レジスタ) を汎用レジスタとして使う) • 要するに、メソッドの呼び出し元のメソッド が判らなくなる • JVM 起動時に -XX:+PreserveFramePointer オプションを付ける

Slide 43

Slide 43 text

JVM による最適化の問題点(2) • 呼び出し頻度の多いメソッドが Inline 化され る (呼び出し元に展開される) • メソッド呼び出しのオーバーヘッドがなくな るが、perf では困る (小さいメソッドが見えなくなる) • JVM 起動時に -XX:-Inline オプションをつける

Slide 44

Slide 44 text

JVM による最適化の問題点(2) • メモリ上のアドレスとメソッド名の対応関係 がわからない • メモリ上のアドレスが実行中にころころ代わ る • perf-map-agent を使って名前を解決する https://github.com/jrudolph/perf-map-agent

Slide 45

Slide 45 text

# Overhead Command # ........ ............... ............................... 12.77% java perf-106368.map [.] Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXX;.select | --- Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.select Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.decide Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.process Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.execute Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.channelRead0 Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.channelRead0 Lio/netty/channel/SimpleChannelInboundHandler;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/channel/ChannelInboundHandlerAdapter;.channelRead Ljp/so_netmedia/rtb/buyer/application/RequestRecordingHandler;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/handler/codec/MessageToMessageDecoder;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/handler/codec/ByteToMessageDecoder;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/handler/timeout/ReadTimeoutHandler;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/channel/ChannelInboundHandlerAdapter;.channelRead Ljp/so_netmedia/rtb/buyer/application/BuyerServerLoggingHandler;.channelRead Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead Lio/netty/channel/DefaultChannelPipeline;.fireChannelRead これが 25,000行ほど続く

Slide 46

Slide 46 text

flame graph • Netflix の Brendan Gregg さんが作った perf の結果をグラフ化してくれる 優れもの • 詳しくは… http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html

Slide 47

Slide 47 text

No content

Slide 48

Slide 48 text

No content

Slide 49

Slide 49 text

No content

Slide 50

Slide 50 text

DB への アクセス部 デバイスドライバ カーネル

Slide 51

Slide 51 text

正規表現で検索もできる "HashMap" で検索した結果

Slide 52

Slide 52 text

Intel Performance Counter Monitor https://software.intel.com/en-us/articles/intel-performance-counter-monitor

Slide 53

Slide 53 text

Core (SKT) | EXEC | IPC | FREQ | AFREQ | L3MISS | L2MISS | L3HIT | L2HIT | L3MPI | L2MPI | L3OCC | TEMP 0 0 1.81 1.53 1.18 1.22 2381 K 22 M 0.89 0.12 0.00 0.01 3528 30 1 0 1.68 1.42 1.19 1.22 2363 K 22 M 0.90 0.12 0.00 0.01 3744 32 2 0 1.86 1.57 1.18 1.22 2278 K 22 M 0.90 0.11 0.00 0.01 1800 30 3 0 1.84 1.55 1.18 1.22 2172 K 22 M 0.90 0.11 0.00 0.01 1656 30 4 0 1.84 1.56 1.18 1.22 2354 K 23 M 0.90 0.11 0.00 0.01 2592 30 5 0 1.70 1.44 1.18 1.22 2287 K 22 M 0.90 0.11 0.00 0.01 2448 33 6 0 1.84 1.56 1.18 1.22 2208 K 21 M 0.90 0.12 0.00 0.01 3456 30 7 0 1.80 1.53 1.18 1.22 2266 K 22 M 0.90 0.11 0.00 0.01 2232 30 8 0 1.84 1.56 1.18 1.22 2590 K 22 M 0.88 0.12 0.00 0.01 2808 31 9 0 1.73 1.47 1.17 1.22 2645 K 23 M 0.89 0.12 0.00 0.01 3240 31 10 0 1.89 1.62 1.17 1.22 2399 K 21 M 0.89 0.12 0.00 0.00 2592 31 11 0 1.80 1.54 1.17 1.22 2483 K 20 M 0.88 0.12 0.00 0.01 2016 30 12 0 1.73 1.50 1.15 1.22 2388 K 21 M 0.89 0.11 0.00 0.01 1584 28 13 0 1.70 1.46 1.16 1.22 2338 K 21 M 0.89 0.12 0.00 0.01 3888 30 14 0 1.89 1.61 1.18 1.22 1658 K 12 M 0.87 0.63 0.00 0.00 576 30 15 0 1.70 1.48 1.14 1.22 2460 K 20 M 0.88 0.12 0.00 0.01 3816 32 16 0 1.97 1.65 1.20 1.22 1087 K 10 M 0.89 0.74 0.00 0.00 1944 29 17 0 1.78 1.53 1.16 1.22 2445 K 21 M 0.89 0.12 0.00 0.01 2880 29 --------------------------------------------------------------------------------------------------------------- SKT 0 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 46800 28 --------------------------------------------------------------------------------------------------------------- TOTAL * 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 N/A N/A Instructions retired: 75 G ; Active cycles: 49 G ; Time (TSC): 2317 Mticks ; C0 (active,non-halted) core residency: 96.57 % C1 core residency: 2.92 %; C3 core residency: 0.48 %; C6 core residency: 0.03 %; C7 core residency: 0.00 %; C2 package residency: 0.00 %; C3 package residency: 0.00 %; C6 package residency: 0.00 %; C7 package residency: 0.00 %; PHYSICAL CORE IPC : 1.53 => corresponds to 38.28 % utilization for cores in active state Instructions per nominal CPU cycle: 1.80 => corresponds to 45.00 % core utilization over time interval --------------------------------------------------------------------------------------------------------------- ※Intel Xeon E5-2699v3 で実行中の様子。CPU によって違うかも

Slide 54

Slide 54 text

Core (SKT) | EXEC | IPC | FREQ | AFREQ | L3MISS | L2MISS | L3HIT | L2HIT | L3MPI | L2MPI | L3OCC | TEMP 0 0 1.81 1.53 1.18 1.22 2381 K 22 M 0.89 0.12 0.00 0.01 3528 30 1 0 1.68 1.42 1.19 1.22 2363 K 22 M 0.90 0.12 0.00 0.01 3744 32 2 0 1.86 1.57 1.18 1.22 2278 K 22 M 0.90 0.11 0.00 0.01 1800 30 3 0 1.84 1.55 1.18 1.22 2172 K 22 M 0.90 0.11 0.00 0.01 1656 30 4 0 1.84 1.56 1.18 1.22 2354 K 23 M 0.90 0.11 0.00 0.01 2592 30 5 0 1.70 1.44 1.18 1.22 2287 K 22 M 0.90 0.11 0.00 0.01 2448 33 6 0 1.84 1.56 1.18 1.22 2208 K 21 M 0.90 0.12 0.00 0.01 3456 30 7 0 1.80 1.53 1.18 1.22 2266 K 22 M 0.90 0.11 0.00 0.01 2232 30 8 0 1.84 1.56 1.18 1.22 2590 K 22 M 0.88 0.12 0.00 0.01 2808 31 9 0 1.73 1.47 1.17 1.22 2645 K 23 M 0.89 0.12 0.00 0.01 3240 31 10 0 1.89 1.62 1.17 1.22 2399 K 21 M 0.89 0.12 0.00 0.00 2592 31 11 0 1.80 1.54 1.17 1.22 2483 K 20 M 0.88 0.12 0.00 0.01 2016 30 12 0 1.73 1.50 1.15 1.22 2388 K 21 M 0.89 0.11 0.00 0.01 1584 28 13 0 1.70 1.46 1.16 1.22 2338 K 21 M 0.89 0.12 0.00 0.01 3888 30 14 0 1.89 1.61 1.18 1.22 1658 K 12 M 0.87 0.63 0.00 0.00 576 30 15 0 1.70 1.48 1.14 1.22 2460 K 20 M 0.88 0.12 0.00 0.01 3816 32 16 0 1.97 1.65 1.20 1.22 1087 K 10 M 0.89 0.74 0.00 0.00 1944 29 17 0 1.78 1.53 1.16 1.22 2445 K 21 M 0.89 0.12 0.00 0.01 2880 29 --------------------------------------------------------------------------------------------------------------- SKT 0 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 46800 28 --------------------------------------------------------------------------------------------------------------- TOTAL * 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 N/A N/A Instructions retired: 75 G ; Active cycles: 49 G ; Time (TSC): 2317 Mticks ; C0 (active,non-halted) core residency: 96.57 % C1 core residency: 2.92 %; C3 core residency: 0.48 %; C6 core residency: 0.03 %; C7 core residency: 0.00 %; C2 package residency: 0.00 %; C3 package residency: 0.00 %; C6 package residency: 0.00 %; C7 package residency: 0.00 %; PHYSICAL CORE IPC : 1.53 => corresponds to 38.28 % utilization for cores in active state Instructions per nominal CPU cycle: 1.80 => corresponds to 45.00 % core utilization over time interval --------------------------------------------------------------------------------------------------------------- ※Intel Xeon E5-2699v3 で実行中の様子。CPU によって違うかも 意味わからないと思うので解説

Slide 55

Slide 55 text

CPUの中身 インテル® 64 アーキテクチャーおよびIA-32 アーキテクチャー最適化リファレンス・マニュアルより抜粋 (24コアの CPU の例)

Slide 56

Slide 56 text

CPUコアの中身 インテル® 64 アーキテクチャーおよびIA-32 アーキテクチャー最適化リファレンス・マニュアルより抜粋

Slide 57

Slide 57 text

CPUコアの中身 インテル® 64 アーキテクチャーおよびIA-32 アーキテクチャー最適化リファレンス・マニュアルより抜粋 ALU = 整数演算器 1コアに3個ある (同時に3つの計算ができる）

Slide 58

Slide 58 text

CPUコアの中身 インテル® 64 アーキテクチャーおよびIA-32 アーキテクチャー最適化リファレンス・マニュアルより抜粋 なるべく演算器の 稼働率が高くなるように 命令を並び替える

Slide 59

Slide 59 text

メモリはすごく遅い • 足し算1回…0.5サイクル • L1 キャッシュ ... 5サイクル • L2 キャッシュ … 12サイクル • L3 キャッシュ… 42サイクル • メインメモリ…もっと • メモリアクセスが多いと計算ユニットが 空回りする = CPU使用率100%でも CPU の中身は ほとんど遊んでたりする (Intel Skylake アーキテクチャの場合）

Slide 60

Slide 60 text

キャッシュ階層 メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ …45MB/28コア …256KB/コア …64KB/コア 64GB くらい メインメモリは遠い・遅いので、まずキャッシュメモリを順番に参照する データが無ければ… データが無ければ… データが無ければ… 欲しいデータ (Intel Haswell-EP アーキテクチャの場合）

Slide 61

Slide 61 text

2回目の参照に備えて… メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ 45MB/28コア 256KB/コア 64KB/コア 64GB くらい 1回目の参照後、2回目の参照に備えてただちにキャッシュメモリに書き込んでいく データ データ データ データ

Slide 62

Slide 62 text

2回目の参照は… メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ 45MB/28コア 256KB/コア 64KB/コア 64GB くらい データ データ データ データ ここにある! すぐ取れる!

Slide 63

Slide 63 text

容量がいっぱいになると消える けど… メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ 45MB/28コア 256KB/コア 64KB/コア 64GB くらい データ データ データ ここには残ってる!!

Slide 64

Slide 64 text

容量がいっぱいになると消える けど… メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ 45MB/28コア 256KB/コア 64KB/コア 64GB くらい データ データ L2 から消えても ここには残ってる!!

Slide 65

Slide 65 text

64バイト一気に取ってくる メインメモリ L3キャッシュ L2キャッシュ L1キャッシュ メモリアクセスは64バイト (Java long 8個分)。隣接するデータも一緒に取ってくる 64バイトのデータ 64バイトのデータ 64バイトのデータ 64バイトのデータ

Slide 66

Slide 66 text

Core (SKT) | EXEC | IPC | FREQ | AFREQ | L3MISS | L2MISS | L3HIT | L2HIT | L3MPI | L2MPI | L3OCC | TEMP 0 0 1.81 1.53 1.18 1.22 2381 K 22 M 0.89 0.12 0.00 0.01 3528 30 1 0 1.68 1.42 1.19 1.22 2363 K 22 M 0.90 0.12 0.00 0.01 3744 32 2 0 1.86 1.57 1.18 1.22 2278 K 22 M 0.90 0.11 0.00 0.01 1800 30 3 0 1.84 1.55 1.18 1.22 2172 K 22 M 0.90 0.11 0.00 0.01 1656 30 4 0 1.84 1.56 1.18 1.22 2354 K 23 M 0.90 0.11 0.00 0.01 2592 30 5 0 1.70 1.44 1.18 1.22 2287 K 22 M 0.90 0.11 0.00 0.01 2448 33 6 0 1.84 1.56 1.18 1.22 2208 K 21 M 0.90 0.12 0.00 0.01 3456 30 7 0 1.80 1.53 1.18 1.22 2266 K 22 M 0.90 0.11 0.00 0.01 2232 30 8 0 1.84 1.56 1.18 1.22 2590 K 22 M 0.88 0.12 0.00 0.01 2808 31 9 0 1.73 1.47 1.17 1.22 2645 K 23 M 0.89 0.12 0.00 0.01 3240 31 10 0 1.89 1.62 1.17 1.22 2399 K 21 M 0.89 0.12 0.00 0.00 2592 31 11 0 1.80 1.54 1.17 1.22 2483 K 20 M 0.88 0.12 0.00 0.01 2016 30 12 0 1.73 1.50 1.15 1.22 2388 K 21 M 0.89 0.11 0.00 0.01 1584 28 13 0 1.70 1.46 1.16 1.22 2338 K 21 M 0.89 0.12 0.00 0.01 3888 30 14 0 1.89 1.61 1.18 1.22 1658 K 12 M 0.87 0.63 0.00 0.00 576 30 15 0 1.70 1.48 1.14 1.22 2460 K 20 M 0.88 0.12 0.00 0.01 3816 32 16 0 1.97 1.65 1.20 1.22 1087 K 10 M 0.89 0.74 0.00 0.00 1944 29 17 0 1.78 1.53 1.16 1.22 2445 K 21 M 0.89 0.12 0.00 0.01 2880 29 --------------------------------------------------------------------------------------------------------------- SKT 0 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 46800 28 --------------------------------------------------------------------------------------------------------------- TOTAL * 1.80 1.53 1.18 1.22 40 M 375 M 0.89 0.20 0.00 0.00 N/A N/A Instructions retired: 75 G ; Active cycles: 49 G ; Time (TSC): 2317 Mticks ; C0 (active,non-halted) core residency: 96.57 % C1 core residency: 2.92 %; C3 core residency: 0.48 %; C6 core residency: 0.03 %; C7 core residency: 0.00 %; C2 package residency: 0.00 %; C3 package residency: 0.00 %; C6 package residency: 0.00 %; C7 package residency: 0.00 %; PHYSICAL CORE IPC : 1.53 => corresponds to 38.28 % utilization for cores in active state Instructions per nominal CPU cycle: 1.80 => corresponds to 45.00 % core utilization over time interval --------------------------------------------------------------------------------------------------------------- ※Intel Xeon E5-2699v3 で実行中の様子。CPU によって違うかも

Slide 67

Slide 67 text

読み方 • IPC – instruction per cycle – 命令を1サイクルで何個できたか – (CPUによって違うけど) 2 超えたらすごいと思う – 1を割っている場合は… = 演算ユニットがメモリアクセス待ちで 待っている = (理論上) もっと改善できる • L3hit … L3 キャッシュヒット率 • L2hit … L2 キャッシュヒット率

Slide 68

Slide 68 text

perf のいいところ • L2 キャッシュミスの発生している箇所を 特定できる perf record -F 99 -a -g -e cache-misses

Slide 69

Slide 69 text

# ........ ............... ................................ ..... # 5.28% java perf-106368.map [.] Ljava/util/Arrays;.binarySearch0 | --- Ljava/util/Arrays;.binarySearch0 | |--96.20%-- Ljava/util/Arrays;.binarySearch | Ljp/so_netmedia/rtb/kvs/domain/user/XXXXXXXXXXXXXXX;.XXXXXXXXXXXXXXX | Ljp/so_netmedia/rtb/kvs/domain/user/XXXXXXXXXXXXXXX;.XXXXXXXXXXXXXXX | Ljp/so_netmedia/rtb/kvs/domain/user/XXXXXXXXXXXXXXX;.XXXXXXXXXXXXXXX | Ljp/so_netmedia/rtb/kvs/domain/user/XXXXXXXXXXXXXXX;.XXXXXXXXXXXXXXX | Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.isCalculated | Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.match | Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.select | Ljp/so_netmedia/rtb/buyer/domain/buyer/XXXXXXXXXXXXXXX;.decide | Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.process | Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.execute | Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.channelRead0 | Ljp/so_netmedia/rtb/buyer/application/XXXXXXXXXXXXXXX;.channelRead0 | Lio/netty/channel/SimpleChannelInboundHandler;.channelRead | Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead | Lio/netty/channel/AbstractChannelHandlerContext;.fireChannelRead | Lio/netty/channel/ChannelInboundHandlerAdapter;.channelRead | Ljp/so_netmedia/rtb/buyer/application/RequestRecordingHandler;.channelRead | Lio/netty/channel/AbstractChannelHandlerContext;.invokeChannelRead java.util.Arrays.binarySearch は L2キャッシュミス発生源 アルゴリズム的に仕方無い

Slide 70

Slide 70 text

12.40% java perf-106368.map [.] Ljava/util/HashMap;.getNode | --- Ljava/util/HashMap;.getNode | |--35.09%-- Ljava/util/LinkedHashMap;.get | | | |--62.05%-- Ljp/so_netmedia/rtb/...... | | | | | |--89.88%-- Ljp/so_netmedia/rtb/buyer/domain/.... | | | Ljp/so_netmedia/rtb/buyer/domain/..... | | | Ljp/so_netmedia/rtb/buyer/domain/ | | | Ljp/so_netmedia/rtb/buyer/domain/ | | | Ljp/so_netmedia/rtb/buyer/domain/ | | | Ljp/so_netmedia/rtb/buyer/application | | | Ljp/so_netmedia/rtb/buyer/application/ | | | Ljp/so_netmedia/rtb/buyer/application | | | Ljp/so_netmedia/rtb/buyer/application | | | Lio/netty/channel/..... | | | Lio/netty/channel/...... | | | Lio/netty/channel java.util.HashMap.get は L2キャッシュミス発生源 データの持ち方を変えることで改善できる(かも)

Slide 71

Slide 71 text

正規表現を使って着色 HashMap" で検索した結果

Slide 72

Slide 72 text

オブジェクトはメモリ上でどう表現されるか class Hoge { } new Hoge(); コード クラス定義への pointer(4バイト) GC 用 フラグ(4バイト) ロック用のフラグ (4バイト) ヒープ ※64bit環境・ヒープサイズ32GB以下のとき。以下同様

Slide 73

Slide 73 text

以降、このように表記 クラス定義への pointer(4バイト) フラグ類 (4バイト) ロック用のフラグ (4バイト) ヘッダ (12バイト)

Slide 74

Slide 74 text

オブジェクトを3つ作ってみた class Hoge { } new Hoge(); new Hoge(); new Hoge(); コード ヒープ ヘッダ (12バイト) ヘッダ (12バイト) ヘッダ (12バイト)

Slide 75

Slide 75 text

インスタンス変数はヘッダ直下に class Hoge { int a = 1; } new Hoge(); コード 変数 a (4バイト) ヒープ ヘッダ (12バイト)

Slide 76

Slide 76 text

並び替えされる class Hoge { int a = 1; long b = 2; } new Hoge(); コード 変数 b (8バイト) 変数 a (4バイト) ヒープ ヘッダ (12バイト)

Slide 77

Slide 77 text

参照型 Integer.valueOf(12345) コード 数値12345 (4バイト) ヒープ ヘッダ (12バイト) ヘッダ (12バイト) 数値67890L (8バイト) Long.valueOf(67890L)

Slide 78

Slide 78 text

配列 new int[] { 1, 2, 3 }; コード ヒープ ヘッダ (12バイト) 数値 “1” (4バイト) 数値 “2” (4バイト) 数値 “3” (4バイト) 配列の長さ “3” (4バイト)

Slide 79

Slide 79 text

参照 class A { } class B { A a = new a(); } new B(); コード ヒープ a のヘッダ (12バイト) b のヘッダ (12バイト) ポインタ (4バイト)

Slide 80

Slide 80 text

HashMap HashMap m = new HashMap<>(); m.put("Apple", 3); m.put("Orange", 2); m.put("Banana", 10);

Slide 81

Slide 81 text

HashMap m HashMap$Node[16] "Apple" 3 "Orange" "Banana" 10 2 HashMap$Node HashMap$Node HashMap$Node key value key value key value 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15

Slide 82

Slide 82 text

Eclipse Collections を使う MutableObjectIntMap m2 = ObjectIntMaps.mutable.of(); m2.put("Apple", 3); m2.put("Orange", 2); m2.put("Banana", 10);

Slide 83

Slide 83 text

ObjectIntHashMap m Object[8] keys "Apple" "Orange" "Banana" int[8] values 0 1 2 3 4 5 6 7 0 1 2 3 4 5 6 7 10 0 3 0 0 2 0 0 全体のサイズが小さくなる。キャッシュにも乗りやすい

Slide 84

Slide 84 text

HashSet → ArrayList へ置換 してみた • HashSet – 中身は HashMap – add, get, remove, contains, size の 実行時間が O(1) • ArrayList – 中身は配列 – get, remove, contains, size の実行時間が O(N) O(1) < O(N) のはずなんだが…

Slide 85

Slide 85 text

レスポンスタイム半減 WRYYYYYYYYYYYYYYYYY

Slide 86

Slide 86 text

もっとやりたい人 • HotSpot VM が生み出した機械語を 逆アセンブルして見てみましょう。 詳しい使い方はおググりください -XX:+PrintAssembly : 0x000000010d528f80: mov %eax,-0x14000(%rsp) 0x000000010d528f87: push %rbp 0x000000010d528f88: sub $0x30,%rsp 0x000000010d528f8c: movabs $0x12166e950,%rax 0x000000010d528f96: mov 0x8(%rax),%edi 0x000000010d528f99: add $0x8,%edi 0x000000010d528f9c: mov %edi,0x8(%rax) 0x000000010d528f9f: movabs $0x12166e460,%rax ; {metadata({method} {0x000000012166e460} 'disjoint' '([I[I)Z' in '.......

Slide 87

Slide 87 text

ここまで来れば • 逆アセンブル結果を見て Java のソースを 書き換えることで高速化できる • ループアンローリング等、C/C++ でしか 有効でないと思われていたテクニックも Java で使える • インラインアセンブラを使えない点を除けば ほとんど C/C++ と同レベルの最適化が できる • ただし GC だけはどうしようもない

Slide 88

Slide 88 text

今日の話 コードを最適化しよう GC の悪影響をなんとかしよう

Slide 89

Slide 89 text

ヒープをケチると GC 大量発生 リクエスト数 レスポンスタイム 100 ms 会社の 存続に関わる レベルに…

Slide 90

Slide 90 text

G1 GC しかない • G1 GC は非常に優秀 • G1 GC については JJUG CCC 2015 Fall の KUBOTA Yuji さんの発表を参照 http://www.slideshare.net/YujiKubota/garbage- first-garbage-collection • 大量にヒープとCPUコアを割り当てれば Full GC が滅多に起きない

Slide 91

Slide 91 text

GC による Stop the world • -XX:+UseParallelGC → 0.3% -XX:+UseG1GC → 0.1% • もはや G1 GC でいいんじゃないか • 弊社の主戦力は G1 GC 、ヒープ30GBytes

Slide 92

Slide 92 text

ヒープ 30GBytes の世界 • ヒープダンプ取れない (取るのに10時間以上かかる…) • 取れても VisualVM で開けない (大量のメモリを積んだマシンでないと…) • 開けても解析できない (OQL 1つ走らせるのに2時間以上…) ヒーププロファイリング困難

Slide 93

Slide 93 text

恐怖の GCLocker Initiated GC • JNI API の GetPrimitiveArrayCritical GetStringCritical を呼ぶと GC の実行が保留される →そのまま放置すると OutOfMemoryError • ReleasePrimitiveArrayCritical ReleaseStringCritical を呼ぶと GC が再開する →GC 保留中にたまったガベージを 一気に回収する = 時間がかかることがある

Slide 94

Slide 94 text

使ってはいけない Java SE API java.io.ObjectInputStream#bytesToFloats, bytesToDoubles java.io.ObjectOutputStream#floatsToBytes, doublesToBytes java.nio.Bits#copyFromShortArray, copyToShortArray java.nio.Bits#copyFromIntArray, copyToIntArray java.nio.Bits#copyFromLongArray, copyToLongArray java.util.zip.Adler32#updateBytes java.util.zip.CRC32#updateBytes java.util.zip.Deflater#setDictionary, deflateBytes java.util.zip.Inflater#setDictionary, inflateBytes java.lang.ClassLoader$NativeLibrary.load, unload java.lang.ClassLoader#findBuiltinLib java.util.TimeZone#getSystemTimeZoneID java.util.zip.ZipFile#open GCLocker Initiated GC を発生させるので、使わない!

Slide 95

Slide 95 text

GClocker Initiated GC 対策 • GC ログを見て、 GClocker Initated GC を見たら直ちに 「使ってはいけないAPI」を使っている 箇所を特定し、駆逐して差し上げる • ライブラリの中でも使っていたりする • デバッガを使って「使ってはいけない API」 を使っている箇所を燻り出す

Slide 96

Slide 96 text

モニタリング • GC ログを監視 – GCはさだめ – さだめは死 – 己のさだめをうけとめよ • HTTPレスポンスのパーセンタイル値を 監視 – 99.9、99、98、95、75、50パーセンタイル値

Slide 97

Slide 97 text

弊社の現状 • 平均 約 5 ms でレスポンスを返しています • 99.5% のリクエストは 100 ミリ秒以内に 返しています • 今後もがんばります。Java で戦い続けます • 他にも色々テクニックがありますが またの機会に

Slide 98

Slide 98 text

おわり