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

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

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

LogstashからIngest Nodeへの移行

ELK

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ファイル名>
  • -t 時刻をUTCではなくローカルのタイムゾーン時間を表示
  • -d ; 区切りで表示
  • -P ALL CPUコアごとにCPU使用率を出力。-1がALL相当。0はcpu0、1はcpu1。

以下のようなログをパース対象とする。

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になる頃にはこの回避策は不要になるだろう。

また、drop相当の機能はAlpha5の段階では見当たらないため、『centos7;-1;2016-09-14 21:02:39;LINUX-RESTART』のようにgrokでパースできない行にあたると、Elasticsearch側でエラーログが出力され、該当行のpipelineの処理はスキップされる。エラーログが気になる場合は、Filebeatのinclude-lineで送信したい行のフォーマットの正規表現が指定でき、Elasticsearchに送信するログをFilebeat側で絞り込むことが可能。

pidstat (プロセス別CPU使用率)

不安定なシステムにおいて定常的にcronで収集する。
JavaPostgreSQLが同一のマシンのサービスとして稼働しているが、どれが重くなっているのかがわからないときに必要なデータ。

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)     	20160916日 	_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風に取り込む

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を使っているなど、単純な置き換えはバグを招く