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

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

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

コネクションプールの挙動差分によるバグ顕在化

JBoss

この記事は 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() { ... }
}

まとめ

バージョンアップに伴う些細な差分がバグを顕在化させる例を紹介しました。

このような一定の仕様範囲の些細な実装差分は、ドキュメントに記載されていることも少なく、突然遭遇します。少しでもこのような問題を避けるためには、以下のようなことに注意します。

  • ドキュメントやAPI仕様に書いていない振る舞いには期待しない
    • 例えばjava.sql.DataSourceインタフェースのAPI仕様には払い出し順序に関する言及はありません
  • APサーバの内部クラスに依存させない
    • 可能な限りjavax.xxxパッケージのJava EEの範囲でコードを書く
    • org.jbossなどの実装依存のクラスを利用する際は、互換性に強く期待しない

上記を守っていても、問題を必ず避けられるわけではありません。
普段から対象製品のログレベルの詳細化方法やソースコードの入手、jdbによるデバッグに慣れておくことで、問題に遭遇しても、すぐに原因を特定できるような準備が大切です。

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のバッファ拡大の方が早いです