コネクションプールの挙動差分によるバグ顕在化
この記事は Java EE Advent Calendar 2016の12/2分の記事です。
明日は@opengl_8080さんです。
Java EEが使われているシステムは、改修を加え続けながら数年〜十年と運用し続けるライフサイクルの長いシステムが多くあります。
アプリケーションを全面刷新することはなくても、ハードウェアやOS、ミドルウェアのEOSLを契機にJava EEサーバのバージョンを上げる、いわゆる『更改』という作業は色々な所で行われていると思います。
更改で厄介なのは、OSやミドルウェアのリリースノートや非互換ガイドに記載されていない『些細なバージョン間差分』です。本来であれば些細なバージョン間差分はアプリケーションの振る舞いに影響を与えないものですが、モノによってはバグを顕在化させ、たまたま動作していたものが、バージョンアップすると動かなくなったり、リソースリークを発生させたりします。
コネクションプールの些細な挙動差分による、バグ顕在化の例を以下にまとめます。
WildFlyバージョン間のコネクションプール挙動差分
データソースからコネクションを取得する良くあるコードを考えます。
DataSource ds = ...; try (Connection conn = ds.getConnection()) { System.out.println(conn); // SQLの実行...
WildFlyはバージョンにより、コネクションプールの払い出しポリシーが異なります。
- FIFO(First In First Out)
- プールに返されたコネクションから再払い出し
- 古いコネクションがプールの残るため、一定時間アイドル後の切断設定(idle-timeout-minutes)により切断されやすい
- FILO(First In Last Out)
- 前回の払い出しから最も時間の経っているコネクションから再払い出し
- idle-timeout-minutesの契機で切断されにくい
| バージョン | コネクションプールの払い出しポリシー | |
|---|---|---|
| JBoss AS 7.1.1 | FIFO | |
| WildFly 8.x | FILO | |
| WildFly 9.0.0〜9.0.1 | FIFO | |
| WildFly 9.0.2 | FILO | |
| WildFly 10.x〜 | FILO | |
| 参考: Tomcat8.5.x (DBCP) | FIFO (lifo=falseの追加によりFILOに変更可能) | |
| 参考: Tomcat8.5.x (Tomcat JDBC) | FIFO |
通常はプールの払い出し順序が変わっても、アプリケーションの振る舞いに影響はありません。払い出し順序はJava EE仕様や実装製品固有の仕様で規定されているものでもないため、特定の払い出し順序を期待すること自体、あまり良くないことです。
しかし、APサーバと連携するDBサーバのリソースリークや、アプリケーション自体の潜在的な問題を露にさせることもあります。
PostgreSQL側のメモリリークが顕在化
PostgreSQLには以下で紹介されているように、create temporary tableとdrop temporary tableを同一セッションで繰り返すと、メモリリークする不具合があります。
Memory leak in PL/pgSQL function which CREATE/SELECT/DROP a temporary table
psコマンドで該当のセッションに対応するプロセスのRSSをモニタリングすると徐々に上がっていきます。
# コネクションごとのステータスが書かれている子プロセスのRSSが徐々に上がる USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND postgres 5994 0.0 0.2 338948 4004 ? Ss 07:21 0:00 postgres: postgres test 127.0.0.1(59780) idle
コネクションプールの最小値と最大値を一般的に推奨される同一値に設定したJBoss AS7を、最新のWIldFly10.x系にバージョンアップすると、このメモリリークが顕在化しやすくなります。
JBoss AS7のプール払い出しポリシーはFIFOのため、古いコネクションがプール中に残りやすく、idle-timeout-minutesに到達して定期的に切断され、PostgreSQL側はセッションの終了と共にメモリが解放されます。
一方、WildFly10.x系ではFILOのため、プール中のコネクションは均等に払い出され、アイドル時間が短くなる傾向になります。idle-timeout-minutesに引っかかるコネクションが減り、結果的にPostgreSQL側でセッションごとの子プロセス終了が発生しにくく、メモリリークが顕在化しやすくなります。
対処
WildFlyには設定によってプールの払い出し順序を変更するオプションがあります。
WildFly10.xおよびJBossEAP7.xの場合
JBoss CLIで以下のように設定すると、プール払い出しポリシーがデフォルトのFILOからFIFOに変更されます。
/subsystem=datasources/data-source=データソース名:write-attribute(name=capacity-decrementer-class,value=org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutFIFODecrementer)
上記のCLIはstandalone-xxx.xmlにcapacityの子要素として反映されます。
<datasource jndi-name="java:jboss/jdbc/testDS" pool-name="testDS" enabled="true"> <connection-url>jdbc:postgresql://localhost:5432/test</connection-url> ... <capacity> <decrementer class-name="org.jboss.jca.core.connectionmanager.pool.capacity.TimedOutFIFODecrementer"/> </capacity>
JBoss EAP 6.4.2 以降の場合
有償版のJBoss EAP 6.4系のデフォルトのプール払い出しポリシーはFILOですが、以下のissueによりFIFOに変更できるオプションが6.4.2より追加されています。
[JBJCA-1260] Allow System Property to override default First In First Out (FIFO) pooling behavior - JBoss Issue Tracker
プール払い出しポリシーをFIFOに変更するためには、Javaシステムプロパティに ironjacamar.filo_pool_behavior=true を設定します。
$JBOSS_HOME/bin/standalone.conf
if [ "x$JAVA_OPTS" = "x" ]; then JAVA_OPTS="-Xms1303m -Xmx1303m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true" ... JAVA_OPTS="$JAVA_OPTS -Dironjacamar.filo_pool_behavior=true"
トランザクション設定のミスが顕在化
プールの払い出し順序の変更は、アプリケーションの潜在的なバグを顕在化させ、処理が正常に動作しない事象を引き起こすこともあります。
以下の例はSpringの誤ったトランザクションの設定例です。本来は同一トランザクションでSELECT ... FOR UPDATEによる悲観ロックの取得と更新を実行したいところです。以下のコードでは、privateメソッドに設定された@Transactionalは意味がなく、lock()メソッドとupdate()メソッドは別々のトランザクション、別々のDBコネクション(DBセッション)で動作します。しかし、プールの挙動がFIFOであるJBoss AS7以前にデプロイして動作させると、並行リクエストがない低負荷な状態ではプールに返した直後のコネクションが再度払い出されるため、擬似的にトランザクションが継続したのと同様に振る舞います。
WildFlyのバージョンを上げると、続けて実行されたDataSource.getConnection()が同一のコネクションを返さなくなる為、ロックを取得した状態のコネクションが再取得されません。既に別コネクションで悲観ロックが取得されているため、UPDATE文はロック待ちとなり、タイムアウトまで一時的にハングアップしたように見えます。
@Service public class SampleService { public void doSomething() { lock(); update(); } @Transactional private void lock() { // 悲観ロックの取得 // Connection conn = dataSource.getConnection(); // SELECT ... FOR UPDATE } @Transactional private void update() { // ロックしたレコードの更新 // Connection conn = dataSource.getConnection(); // UPDATE ... SET ... } }
対処
これは単純にアプリケーションのミスであるため、アプリケーションを改修します。
@Service public class SampleService { @Transactional public void doSomething() { lock(); update(); } private void lock() {...} private void update() { ... } }
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だけですが、ネットワーク経由でアクセスする他のファイルシステムも、同様の注意が必要と思います。
