LogstashからIngest Nodeへの移行
Elasticsearch 5.xからはIngest Nodeを使うと、Logstashを使わなくてもElasticsearchでログの変換ができるとElastic社のスライドにまとまっていたので、LogstashからIngest Nodeへの移行についてメモ。
LogstashからIngest Nodeへの移行
今までFilebeatで集めてきたログをLogstashに送ってjson変換していたところ、Elasticsearchで直接json変換できるようになるため、Logstashを使わなくてもログの収集と可視化が可能となる。
- Filebeat(収集) -> Logstash(変換) -> Elasticsearch(蓄積)
- Filebeat(収集) -> Elasticsearch(変換/蓄積)
Logstashのfilterプラグインの多くはIngest Nodeの機能にProcessorとして移植されている。Processor一覧はElasticsearch5.xのドキュメントにあるが、大まかな対応は以下の通り。Logstashのfilter名とIngest NodeのProcessor名には同じ名前が付いていることが多いが、LogstashのmutateがオプションごとにProcessorに分割されていたり、日付ごとのインデックス切り替えをProcessorで定義できたり、一部差分もある。
| Logstash | Ingest NodeのProcessor |
|---|---|
| grok | Grok Processor |
| date | Data Processor |
| mutate | Convert Processor, Gsub Processor, Join Processor, Lowercase Processor ... |
| ruby | Script Processor (言語はElasticsearch固有のPainless Scripting Language) |
| useragent | Ingest user agent processor plugin (非バンドルプラグイン) |
| 日付ごとのインデックス切り替え (elasticsearch {index => "logstash-%{+YYYY.MM.dd}"}) | Date Index Name Processor |
| if文使える | 少なくともAlpha5の段階では使えない |
また、Ingest Nodeはあくまで変換機能のみを担うため、Logstashのinputプラグインにあるような、Kafkaからの入力や、HTTP Pollerによる定期的なREST API経由のメトリクス収集、JDBCによるRDBMSからのデータ吸い上げのような機能のサポートはない。また、Kibana5にCSVファイルアップロード機能が追加されているからか、csvフィルタ相当のProcessorも今のところない。
まとめると、Elasticsearch5.0.0 alpha5の段階では、以下のようなケースでは引き続きLogstashの方が便利。
- Kafka、HTTP Poller、JDBCなどを入力ソースとしたい場合
- Logstashのif文相当を実行したい場合
Ingest Nodeのpipeline設定
以下のような障害解析でよく可視化するログを対象に、Logstashの場合とIngest Nodeの場合の設定例をそれぞれまとめる。
Apache (combined形式)のアクセスログ
apache-loggenを使って生成したダミーのcombined形式ログを対象とする。
168.66.82.175 - - [12/Sep/2016:18:26:03 +0900] "GET /item/books/3538 HTTP/1.1" 200 82 "-" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)"
Logstashの場合
input { stdin {} } filter { grok { match => { "message" => "%{COMBINEDAPACHELOG}" } } date { match => [ "timestamp", "dd/MMM/yyyy:HH:mm:ss Z"] remove_field => "timestamp" } mutate { convert => { "bytes" => "integer" } } } output { elasticsearch { index => "logstash-accesslog-%{+YYYY.MM.dd}" } }
Ingest Nodeのpipelineの場合
curl -XPUT localhost:9200/_ingest/pipeline/httpd-accesslog -d ' { "description": "Parse HTTPD accesslog", "processors": [ { "grok": { "field": "message", "patterns": ["%{COMBINEDAPACHELOG}"] } }, { "convert": { "field": "bytes", "type": "integer" } }, { "date": { "field": "timestamp", "formats": ["dd/MMM/yyyy:HH:mm:ss Z"] } }, { "date_index_name": { "field": "@timestamp", "index_name_prefix": "filebeat-accesslog-", "date_rounding": "d" } }, { "remove": { "field": "timestamp" } } ] } '
インデックス名をfilebeat-*始まる名前にしている理由は、後述するログ送信時にFilebeatを利用しており、Filebeatのインデックステンプレートを効かせるため。
sar (CPU使用率)
バイナリファイルのsarはsadfで変換するとパースしやすい。
sadf -t -d -P ALL <sarファイル名>
以下のようなログをパース対象とする。
centos7;-1;2016-09-14 21:02:39;LINUX-RESTART # hostname;interval;timestamp;CPU;%user;%nice;%system;%iowait;%steal;%idle centos7;599;2016-09-14 21:20:01;-1;0.20;0.00;0.12;0.01;0.00;99.67 centos7;599;2016-09-14 21:20:01;0;0.26;0.00;0.11;0.01;0.00;99.61 centos7;599;2016-09-14 21:20:01;1;0.14;0.00;0.13;0.01;0.00;99.73 centos7;-1;2016-09-14 22:05:04;LINUX-RESTART
Logstashの場合
input { stdin {} } filter { # drop restart line. ex centos7;-1;2016-09-16 00:12:40;LINUX-RESTART if [message] =~ /LINUX-RESTART$/ { drop {} } # drop header line if [message] =~ /^# hostname/ { drop {} } csv { separator => ";" columns => ["hostname","interval","timestamp","cpu","user","nice","system","iowait","steal","idle"] convert => { "interval" => "integer" "user" => "float" "nice" => "float" "system" => "float" "iowait" => "float" "steal" => "float" "idle" => "float" } } date { match => [ "timestamp", "yyyy-MM-dd HH:mm:ss"] remove_field => "timestamp" } } output { elasticsearch { index => "logstash-sar-cpu-%{+YYYY.MM.dd}" } }
Ingest Nodeのpipelineの場合
curl -H "Expect:" -XPUT localhost:9200/_ingest/pipeline/sadf-cpu -d '{ "description": "sadf -t -d -P ALL", "processors": [ { "grok": { "field": "message", "patterns": ["%{DATA:hostname};%{NUMBER:interval};%{TIMESTAMP_ISO8601:timestamp};%{DATA:cpu};%{NUMBER:user};%{NUMBER:nice};%{NUMBER:system};%{NUMBER:iowait};%{NUMBER:steal};%{NUMBER:idle}"] } }, { "date": { "field": "timestamp", "formats": ["yyyy-MM-dd HH:mm:ss"] } }, { "date_index_name": { "field": "@timestamp", "index_name_prefix": "filebeat-sar-cpu-", "date_rounding": "d" } }, { "remove": { "field": "timestamp" } }, { "convert": { "field": "user", "type": "float" } }, { "convert": { "field": "nice", "type": "float" } }, { "convert": { "field": "system", "type": "float"} }, { "convert": { "field": "iowait", "type": "float"} }, { "convert": { "field": "steal", "type": "float"} }, { "convert": { "field": "idle", "type": "float"} } ] }'
Expectヘッダを明示的に付与しているのは、1024バイト以上のリクエスト送るとElasticsearch側でエラーになる問題を回避するため。v5.0.0-beta1 で修正予定なっているため、GAになる頃にはこの回避策は不要になるだろう。
- https://github.com/elastic/elasticsearch/issues/19893
- https://github.com/elastic/elasticsearch/issues/19834
また、drop相当の機能はAlpha5の段階では見当たらないため、『centos7;-1;2016-09-14 21:02:39;LINUX-RESTART』のようにgrokでパースできない行にあたると、Elasticsearch側でエラーログが出力され、該当行のpipelineの処理はスキップされる。エラーログが気になる場合は、Filebeatのinclude-lineで送信したい行のフォーマットの正規表現が指定でき、Elasticsearchに送信するログをFilebeat側で絞り込むことが可能。
pidstat (プロセス別CPU使用率)
不安定なシステムにおいて定常的にcronで収集する。
JavaやPostgreSQLが同一のマシンのサービスとして稼働しているが、どれが重くなっているのかがわからないときに必要なデータ。
pidstat -U -h -l -p ALL
- -U ユーザIDではなくユーザ名で表示
- -h タイムスタンプをロケール依存ではなくエポックで出力するために使用
- -l コマンドラインオプションも収集。特にjavaはオプションまで見ないと、APサーバのプロセスなのかバッチタスクか識別できない
- -p ALL 全ユーザのプロセスのデータを収集
以下のようなログをパース対象とする。
$ pidstat -U -h -l -p ALL Linux 3.10.0-327.28.3.el7.x86_64 (centos7) 2016年09月16日 _x86_64_ (2 CPU) # Time USER PID %usr %system %guest %CPU CPU Command 1473953274 root 1 0.00 0.00 0.00 0.00 0 /usr/lib/systemd/systemd --switched-root --system --deserialize 21 1473953274 root 2 0.00 0.00 0.00 0.00 1 kthreadd
Logstashの場合
input { stdin {} } filter { if [message] !~ /^\s\d{10}/ { drop {} } grok { match => { "message" => "%{WORD:timestamp}%{SPACE}%{WORD:user}%{SPACE}%{WORD:pid}%{SPACE}%{NUMBER:usr}%{SPACE}%{NUMBER:system}%{SPACE}%{NUMBER:guest}%{SPACE}%{NUMBER:cpu_percent}%{SPACE}%{WORD:cpu}%{SPACE}%{GREEDYDATA:command}" } } date { match => [ "timestamp", "UNIX"] remove_field => "timestamp" } mutate { convert => { "usr" => "float" "system" => "float" "guest" => "float" "cpu_percent" => "float" } } } output { elasticsearch { index => "logstash-pidstat-%{+YYYY.MM.dd}" } }
Ingest Nodeのpipelineの場合
curl -H "Expect:" -XPUT localhost:9200/_ingest/pipeline/pidstat -d '{ "description": "pidstat -U -h -l -p ALL", "processors": [ { "grok": { "field": "message", "patterns": ["%{WORD:timestamp}%{SPACE}%{WORD:user}%{SPACE}%{WORD:pid}%{SPACE}%{NUMBER:usr}%{SPACE}%{NUMBER:system}%{SPACE}%{NUMBER:guest}%{SPACE}%{NUMBER:cpu_percent}%{SPACE}%{WORD:cpu}%{SPACE}%{GREEDYDATA:command}"] } }, { "date": { "field": "timestamp", "formats": ["UNIX"] } }, { "date_index_name": { "field": "@timestamp", "index_name_prefix": "filebeat-pidstat", "date_rounding": "d" } }, { "remove": { "field": "timestamp" } }, { "convert": { "field": "usr", "type": "float" } }, { "convert": { "field": "system", "type": "float"} }, { "convert": { "field": "guest", "type": "float"} }, { "convert": { "field": "cpu_percent", "type": "float"} } ] }'
FilebeatによるIngest Nodeへのログ送信
前述までの設定はあくまでpipelineの定義であるため、何らかの方法でこれらpipelineを宛て先にログを送信する必要がある。
ログを1行ずつ読み取ってcurlで送ることもできなくはないだろうが、ここではFilebeatを使う。一般的には低リソースで継続的にログを収集するエージェントとしてFilebeatが使われることが多いと思うが、Filebeatは標準入力にも対応しているため、ログを一式受領して問題解析のために解析する用途にも使える。
標準入力向けのFilebeatの設定ファイルを以下のように作成する。parameters.pipelineで宛て先のパイプラインを設定する。以下の例では、前述で定義したパイプラインpidstatを宛て先としている。console用出力はログが流れているかの確認用のため、大量データを取り込む際にはコメントアウトした方がロードが早い。
filebeat.prospectors: - input_type: stdin output.elasticsearch: hosts: ["localhost:9200"] parameters.pipeline: "pidstat" output.console: # Boolean flag to enable or disable the output module. enabled: true # Pretty print json event pretty: true
標準入力経由でFilebeatに流し込む。
cat pidstat.log | ./filebeat -c filebeat.pidstat.yml
Filebeat 5.0.0 alpha5の時点では、すべてのログをロードしてもFilebeatは終了せず、そのままさらなる標準入力を待ち続ける。以下のissueがベータ1リリース時に入ってくるとこの問題も解決すると思う。
Allow filebeat to only run once #2456
まとめ
- Logstashのfilterは、Ingest NodeのProcessorで同じようなことが実現できる
- Ingest Nodeに定義したパイプラインへのログ送信はFilebeatの
parameters.pipelineで簡単にできる
今回の例のように手動によるバルク取り込みでは、Logstash + Elasticsearchの組合せがFilebeat + Elasticsearchの組合せに変わるだけなのでメリットがないように感じられるが、elasticsearch-ingest-node-vs-logstash-performance-2など記事ではIngest Nodeの方が軽量とレポートされているため、実機で試してIngest Nodeの方が軽い場合は積極的に使うとより早くログが可視化できると思う。
EmbulkでアクセスログをLogstash風に取り込む
トラブルシューティング時に、バッチ取り込みによる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ボタンでアップロードする。
可視化したい時間帯を指定すると、以下のようにダッシュボードが表示される。
まとめ
grok.patternsとelasticsearch-template.jsonをLogstashから持ってくることにより、LogstashユーザでもEmbulkが扱いやすくなります。
Logstashを前提に色々ダッシュボードを作っていても、上記のようなやり方でEmbulkで取り込んだ時にもダッシュボードが流用できそうです。
Kibana4.4.0の機能追加
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)
グラフ項目の色指定
凡例の項目をクリックするとカラーパレットが表示され、グラフ項目を好きな色に変更できるようになった。このような可視化ツールを人に見せると、真っ先に挙がる要望にグラフ色の変更があるが、対応できるようになった。
CentOS7でOpenJDKのソースツリー取得時に/dev/stdout: Permission denied
手元の環境を再構築したときにハマったのでメモ。
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 2月 5 20:12 /dev/stdout -> /proc/self/fd/1 ls -l /proc/self/fd/1 lrwx------. 1 openjdk openjdk 64 2月 5 20:52 /proc/self/fd/1 -> /dev/pts/0 $ ls -l /dev/pts/0 crw--w----. 1 root tty 136, 0 2月 5 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)のデフォルトヒープサイズ
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:InitialRAMFractionを設定すると、物理メモリの8分の1をエルゴノミクスで決められる初期ヒープサイズにすることが可能。
java -XX:InitialRAMFraction=8 ...
ここまでの内容を踏まえて、例えば物理メモリ32GBの場合、何もオプションを指定しないと以下と同等です。思ったより最大ヒープサイズが大きいなと思う方も多いと思います。
java -Xms512m -Xmx8g ...
Javaバッチ処理のNFS向けファイルI/O
この記事は Java EE Advent Calendar 2015の12/7分の記事です。
明日は@btnrougeさんです。
Java EEのAPIが直接関連する話ではなくて恐縮ですが、サーバサイド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_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のバッファ拡大もありかと思います。
まとめ
BuffertedWriterのバッファ拡大により、性能差分が発生するあまり見かけないケースをまとめました。実測したのはNFSv4だけですが、ネットワーク経由でアクセスする他のファイルシステムも、同様の注意が必要と思います。
JavaOne 2015 4日目メモ (10/28)
JavaOne 4日目の夜には、毎年トレジャーアイランドでOracle Appreciation Event(オラクルによる感謝祭？)が行われ、有名な方のライブが行われる。今年はエルトンジョンとBECKだった。毎年寒いので、薄手のダウンなど暖かい服装が必須。
4日目は以下のセッションに参加。
- [CON2709] The New HTTP Client API, Including HTTP/2 and WebSocket
- [CON2809] Deep Dive into Top Java Performance Mistakes in 2015
- [CON6446] WebSocket in Enterprise Applications
- [CON6856] Saving the Future from the Past
[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: ロギング量
メトリクス5: GC回数、ライブヒープの増加
- アプリケーションの改修に伴いライブヒープが一気に増加
- 低負荷時のレスポンスタイムに変化はないが、高負荷時にライブヒープ増加に伴いCPUネックが顕在化し、大幅なレスポンス低下
他にも確認した方が良いデータ:
ここからはセッション内容と関連しないメモ。有償であるdynatraceを使わずにELK(ElasticSearch+Logstash+Kibana)でメトリクスが収集できないか考える。
- フロントエンド
- DB関連
- slow queryはログから取れる。
- ログからのN+1の検知は難しそう。今まで通り、スロークエリが出てないがDBアクセスクラスで遅い場合は、デバッグ用途でORMのSQL出力を有効化するしかない？
- コネクション数も、例えばPostgreSQLであればpg_stat_databaseビューのnumbackendsを拾ってくればいけそう。
- 連携サービスのRPC呼び出し過多
- ロギング過多
- プロファイラ使わずにログからとなると 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を何に使うか:
いくつかの例が紹介された。
- サーバプッシュ
- 頻繁にリクエスト&レスポンスがある処理。株トレーディングなど。
- リモートコントロール。リアルタイムでフィードバックを受けながら操作するもの。機械操作など。
- リアルタイムモニタリング。
- バックエンドサーバ間の高速なリクエスト&レスポンス。
- メモ: 高速RPC用途であれば、grpcなどの選択肢もあると思う
WebSocketのサブプロトコル:
WebSocket自体は、ブラウザの世界にソケット接続を持ってきたものなので、アプリケーション固有のjson以外にも、サブプロトコルがいくつか出ている。
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に気が付かないパターン:
コンパイル警告、JavaDoc、IDEの取り消し線でユーザに知らせているが、JDKの移行の仕方によっては気が付かないパターンもある。再コンパイルせずにバイナリ互換を活かしてJDKのバージョンアップをした場合はユーザはわからない。
APIのライフサイクル:
以下のようなフローが理想とされているが、Java SEの実態は異なる。
- 新しいAPIが導入され、古いAPIが非推奨になる
- しかし実態は、多くの人は非推奨警告を無視する
- ユーザは新しいAPIに移行する
- 実態は様々な理由からなかなか移行しない
- 移行が済んだころに、APIは削除される
- 実態は、JDK9となってもほとんどのAPIは削除されていない。
- APIの削除は究極の非互換である
- ソース互換性はコンパイルが通らず壊れる、バイナリ互換性もNoSuchMethodErrorで壊れる、振る舞い互換性もAPIがないのでもちろん壊れる
- なぜ無くなったのか、何がなくなったのかjavadoc化が困難
これからのDeprecated:
- 非推奨の理由カテゴリを再整理し、enum型で表現したい。
- UNSPECIFIED(特になし)
- CONDEMNED(将来的に削除予定)
- DANGEROUS(リスクあり)
- OBSOLETE(時代遅れで古い)
- SUPERSEDED(もっと良い代替がある)
- UNIMPLEMENTED(実装なし、呼ぶとUnSupportedOperationExceptionになるので注意)
- @Deprecatedのアノテーション要素として情報が補足できるようにしたい。
@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を使っているなど、単純な置き換えはバグを招く
- これらの提案は JEP 277: Enhanced Deprecation にまとめられている。
- JDK9への盛り込みを目指して検討中。
