読者です 読者をやめる 読者になる 読者になる

見習いプログラミング日記

Java EE を中心に色々なことを考えてみます。目指せ本物のプログラマ。

EmbulkでアクセスログをLogstash風に取り込む

ELK

トラブルシューティング時に、バッチ取り込みによるKibanaアクセスログ可視化を行う場合、ログの取り込みに掛かる時間は短い程嬉しい。

もちろん測定条件やチューニングにも依存すると思うが、手元のマシン*1においては、Logstash2.2を使うより、Embulk v0.8.5を使った方が早かった*2

Logstashではgrokのおかげで、たとえばリクエストURLならrequestフィールドなど、フィールド名が固定化されるが、Embulkの場合、各人が自由にパースすると各々の項目に対して微妙に異なるフィールド名を付与し、チームでダッシュボードが共有しにくい。

Logstashの以下のコンフィグで読み込んだフィールドの構成と同じように、EmbulkでElasticsearchにデータをロードできないか考えたのでメモする。

input {
  stdin {}
}

filter {
  grok {
    match => {
      "message" => "%{COMMONAPACHELOG}"
    }
  }
  date {
    match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z" ]
    locale => "en"
  }
  mutate {
    convert => { "bytes" => "integer" }
  }
}

output {
  elasticsearch {}
}

セットアップ

Embulkのインストール
curl --create-dirs -o ~/.embulk/bin/embulk -L "http://dl.embulk.org/embulk-latest.jar
echo 'export PATH="$HOME/.embulk/bin:$PATH"' >> ~/.bashr
source ~/.bashrc
Embulkプラグインのインストール

Logstashユーザにとって、特にembulk-parser-grokプラグインは嬉しい。Logstashを同じ感覚で、ログのパース条件を定義できる。

embulk gem install embulk-parser-grok
embulk gem install embulk-filter-column
embulk gem install embulk-output-elasticsearch
Embulkのコンフィグ

作業ディレクトリを適当な場所に作って、

mkdir ~/work
cd ~/work
vim httpd-embulk.yml

以下のようにEmbulkのコンフィグを作成。

in:
  type: file
  path_prefix: log/access_log
  parser:
    type: grok
    grok_pattern_files:
      - grok-patterns
#    grok_pattern: '%{COMBINEDAPACHELOG}'
    grok_pattern: '%{COMMONAPACHELOG}'
    timestamp_parser: SimpleDateFormat
    default_timezone: 'Japan'
    charset: UTF-8
    newline: LF
    columns:
    - {name: COMMONAPACHELOG, type: string}
    - {name: clientip,     type: string}
    - {name: ident,        type: string}
    - {name: auth,         type: string}
    - {name: timestamp,    type: timestamp, format: '%d/%b/%Y:%T %z'}
    - {name: verb,         type: string}
    - {name: request,      type: string}
    - {name: httpversion,  type: string}
    - {name: response,     type: string}
    - {name: bytes,        type: long}
#    - {name: referrer,     type: string}
#    - {name: agent,        type: string}

filters:
  - type: column
    add_columns:
      - {name: "@timestamp", src: timestamp}
      - {name: "host", type: string, default: "localhost.localdomain"}
  - type: rename
    columns:
      COMMONAPACHELOG: message
#    COMBINEDAPACHELOG: message

out:
  type: elasticsearch
  nodes:
  - {host: localhost, port: 9300}
  cluster_name: my-application
  index: logstash-1995
  index_type: "access_log"

Apacheアクセスログは、~/work/log/にaccess_logから始まるファイル名で格納する。COMBINED形式のログを読み込む時は、コメントアウトされた部分を外して、grok_pattern: '%{COMMONAPACHELOG}'をコメントアウトする。適当なアクセスログがない場合は、NASAのアクセスログが練習に便利。

localhost.localdomeinの部分は、取り込み対象のアクセスログを出力したマシンのホスト名になおす。

grokパターンはLogstashのgrokに含まれるgrok-patternsをそのまま持ってくる。

cp logstash-2.2.0/vendor/bundle/jruby/1.9/gems/logstash-patterns-core-2.0.2/patterns/grok-patterns ~/work
インデックステンプレートの登録

Logstashでデータを取り込むと、termで集計しやすいようにrequest.rawなどの非アナライズフィールドが生成されるが、これはLogstashのElasticsearchプラグインがインデックステンプレートとしてrawフィールドを生成しているため。Embulkでも同様のフィールドを作るために、Logstashから持ってきて登録する。

cp  logstash-2.2.0/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-2.4.1-java/lib/logstash/outputs/elasticsearch/elasticsearch-template.json ~/work
curl -XPUT http://localhost:9200/_template/logstash -d @elasticsearch-template.json
Embulkで取り込み開始
embulk run httpd-embulk.yml

私の手元のマシンでは、NASAのログ(NASA_access_log_Jul95, 196MB, 1891714行)が7分程で取り込み完了。

ダッシュボードで可視化

gistにサンプルダッシュボードを張ってるので、このexport.jsonをKibanaのSettingsタブ -> Objects からimportボタンでアップロードする。

可視化したい時間帯を指定すると、以下のようにダッシュボードが表示される。
f:id:n_agetsuma:20160224223640p:plain

まとめ

grok.patternsとelasticsearch-template.jsonをLogstashから持ってくることにより、LogstashユーザでもEmbulkが扱いやすくなります。

Logstashを前提に色々ダッシュボードを作っていても、上記のようなやり方でEmbulkで取り込んだ時にもダッシュボードが流用できそうです。

*1:Mac Book Air 2013 Mid/Core i5 1.7GB/Mem 4G

*2:私の環境では約20%ほどEmbulkが早かった。あくまで環境や条件に依存すると思う。

Kibana4.4.0の機能追加

ELK

2016/02/02にリリースされたkibana4.4.0に欲しかった機能が入っていたのでメモ。
詳細は公式のリリースノート Kibana 4.4 Release Notes を参照。

4.1から起動スクリプトを含むRPMファイルもリリースされている。公式のダウンロード リンクにはなく、yum経由でのインストールのみ紹介されているが、閉鎖的な環境など、yumが使えない場合は以下からダウンロード可能。

http://packages.elastic.co/kibana/4.4/centos/kibana-4.4.0-1.x86_64.rpm

kibana4.4.0を利用するためには、Elasticsearchも2.2.0に上げる必要がある。Elasticsearch側が古いと、以下のようにkibanaのエラーが出力される。

log   [00:29:45.283] [error][status][plugin:elasticsearch] Status changed from yellow to red - This version of Kibana requires Elasticsearch ^2.2.0 on all nodes. I found the following incompatible nodes in your cluster: Elasticsearch v2.1.1 @ 127.0.0.1:9200 (127.0.0.1)

グラフ項目の色指定

凡例の項目をクリックするとカラーパレットが表示され、グラフ項目を好きな色に変更できるようになった。このような可視化ツールを人に見せると、真っ先に挙がる要望にグラフ色の変更があるが、対応できるようになった。
f:id:n_agetsuma:20160206001015p:plain
f:id:n_agetsuma:20160206001022p:plain

短縮URLの表示

画像はクリックで拡大。
ダッシュボードへのリンクは以下のようにとても長いものであったが、
f:id:n_agetsuma:20160206000958p:plain


赤で囲った部分のボタンを押す事で短縮URLが表示可能になった。メールに貼付けて送る時に便利。
f:id:n_agetsuma:20160206001005p:plain

折り返されたvisualization nameのツールチップ表示

画面の解像度が狭い/グラフタイトルが長いと、... と末尾が省略されるが、フォーカスさせるとツールチップとしてグラフ名の全体が表示されるようになった。
f:id:n_agetsuma:20160206001131p:plain

CentOS7でOpenJDKのソースツリー取得時に/dev/stdout: Permission denied

OpenJDK

手元の環境を再構築したときにハマったのでメモ。

get_source.shでエラー

CentOS7でOpenJDK9のソースコードを取得しようとすると、以下のようなエラーが発生してget_source.shでソースコードがhg cloneできない。

hg clone http://hg.openjdk.java.net/jdk9/jdk9/
cd jdk9/jdk9
sh get_source.sh
./common/bin/hgforest.sh: 行 286: /dev/stdout: Permission denied
./common/bin/hgforest.sh: 行 377: /dev/stdout: Permission denied
./common/bin/hgforest.sh: 行 377: /dev/stdout: Permission denied

他の色々のページでも言及されているように、シンボリックリンクである/dev/stdoutの最終的な参照先である、/dev/pts/0のオーナーがrootなので、一般ユーザでは権限ではないと言われている。

ls -l /dev/stdout
lrwxrwxrwx. 1 root root 15  25 20:12 /dev/stdout -> /proc/self/fd/1
ls -l /proc/self/fd/1
lrwx------. 1 openjdk openjdk 64  25 20:52 /proc/self/fd/1 -> /dev/pts/0
$ ls -l /dev/pts/0
crw--w----. 1 root tty 136, 0  25 20:54 /dev/pts/0

get_source.shの中で呼ばれているhgforest.shには以下のようなリダイレクトが多くあり、デフォルトは変数status_outputが/dev/stdoutを指し示している。これにより、上記のようなエラーが発生している。

vim common/bin/hgforest.sh
 99 # Make sure we have a command.
100 if [ ${#} -lt 1 -o -z "${1:-}" ] ; then
101   echo "ERROR: No command to hg supplied!" > ${status_output}
102   usage > ${status_output}

対処

1つずつ以下のようにコメントアウトするのはとても面倒なので、

#echo "ERROR: No command to hg supplied!" > ${status_output}
echo "ERROR: No command to hg supplied!"

hgforest.shが参照している標準出力抑止用のオプション環境変数 HGFOREST_QUIET=true を設定すると、${status_output}が/dev/nullに切り替わり、エラーが出ずにソースツリーが取得できる。

export HGFOREST_QUIET=true
sh get_source.sh

ソースが取得できたらビルドする。

# OpenJDK9のビルド
sh configure
make all

JDK8(Linux 64bit)のデフォルトヒープサイズ

Java SE OpenJDK

Oracleの公式ドキュメントには、-Xmxが未指定であった場合のエルゴノミクスによる最大ヒープサイズは『32GBを上限として、物理メモリの4分の1』書かれている。32GBは-XX:-UseCompressedOopsにより圧縮Oopを明示的に無効にした場合の最大デフォルトヒープサイズで、何もオプションを付けずに起動した場合は29GBが上限。

ヒープサイズの決定はarguments.cppのArguments::set_heap_size()で計算されている。デフォルトの最大および初期ヒープサイズは、物理メモリ量により異なる。

デフォルト最大ヒープサイズ(-Xmx)

物理メモリが248MB以下の場合

物理メモリの2分の1。
248MBは-XX:MaxHeapSize(デフォルト124MB) x -XX:MinRAMFraction(デフォルト2)の値。

物理メモリが248MBより大きい場合

物理メモリの4分の1。
4分の1というのは-XX:MaxRAMFraction(デフォルト4)の値。例えば以下のようなオプションを指定した場合は、物理メモリの8分の1をエルゴノミクスで決められる最大ヒープサイズとすることが可能。

java -XX:MaxRAMFraction=8 ...

上限値は、デフォルトで29GB。デフォルト有効化されているOop圧縮を-XX:-UseCompressedOopsで明示的に無効化している状況では32GB。

この29GBは、同じargument.cppにあるmax_heap_for_compressed_oops()で計算されたOop圧縮有効時の最大ヒープサイズ(手元の環境では34357641216B/31GB)から、-XX:HeapBaseMinAddress(Linuxはデフォルト2GB)を引いた値。

デフォルト初期ヒープサイズ(-Xms)

物理メモリが384MB以下の場合

6MB。
物理メモリの64分の1の値が-XX:OldSize(デフォルト5MB) + -XX:NewSize(デフォルト1MB)の6MBを下回る場合は、初期ヒープサイズは6MBに設定される。

物理メモリが384MBより大きい場合

物理メモリの64分の1。
MaxRAMFractionと同様に、以下のようにオプション-XX:MinRAMFractionを設定すると、物理メモリの8分の1をエルゴノミクスで決められる初期ヒープサイズにすることが可能。

java -XX:MinRAMFraction=8 ...

ここまでの内容を踏まえて、例えば物理メモリ32GBの場合、何もオプションを指定しないと以下と同等です。思ったより最大ヒープサイズが大きいなと思う方も多いと思います。

java -Xms512m -Xmx8g ...

まとめ

64bitJVMのエルゴノミクスの挙動は、物理メモリ128GBまでは積むほど最大ヒープサイズが大きくなります。WebサーバやDBは、メモリを積むほど動作が軽快になることが多いです。しかし、Javaに限っては-Xms -Xmxが設定されていないと、4多重以上のJavaプロセス起動によりスワップが出続けるようなことが起こり得ます。

特にバッチタスクのように、並行で多数JVMを起動させる場合は注意が必要です。

Javaバッチ処理のNFS向けファイルI/O

この記事は Java EE Advent Calendar 2015の12/7分の記事です。
明日は@btnrougeさんです。


Java EEAPIが直接関連する話ではなくて恐縮ですが、サーバサイドJavaでファイルI/Oを含むバッチ処理の性能Tipsをまとめます。

テーマはjava.io.BufferedWriterクラスのバッファサイズについてです。
デフォルトは8KBでBufferedWriterのコンストラクタにおいて変更可能ですが、javadocには以下の記載があります。

バッファのサイズは、デフォルト値のままにすることも、特定の値を指定することもできます。デフォルト値は、通常の使い方では十分な大きさです。

http://docs.oracle.com/javase/jp/8/docs/api/java/io/BufferedWriter.html

あまり変更する機会もないせいか、Java SE 7で導入された便利なFiles.newBuffertedWriterメソッドにはバッファサイズを設定する引数がありません。

しかし、NFSへの書き込み時においては、mountオプションnoac*1の有効時にバッファサイズ拡大が効果的なケースがあります。

Javaバッチ処理のシステム連携において、NFSサーバにファイルを置くファイル連携方式は、業務システムで見かける構成かと思います。

効果測定

手元の仮想マシンでバッファサイズ変更時の書き込み性能を実測してみます。

  • NFSサーバ/クライアントともにCentOS7
  • java 1.8.0_65
  • NFSパラメータは以下の通り

NFSの環境設定
NFSサーバ: /etc/exports

/nfs_export/batch 192.168.xxx.xxx(rw)

NFSクライアント: マウントオプションnoac

mount -o noac 192.168.xxx.xxx:/nfs_export/batch /nfs

NFSクライアント: /proc/mounts

192.168.xxx.xxx:/nfs_export/batch /nfs nfs4
rw,sync,relatime,vers=4.0,rsize=131072,wsize=131072,namlen=255,
acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,noac,
proto=tcp,port=0,timeo=600,retrans=2,sec=sys,
clientaddr=192.168.xxx.xxx,local_lock=none,addr=192.168.xxx.xxx 0 0

検証コード
ローカルファイルシステム上のddで生成した100MBファイルのダミーデータ(test.src)を、NFSマウント上のパスにコピーするシンプルな処理です。

public class Fcopy {
    
    private static final String SRC = "/home/test/input/test.src";
    private static final String DST = "/nfs/test.dst";
    
    public static void main(String ... args) throws IOException {        
        int bufSize = Integer.valueOf(args[0]);
        byte[] buf = new byte[8192];
        
        try (
          BufferedInputStream bis 
            = new BufferedInputStream(Files.newInputStream(Paths.get(SRC)));
          BufferedOutputStream bos
            = new BufferedOutputStream(Files.newOutputStream(Paths.get(DST)), bufSize)) {
            
            long start = System.currentTimeMillis();
            for (int readSize = bis.read(buf); readSize >= 0; readSize = bis.read(buf)) {
                bos.write(buf);
            }
            long time = start - System.currentTimeMillis();
            System.out.println("BufferedStream bufSize: " + bufSize + " Time(millisec): " + time);
        }
    }
}

測定結果

以下のような結果となりました。デフォルトのNFSクライアントの非同期書き込みには及ばないものの、BufferedWriterのバッファサイズ変更で、数倍の処理時間差が見られます*2

BufferedWriterのバッファサイズ 処理時間(ミリ秒)
8192 (8KB, デフォルト) 36857
65536(64KB) 18452
131072(128KB) 7888
(参考) 8192/NFSクライアント側の非同期書き込み 407

なぜ早くなったか

ここから先はNFS実装の知識が足りず、若干自信なしです。

/proc/mountsの結果を振り返ると、wsizeが131072です。man nfsを見ると、wsizeはNFSクライアントがNFSサーバに一度に書き込むサイズを示しています。wsizeは明示的に指定しない場合、クライアントサーバ間で適切な値を自動的に決定します。

192.168.56.101:/nfs_export/batch /nfs nfs4 rw,sync,relatime,vers=4.0,rsize=131072,wsize=131072 ...

デフォルトの非同期NFSクライアントの場合は、ある程度まとまったデータをwsize単位(例では128KB)でNFSサーバに送ります。しかし、noacにより同期書き込みになった場合は、writeシステムコールの都度サーバに書き込まれるため、JavaのBufferedWriterの単位でNFSサーバに書き出されます。tcpdumpで見ると、noacオプションを付けてマウントした場合はLen:が示すWRITE RPCのサイズがJava側のバッファサイズと同じです。

BuffertedWriterのバッファサイズが8192の場合

 11 0.029289000 192.168.56.102 -> 192.168.56.101 NFS 1222 V4 Call WRITE StateID: 0x6366 Offset: 0 Len: 8192
 14 0.035469000 192.168.56.101 -> 192.168.56.102 NFS 202 V4 Reply (Call In 11) WRITE
...

BuffertedWriterのバッファサイズが131072の場合

 53   0.012420 192.168.56.102 -> 192.168.56.101 NFS 458 V4 Call WRITE StateID: 0x8849 Offset: 0 Len: 131072
 55   0.015583 192.168.56.101 -> 192.168.56.102 NFS 202 V4 Reply (Call In 53) WRITE
...

また、nfsstatの結果からも、writeを示すRPC発行回数が減っています。
(データは1MBのファイルコピー処理時のもの)

BuffertedWriterのバッファサイズが8192の場合
(writeが128回。8192B * 128回 = 1MB)

nfsstat -c
# ファイルコピー処理前
null         read         write        commit       open         open_conf
0         0% 0         0% 133228   93% 7915      5% 149       0% 13        0%
# 処理後
null         read         write        commit       open         open_conf
0         0% 0         0% 133356   93% 7915      5% 150       0% 14        0%

BuffertedWriterのバッファサイズが131072の場合
(writeが8回。131072B * 8回 = 1MB)

# ファイルコピー処理前
null         read         write        commit       open         open_conf
0         0% 0         0% 133356   93% 7915      5% 150       0% 14        0%
# 処理後
null         read         write        commit       open         open_conf
0         0% 0         0% 133364   93% 7915      5% 151       0% 15        0%

JavaのBufferetedWriterのデフォルト8KBの単位での書き出しでは、NFSのwsize(128KB)と書き込み単位が合わず、サイズの小さい断片化したRPCを繰り返し発行していたことが、バッファ拡大による性能向上の理由と思います。

バッファ拡大の注意点

NFSクライアントマシンの不測なクラッシュに備えた同期書き込みを目的にnoacオプションでマウントしていた場合、JavaレイヤでのバッファリングはNFSレイヤでの同期書き込みの意味をなくし、データ損失の可能性を高めるため注意が必要です。

以下のようなケースでは、BufferetedWriterのバッファ拡大もありかと思います。

  • 複数NFSクライアントが同一パスを参照する環境において、属性キャッシュを無効にして他クライアントの変更がすぐ見える目的でnoacマウントしている場合
  • 事情はわからないがnoacでマウントされており、諸処の事情で変更困難の場合

まとめ

BuffertedWriterのバッファ拡大により、性能差分が発生するあまり見かけないケースをまとめました。実測したのはNFSv4だけですが、ネットワーク経由でアクセスする他のファイルシステムも、同様の注意が必要と思います。

*1:属性キャッシュを無効とするオプション。/etc/exportsに定義されたディレクトリに対して、複数NFSクライアントがマウントし、頻繁に書き込みおよびファイル属性変更が行われる場合に使われる。noacを付けると同期書き込みsyncも有効になる。詳細はman nfs 参照 http://linux.die.net/man/5/nfs

*2:趣旨とずれるため記載していませんが、NFS同期書き込みマウント時に限っては、一般的にJavaで最も早いファイルコピーFileChanel.tranferToよりも、BufferetedWriterのバッファ拡大の方が早いです

JavaOne 2015 4日目メモ (10/28)

JavaOne

JavaOne 4日目の夜には、毎年トレジャーアイランドでOracle Appreciation Event(オラクルによる感謝祭?)が行われ、有名な方のライブが行われる。今年はエルトンジョンとBECKだった。毎年寒いので、薄手のダウンなど暖かい服装が必須。

4日目は以下のセッションに参加。

[CON2709] The New HTTP Client API, Including HTTP/2 and WebSocket

JEP110で提案されている、Java SEに盛り込む新しいHTTPクライアントについて。JDK9には、HttpUrlConnectionに代わるHTTPクライアントを盛り込む計画があり、HTTP1.1/HTTP2/WebSocketのクライアントがサポートされる予定である。

セッションの前半はHTTP2の説明と、Java8から導入されたComputableFutureの振り返りであったため省略。後半から、具体的なAPIのアイディアが紹介された。いずれもまだOpenJDK9のリポジトリに含まれていないため、まだ変更が入る可能性が高い。

HTTP GETし、結果を文字列(HttpResponse.asStringメソッド)で取得:

HttpResponse resp = HttpRequest
                     .create(new URI("http://www.foo.com/")
                     .GET()
                     .response();

if (reap.statusCode() == 200) {
    String responseBody = resp.body(HttpResponse.asString());
    System.out.println(System.out.println(responseBody);
}

POSTする場合は、以下のようにbodyメソッドに設定する:

HttpResponse resp = HttpRequest
                     .create(new URI("http://www.foo.com/")
                     .body(HttpRequest.fromString("param1=1,param2=2")
                     .POST()
                     .response();

非同期実行。レスポンスボディをファイルに書き出す:

ComputableFuture<Path> future= HttpRequest.create(uri)
    .GET()
    .responseAsync()
    .thenApplyAsync(resp -> {
        if (reap.statusCode() == 200) {
            return reap.body(asFile(path));
        } else {
            throw new UncheckedIOException(new IOException());
        }
    });    //=> このメソッドチェーンの返り値はComputableFuture<Path>
future.join();  //=> thenApplyAsyncが完了するまでブロック

ExecutorServiceを渡せるので、Java EE環境でもComputableFutureが使いやすい:
(APサーバが管理しているスレッドプールManagedExecutorが渡せる)

HttpClient client = HttpClient.create()
              .executorService(Executors.newCachedThreadPool())
              .build();
HttpRequest request = client.request(URI.create("https://www.foo.com/")).GET();

HTTP2でリクエストするときは、メソッドチェーンに追加する:

HttpRequest request = client.request(URI.create("https://www.foo.com/"))
    .version(HttpClient.Version.HTTP_2)
    .GET();

セッションの中ではリソースクローズに関する言及がなかったが、HttpUrlConnectionのように、クリーンアップをどうやるかわかりくいAPIにならないことを願っている。

[CON2809] Deep Dive into Top Java Performance Mistakes in 2015

性能解析ツールのdynatrace社の方による、どんなメトリクス(ページサイズ、HTTPエラーレスポンス数などの指標)が、性能遅延に直結しやすいか実例を交えながら紹介するセッション。セッションではdynatraceによる以下のようなメトリクス収集結果のデモが紹介された。

メトリクス1: 画像などのリソース数、サイズに注意

  • アメフトのスーパーボウルのページは、1ページに434の画像などのリソース、合計20MBのサイズによりレスポンス遅延が発生していた
  • FIFAワールドカップのページで、faviconアイコンが370KBを超え、そのほかにも150KBを超えるCSS複数あって遅延
  • 大きな背景画像もかっこいいが、サイズには注意が必要
  • 遅いと思ったら、まずブラウザF12のデバッグツールで見てみる

メトリクス2: SQL大量row取得、同一SQLの繰返実行(N+1)、大量のコネクション生成

  • Room Reservertion System(会議室予約?) で1リクエストで2万回以上のSQL発行 (典型的なORMのN+1問題)
  • 1万以上のコネクション生成 (プールによるコネクション再利用漏れ)
  • データキャッシュをHashTableに全て置いて、ブロック多発による性能劣化

メトリクス3: 外部サービスの呼び出し数、WebAPI実行時のN+1問題

  • 100回以上の外部WebAPIの繰り返し呼出
  • ORMのN+1問題と同様に、キーごとに毎回APIコールすると同じ問題が起こる

メトリクス4: ロギング量

  • DEBUGレベルのログを大量出力して、log4jのcallAppenderメソッドでブロック多発

メトリクス5: GC回数、ライブヒープの増加

  • アプリケーションの改修に伴いライブヒープが一気に増加
  • 低負荷時のレスポンスタイムに変化はないが、高負荷時にライブヒープ増加に伴いCPUネックが顕在化し、大幅なレスポンス低下

他にも確認した方が良いデータ:

  • サーバログのException数
  • HTTP 40x、50xエラーレスポンス
  • DBメトリクス(SQL応答時間、発行回数)

ここからはセッション内容と関連しないメモ。有償であるdynatraceを使わずにELK(ElasticSearch+Logstash+Kibana)でメトリクスが収集できないか考える。

  • フロントエンド
    • リソースのサイズはApacheアクセスログからも取得可能 (%b)。kibanaで見るときに、xxxKBを超えるレスポンス数でフィルタすれば見れそう。
    • .jsや.cssはサイズでフィルタして、xxxKBを超えるものは、minify漏れでは?というチェックもできる。
  • DB関連
    • slow queryはログから取れる。
    • ログからのN+1の検知は難しそう。今まで通り、スロークエリが出てないがDBアクセスクラスで遅い場合は、デバッグ用途でORMのSQL出力を有効化するしかない?
    • コネクション数も、例えばPostgreSQLであればpg_stat_databaseビューのnumbackendsを拾ってくればいけそう。
  • 連携サービスのRPC呼び出し過多
    • バックエンドのAPサーバ群のHTTPアクセスログと、フロントWebサーバのアクセスログを比較すればわかりそう。送信元ごとにリクエスト数をグラフ化すれば良い。ユーザからは1リクエストなのに、バックエンドのサーバで1000リクエストがあったら、どこか繰り返し呼び出しをしてる。
    • サービスの粒度が細かく、アクセスログからでは全体の把握が苦しくなったらzipkin使えないか考える。3〜4つのREST APIの連携であればアクセスログ収集と解析でもいけそう。
  • ロギング過多
    • プロファイラ使わずにログからとなると dfによるディスク使用量ぐらい?
  • GC回数、ライブヒープの増加
  • OSリソース系
    • ELK構成でsar, df, proc xxx を取り込む以外にも、RHEL7(および6.7)以上であれば、Performance Co-Pilot + Netflix vectorの選択肢がある。vectorがELKより便利そうかは要調査。

[CON6446] WebSocket in Enterprise Applications

WebSocketの導入セッション。ゲーム以外のWebSocketの使い道をイメージするために聴講。前半はLong polling/SSE/WebSocket/HTTP2の違いについてだったので省略。

WebSocketを何に使うか:
いくつかの例が紹介された。

  • サーバプッシュ
    • 本来はSSEの領域だが、IE11/Edgeが対応していないため。
    • HTTP2のプッシュは、png, css, jsなどのページ構成リソースを、リクエストを待たずに送付するため。唐突にプッシュ通知するためのものではない。
  • 頻繁にリクエスト&レスポンスがある処理。株トレーディングなど。
  • リモートコントロール。リアルタイムでフィードバックを受けながら操作するもの。機械操作など。
  • リアルタイムモニタリング
  • バックエンドサーバ間の高速なリクエスト&レスポンス。
    • メモ: 高速RPC用途であれば、grpcなどの選択肢もあると思う

WebSocketのサブプロトコル:
WebSocket自体は、ブラウザの世界にソケット接続を持ってきたものなので、アプリケーション固有のjson以外にも、サブプロトコルがいくつか出ている。

  • RFC 7118 SIP over WebSocket
  • RFC 7395 XMPP over WebSocket
  • そのほかにも anything over WebSocket が可能

WebSocketのクラスタ化:
複数のサーバに分かれてWebSocket接続する場合は、他のサーバで接続するWebSocketの存在を考慮する必要がある。たとえば一斉通知する場合、Java EEであればJMSやJCacheによってWebSocketのサーバ間連携を実現する。また、サーバサイドでのフェールオーバは難しいため、障害時はクライアントから再接続する。

[CON6856] Saving the Future from the Past

Javaの非推奨(@Deprecated)の歴史と今後について紹介するセッション。
JJUG CCC 2014 Springで講演されていた、オラクルのStuart Marksさんが"Dr. Deprecator"として白衣を着て発表。

Deprecatedの歴史:

  • 歴史は古く、JDK1.1から既に非推奨は存在
  • 当初はJDK1.1で新しく多くのAPIが導入されたために、古いものを捨てる(abandon)ため、代わりのもっと良いもの(supersede)が出ていることを、ユーザに知らせる仕組みとして導入された。
  • ユーザに新しいものに移行したもらうためのものだった。

Deprecatedの意図の多様化:
当初は今後はメンテしない(abandon)、代わりに良いのがある(supersede)がDeprecatedの意図であったが、現在ではもっと多用な意図でDeprecatedが使われている。

  • CONDEMNED: 今後削除される可能性がある
  • DANGEROUS: データが壊れたり、デッドロックが起こる可能性がある。
    • DANGEROUSの代表例はThread.stop()

Deprecatedこそ付いていないものの、Vectorなどの古いAPIは、ユーザにとって"非推奨"と見られている。

Deprecatedに気が付かないパターン:
コンパイル警告、JavaDocIDEの取り消し線でユーザに知らせているが、JDKの移行の仕方によっては気が付かないパターンもある。再コンパイルせずにバイナリ互換を活かしてJDKのバージョンアップをした場合はユーザはわからない。

APIのライフサイクル:
以下のようなフローが理想とされているが、Java SEの実態は異なる。

  1. 新しいAPIが導入され、古いAPIが非推奨になる
    • しかし実態は、多くの人は非推奨警告を無視する
  2. ユーザは新しいAPIに移行する
    • 実態は様々な理由からなかなか移行しない
  3. 移行が済んだころに、APIは削除される
    • 実態は、JDK9となってもほとんどのAPIは削除されていない。

なぜJava SEはAPIを削除しないのか:

  • APIの削除は究極の非互換である
  • ソース互換性はコンパイルが通らず壊れる、バイナリ互換性もNoSuchMethodErrorで壊れる、振る舞い互換性もAPIがないのでもちろん壊れる
  • なぜ無くなったのか、何がなくなったのかjavadoc化が困難

これからのDeprecated:

  • 非推奨の理由カテゴリを再整理し、enum型で表現したい。
    • UNSPECIFIED(特になし)
    • CONDEMNED(将来的に削除予定)
    • DANGEROUS(リスクあり)
    • OBSOLETE(時代遅れで古い)
    • SUPERSEDED(もっと良い代替がある)
    • UNIMPLEMENTED(実装なし、呼ぶとUnSupportedOperationExceptionになるので注意)
@Deprecated(value={DANGEROUS,SUPERSEDED}, replacement="String#getBytes()", since="1.1")
public void getBytes(int srcBegin, int srcEnd, byte[] dst, int dstBegin)
  • ランタイム時にも@Deprecatedの警告を出して、ユーザに通知したい
  • javadocの"All Methods"から@Deprecatedのメソッドを削除して、ユーザに存在を知らせないようにしたい
  • IDEが非推奨APIの利用をもっと自動置換してくれるようになって欲しい
    • しかし、スレッドセーフを意図してHashTableを使っているなど、単純な置き換えはバグを招く

JavaOne 2015 3日目メモ (10/27)

JavaOne

3日目も晴れている。今年は週間天気予報に雨マークが出てたから折りたたみ傘を持ってたが、4回目で今のところ傘が必要なほどの雨に振られたことがない。

今日は以下のセッションに参加。

[CON6712] Enhanced Process APIs

JDK9に向けて、ProcessBuilderの改善アイディアについて。
プロセスの情報をもっとJavaAPIで取得したい:

  • allProcesses()でpsのようにマシン上のプロセス一覧を取得
    • (OSのアクセス制限の範囲で)
  • getCurrent()で現在のプロセス情報、of(pid)で対象pidの情報
  • getPid(), info()のようにプロセス情報の収集
  • onExit()でCoumputableFutureによる非同期ハンドリング?

ProcessHandle.Infoクラスから、対象のプロセス情報を収集する。ユーザ、実行したコマンド、コマンド引数、開始時刻、CPU時間など。取れる情報もあれば、OSの制限により取れない情報もあるので、返り値はOptionalでラップして、例えば Optional user = ph.info().user(); のように返す。

以下の例はプロセスID、親プロセス、ユーザ、コマンドをロギング。

showProcess(ProcessHandle.current());

static void showProcess(ProcessHandler ph) { 
    ProcessHandle.Info info = ph.info();
    log.printf("pid: %d, parent: %s, user: %s, cmd: %s%n",
        ph.getPid(), ph.getParent(), info.user().orElse("none"), info.command().orElse("none"));
}

Java8のストリームAPIへの対応:
以下の例は現在のユーザのプロセス一覧をプロセスID順にソートしてロギングする。

Optional<String> currUser = ProcessHandle.current();
ProcessHandle.allProcesses()
    .filter(p1 -> p1.info().user().equals(currUser))
    .sorted(CodeSamples::parentComparator)
    .forEach(CodeSamples::showProcess);

static int parentComparator(ProcessHandle p1, ProcessHandle p2) {
    return Long.compare(p1.parent().get().getPid(), p2.parent().get().getPid());
}

非同期による外部プロセスの起動:
Java8から入ったComputableFutureをProcess.onExit()メソッドの返り値で返す。
以下の例はプロセスの起動と終了を複数の多重度でプールループで実行している。プロセス終了のタイミングでプロセスID、終了コードのロギングと、再度プロセスの起動を行っている。

Semaphore count = new Semaphore(11);
CountDownLatch end = new CountDownLatch(1);

// paralleism分の多重度でプロセスを繰り返し起動
for (int i = 0; i < paralleism; i++) 
    start(pb1, count, end);

// 並行で実行する全てのプロセスが起動するまでラッチで待機
end.await();

// paralleism分の多重度でプロセスが起動したら、
// Futureと同じような動きをするonExit.get()をプロセスごとに実行して、
// 各プロセスの完了までブロックする
ProcessHandle.current()
    .children().forEach(CodeSample::waitForExit);

static void start(ProcessBuilder pb, Semaphore count, CountDownLatch end) {
    try {
        if (count.tryAcquire()) {
            Process p = pg.start();
            p.onExit()
              .thenAccept(CodeSamples::logExit)
              .thenRun(() -> start(pb, count, end));
        } else {
            end.release();
        }
    } catch (IOException ioe) {
        throw new RuntimeException("Process start failed", joe);
    }
}

static void logExit(Process p) {
    log.printf("exit: %d, status: %d%s", p.getPid(), p.exitValue());
}

static void waitForExit(ProcessHandle p) {
    try { p.onExit().get(); } catch (Exception e) { ... }
}

ProcessBuilderへのパイプの適用:
ls | fgrep dukeと同じようなパイプ繋ぎのコマンドを、Javaで実現する。

ProcessBuilder pb1 = new ProcessBuilder();
ProcessBuilder pb2 = new ProcessBuilder();

List<Process> processes = ProcessBuilder.startPipe(pb1, pb2);
processes.forEach(p -> {
    try {
        int status = p.waitFor();
        log.printf("status: %d%n", status);
    } catch (InterruptedException ie) {
    }
}

他にも今までのProcessはInputStream/OutputStreamを返すが、NIOのChannelに対応させる案の紹介。ノンブロッキングIOに使われているselector()を使って、応答が返ってきたタイミングで通知を受ける案も紹介された。

[CON11284] JDK 9 Language and Tooling Features

Jigsaw以外のJDK9の変更点についてまとめたセッション。
対話式でjavaを実行するjshellの導入、javadocの検索フォームの導入以外はよくわからなかったので要復習。
セッション資料はここで公開されている。

[CON3239] Tuning JavaServer Faces

JSFでパフォーマンスに関する問題を起こさないために、どんなことに注意すべきか紹介するセッション。

JSFの性能にインパクトを与える観点:

  • ページサイズ
  • セッションのサイズ (コンポーネントツリーとアプリケーション分の両方)
  • リクエストパラメータのサイズ
  • EL式の評価
    • EL式のメソッド呼び出しでDBリクエストしない
  • JSFのコンフィグフラグ
    • web.xmlで設定できるチューニングパラメータ 参考
  • FacesContext.getCurrentContext()の繰り返し呼び出し

Bloated component tree対策:
panelタグや、Primefacesなどのコンポーネントにあるタブ機能を使うと、Bloadted component tree (広がりすぎたコンポーネントツリー)に陥りがちである。これは、output系のタグにrendered=false属性を指定しても、画面に表示されないだけで、コンポーネントとしては存在するので性能に影響を与える。以下のような観点で対処を行う。

  • <panel>はdivやspanに置き換えられないか
  • JSF2.2から導入されたステートレスビューの導入
  • 動的ローディングの機能がないか探す
    • たとえばタブであれば、遅延ロード機能が用意されているはず

セッションをなるべく使わない:
セッションの代わりに可能な限り以下を使い、ライブヒープによるGCコスト増加や、レプリケーションコストの増大を避ける。

  • 可能であればリクエストスコープ、Ajaxで更新する画面ならビュースコープ。
  • Flowスコープ(JSF2.2)、Conversationスコープ(CDI)などの期限付きスコープを使う。

id名を短縮してレスポンスデータ量削減:
標準では フォームID:テキスト入力フォームID のような形式でコロン区切りで長いIDが付く。このID名が長い場合は、<h:form id="f" ... のように、1文字IDを明示的に指定すると、テーブルの中にフォームがあるような、何度も繰り返し長い文字列のIDが表示されるケースでデータ量削減に有効。

PartialSubmitを使ってリクエストデータ量削減:
標準の<h:commandButton>は、テーブルの列にフォーム入力がある場合など、大量の変更可能な入力項目の1つを変えただけでも、フォームに含まれるすべてのテキストインプットの内容を再送信する。Primefacesなどのライブラリが用意するコンポーネントを使うと、変更したフォーム内容だけ再送信するPartialSubmit機能がある。
この機能により、リクエスト送信量の削減、送信されたパラメータを再処理するJSFサイクルコストの低減が図れる。

不必要なFacesContext.getCurrentInstance()呼び出しを避ける:
getCurrentInstance()のコストは少なくないため、たとえば同一メソッド内での複数呼び出しは避ける。

[CON2483] Java SE 8 for Java EE Developers

Java EE開発者に有効なJava SE 8の機能を紹介するセッション。

Java EE7でInstantを使う:
JPAの@Convertを使って、DateからData and Time APIのInstantに変換する。Java EE7はDate and Time APIに対応していないため、自作する。

public class DateConverter implements AttributeConverter<Instant, Date> {
    public Date convertToDatabaseColumn(Instant instant) {
        return Date.from(instant);
    }
    public Instant convertToEntityAttribute(Date date) {
        return date.toInstant();
    }
}

以下のようにエンティティクラスのフィールドに適用する。

@Convert(converter=DateConverter.class)
@Temporal(TemporalType.instance);
private Instant instance;

その他もろもろ:

  • StringJoiner使おう
  • ComparatorもComparator.comparingBy(Person::getLastName)のように簡潔に書く
  • MapのcomputIfAbsent、getOrDefaultはEEアプリケーションでもよく使う
  • Files.lines(path)でファイルは読む
  • APサーバ上で間違ってparallelStream()が使われてしまうことへの対策
    • System.setProperty("java.util.concurrent.ForkJoinPool.common.parallelism", "1")

JDK9 JEP269の話:
JEP269がJDK9に盛り込まれれば、EEの世界でもよく使うコレクション初期化がシンプルにできる。

List<String> strints = List.of("one", "two", "three", "four");

[CON2876] JSR 373: New Java EE Management API

Java EE 8に向けて検討が始められている、RESTベースの監視、管理APIの標準化について。結論からまとめると、決まっていることはまだないので、セッション参加者に色々アンケートととって、仕様策定においての悩みをユーザに共有セッション。
フィードバックフォームはここで公開されている。

[BOF7768] Let’s Visualize Log Files for Troubleshooting Java Applications

@cero_tさんと、Koji Ishidaさんのセッション。トラブルシューティングに欠かせないログの可視化について。

冒頭、logをGoogleイメージ検索した、大量の丸太の写真と絵で笑いを取る。海外でも笑いを取りにいく@cero_tさんはすごい、場が暖まる。

内容はホテルの予約サイトの性能、エラー多発トラブルの実例をベースに、どのように問題対処していったかについて。

まずはじめに、seleniumによるテストケース作成と、ソースコードリーディングで問題解析しようとしたが、コード量も多く、困っている問題事象はプロダクション環境でしか起こらなかったため、あまり有効でなかった。

プロダクション環境でしか起こらない問題は、プロダクション環境を対象に解析する必要がある。サービスに影響を与えられないのでログを活用した。ELK(ElasticSearch + Logstash + Kibana)のログ収集の基盤を作り、Apacheアクセスログからリクエスト遅延とMySQLのスロークエリに相関があることを見つけ、性能問題を対処した。

エラーの多発もLogstashで収集したログを、javaプログラムにロードして解析し、原因解析を行った(この部分聞き逃したので少し自信なし)。

ログを解析するにあたって、ElasticSearchでの可視化、cron+javaプログラムでのエラー解析、ファイルサーバに転送してエディタで目視するためには、ログを一度溜め込んで、各ツールに分配するLog Stream Hubが必要となった。今回の事例ではRedisをハブとした。

このようなトラブルログ分析基盤は開発者向けであり、お金が付きにくい。そこでkibanaを販売状況などのビジネスデータの可視化にも利用した。ELK構成はいずれもオープンソースなので、まずは小さくはじめて見ようとセッションを締めくくった。