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

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

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

PayaraのJMX Monitoring Service

GlassFish

この記事は Payara Advent Calendar 2016の12/23分の記事です。
昨日はsuke_masaさんのPayaraのバグを報告してみようでした。
明日は@yumix_hさんです。


2016/8/1にリリースされた Payara Server 4.1.1.163 より、指定したJMX MBeanの値を定期的にロギングできるJMX Monitoring Serviceが追加されました。

多くのAPサーバではJMX経由でリクエストスレッドプールや、JDBCコネクションプールなどの枯渇すると重大なトラブルに絡むことを多いメトリクスを収集できますが、jconsoleでは最新値を見れるだけなので事後障害解析には役立ちません。障害解析には虚無僧を使ってロギングしたり、jolokiaを追加してHTTP-API経由によるLogstashやFluentdで定期的に収集した値が必要です。

Payaraは虚無僧を加えなくてもJMX MBeanの値のロギングが可能です。

JMX Monitoring Serviceの使い方

Payaraの公式ドキュメントにはJavaヒープメモリ使用量の例が記載されています。
しかし、ヒープメモリのロギングであればGCログ(-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps)の方がより詳細な情報が取得できます。JMXに期待するのはヒープ以外のメトリクスです。

GlassFishの頃より、PayaraにはMonitoring Serviceという仕組みがあり、デフォルトではオーバヘッド削減のためメトリクス収集は無効となっていますが、モジュールごとに有効化が可能です。JMX Monitoring Serviceでロギングするためには、事前に対象モジュールのモニタリングを有効化させる必要があります。

Monitoring Serviceの設定状況は asadmin get "server.monitoring-service.module-monitoring-levels.*" で一覧が取得できます。

./asadmin get "server.monitoring-service.module-monitoring-levels.*"
server.monitoring-service.module-monitoring-levels.cloud=OFF
server.monitoring-service.module-monitoring-levels.cloud-elasticity=OFF
server.monitoring-service.module-monitoring-levels.cloud-orchestrator=OFF
server.monitoring-service.module-monitoring-levels.cloud-tenant-manager=OFF
server.monitoring-service.module-monitoring-levels.cloud-virt-assembly-service=OFF
server.monitoring-service.module-monitoring-levels.connector-connection-pool=OFF
server.monitoring-service.module-monitoring-levels.connector-service=OFF
server.monitoring-service.module-monitoring-levels.deployment=OFF
server.monitoring-service.module-monitoring-levels.ejb-container=OFF
server.monitoring-service.module-monitoring-levels.http-service=HIGH
server.monitoring-service.module-monitoring-levels.jdbc-connection-pool=OFF
server.monitoring-service.module-monitoring-levels.jersey=OFF
server.monitoring-service.module-monitoring-levels.jms-service=OFF
server.monitoring-service.module-monitoring-levels.jpa=OFF
server.monitoring-service.module-monitoring-levels.jvm=OFF
server.monitoring-service.module-monitoring-levels.orb=OFF
server.monitoring-service.module-monitoring-levels.security=OFF
server.monitoring-service.module-monitoring-levels.thread-pool=HIGH
server.monitoring-service.module-monitoring-levels.transaction-service=OFF
server.monitoring-service.module-monitoring-levels.web-container=OFF
server.monitoring-service.module-monitoring-levels.web-services-container=OFF

今回はHTTPリクエスト処理のスレッドプールを例にするため、http-serviceの監視レベルを変更します。

./asadmin set "server.monitoring-service.module-monitoring-levels.http-service=HIGH"

jconsoleで接続すると、監視が有効化されている場合、amx配下にthread-pool-monが表示されます。xxx-mon配下のMBeanはメトリクスを属性に持っています。

f:id:n_agetsuma:20161223150553p:plain:w300

8080ポートで受付中のHTTPリクエストのスレッドプールの現在の利用状況であれば、thread-pool-mon/mon/server-mon[server]/network/http-listener-1/thread-pool/currentthreadbusy.countが現在払い出されているスレッド数を示します。

f:id:n_agetsuma:20161223151111p:plain

JMX Monitoring Serviceによるロギングを有効化は、asadmin set-monitoring-configuration --addpropertyをします。

  • --addproperty 'name=(attrname) value=(ObjectName)'
    • name=は監視したい属性名でcurrentthreadbusyのようなコンポジット型の場合は、.区切りで要素currentthreadsbusy.countを指定すると、該当の要素のみロギングできます。value=はObjectNameで以下のようにjconsoleで監視したいMBeanをクリックすると確認できます。

f:id:n_agetsuma:20161223151643p:plain

  • --enable true | false
    • falseを指定すると、次回起動時よりJMX Monitoring Serviceによるロギングが無効化されます。通常はtrueを指定します。
  • --amx true
    • Payara(GlassFish)はApplication Server Management Extension (AMX)という仕組みを利用してMBeanを外部に公開しています。AMXの詳細については、AMX: Design and Useに記載されています。jconsoleでamx配下にあるMBeanを対象にロギングしたい場合は --amx true を指定します
  • dynamic=true
    • オプションで再起動せずにすぐにset-monitoring-configurationした設定によるロギングを開始したい場合に設定します。
./asadmin set-monitoring-configuration --addproperty 'name=currentthreadsbusy.count value=amx:pp=/mon/server-mon[server],type=thread-pool-mon,name=network/http-listener-1/thread-pool' --enabled true --amx true --dynamic=true

設定が有効化されると、$DOMAIN_HOME/logs/server.logには以下のようにログが15秒間隔で出力されます。Filebeatなどで収集してElasticスタックで可視化しておくと、過去の値も振り返ることができます。

[2016-12-23T14:43:50.399+0900] [Payara 4.1] [INFO] [] [fish.payara.jmx.monitoring.MonitoringFormatter] [tid: _ThreadID=47 _ThreadName=payara-monitoring-service(1)] [timeMillis: 1482471830399] [levelValue: 800] [[PAYARA-MONITORING: countcurrentthreadsbusy=0 ]]

まとめ

虚無僧がなくても気軽にJMX MBeanがロギングできるPayaraのJMX Monitoring Serviceを紹介しました。上記以外にもいくつかのオプションがあるため、合わせて公式ドキュメントもご参照ください。

おまけ: MacでPayara起動が遅い、jconsoleで接続できない場合

macOS Sierraでハマったのが、hostnameコマンドで確認できるホスト名localhost.localが/etc/hostsになく、ローカルホストのDNS名が引けない状態だと、Payaraの起動に1分以上かかったり、jconsoleでローカル接続できません。起動中のスレッドダンプを取ると、以下のように名前解決でタイムアウトしているように見えます。

"main" #1 prio=5 os_prio=31 tid=0x00007fd7e1804000 nid=0x1c03 runnable [0x0000700008414000]
   java.lang.Thread.State: RUNNABLE
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method)
        at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:928)
        at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1323)
        at java.net.InetAddress.getLocalHost(InetAddress.java:1500)
        - locked <0x00000007b8ea7eb8> (a java.lang.Object)
        at com.sun.enterprise.util.net.NetUtils.getCanonicalHostName(NetUtils.java:313)
        at com.sun.enterprise.universal.glassfish.ASenvPropertyReader$ASenvMap.getHostname(ASenvPropertyReader.java:310)

以下のようにlocalhost.localを/etc/hostsに加えると、1分間ほどかかるasadmin start-domainが4秒になりました。

$ sudo vim /etc/hosts
127.0.0.1       localhost localhost.local
255.255.255.255 broadcasthost
::1             localhost localhost.local

Payaraは軽快に起動するサーバです。起動が遅いと思った時は上記に当たっていないか試して見ると効果的です。

Commons Lang 3.5 でJava EEにBreakerを組み込む

CDI1.2 Java EE 7

この記事は Java EE Advent Calendar 2016の12/13分の記事です。
昨日はsuke_masaさんの必要最小限のサンプルでThymeleafを完全マスターでした。
明日は@kazuhira_rさんです。


Payara MicroやWildFly Swarmをベースとしたマイクロサービス対応の共通仕様の規定を目指しているmicroprofile.ioでは、Circuit Breakerの仕様盛り込みがこのスレッドで議論されています。

Circuit Breaker実装というとHystrixが有名ですが、上記スレッドでCommons Langに簡易なCircuit Breaker実装が追加されたことに言及があったため紹介します。

2016年10月にリリースされたCommons Lang 3.5より、LANG-1085により、シンプルなBreaker実装が加わっています。ドキュメントとしてはJavaDocがあります。

Commons LangのBreakerの特徴

  • Half Open状態がない
    • 状態はデフォルトのcloseと、異常が閾値を超えた場合のopen状態のみ
  • HystrixのようなWebダッシュボードはない
  • APIやコマンドで手動によるブレーカ切り替え機能はない
  • 非常にシンプルでCircuitBreakerインタフェースと、2つの実装クラスThresoldCircuitBreakerEventCountCircuitBreakerより構成

ThresholdCircuitBreakerクラスは単純に一定の回数、イベントが発生したらブレーカの開閉を行います。一般的なブレーカのイメージである、1分間で5回以上の例外が発生したらブレーカを開けてデフォルト応答を返し、1分間で例外が発生しなかったらブレーカを閉じて元に戻す実装はEventCountCircuitBreakerクラスです。

以下にJAX-WSクライアントに組み込んだ例を示します。

@ApplicationScoped
public class SoapClient {
    private static final Logger LOG = LoggerFactory.getLogger(SoapClient.class);
    private static final String DEFAULT_RESPONSE = "duke hello world!";
    private HelloEndPoint helloEndPoint;

    @PostConstruct
    public void init() {
        helloEndPoint = new HelloEndPointService().getHelloEndPointPort();
        ((BindingProvider) helloEndPoint).getRequestContext().put("javax.xml.ws.client.connectionTimeout", "5000");
        ((BindingProvider) helloEndPoint).getRequestContext().put("javax.xml.ws.client.receiveTimeout", "60000");
        // 第1引数は閾値で一定期間内で内部カウンタ値がこの値を超えたらブレーカを開け、この値を下回ったら再び閉じる
        // 第2、第3引数は閾値の集計時間単位で、以下の例では1分
        breaker = new EventCountCircuitBreaker(5, 1, TimeUnit.MINUTES);
    }

    public String helloWorld(String name) {
        if (breaker.checkState()) {
            try {
                return helloEndPoint.helloWorld(name);
            } catch (Exception e) {
                breaker.incrementAndCheckState();
            }
        } else {
            // ブレーカが開いた場合のデフォルト処理
           LOG.warn("breaker open");
           return DEFAULT_RESPONSE;
        }
    }
}

breaker.checkState()はブレーカが平常時を示すclose状態であればtrueを返し、異常時のopen状態であればfalseを返します。上記の例では、trueを返された場合はSOAPリクエストを投げています。falseが返された場合はブレーカが閾値に達しているため、SOAPリクエストを投げずにデフォルトの応答値を返しています。

例外発生時は、breaker.incrementAndCheckState()を実行し、カウンタ値をインクリメントします。上記の例ではSOAPFaultExceptionが投げられてもカウンタがインクリメントされるため、SOAPFaultが投げられる仕様のAPIでは、どの例外でincrementAndCheckState()を実行するか注意が必要です。

ブレーカはタイムアウトと組み合わせることで初めて効果を発揮します。上記の例においても、WildFly(JBoss)のSOAPクライアントのタイムアウト設定を盛り込んでいます。SOAPクライアントのタイムアウトは実装により異なります。例えば、Metroの場合はcom.sun.xml.ws.connect.timeoutとcom.sun.xml.ws.request.timeoutです。

  • javax.xml.ws.client.connectionTimeout
    • TCP接続時のタイムアウト。NW障害などにより、SYNを送っても応答がなく、TCP接続できない状態に有効。
  • javax.xml.ws.client.receiveTimeout
    • 応答を待つタイムアウトTCP接続後にHTTPリクエストは送信できたが、対向がスローダウンしてHTTP応答が遅い場合に有効。

タイムアウトのみ設定してブレーカがないと、タイムアウトを60秒などの長い時間を指定していた場合、あっという間にリクエスト処理スレッドのプールが枯渇して、SOAPリクエストと全く関係のない機能まで動かなくなる障害の連鎖が起こり得ます。障害が発生しているマシンにはアクセスせずに即座にデフォルト応答を返し、問題のないサービスを守ることがブレーカの目的です。

CDI Extensionでブレーカを組み込む

Commons Lang自体には@HystrixCommandのようなアノテーションによる宣言的なブレーカ設定の仕組みはありません。しかし、CDIインターセプタとCDI Extensionによるアノテーションスキャンの仕組みを用いると、Commons Langでも以下のように宣言的な@Breakerが実現できます。

@ApplicationScoped
public class SoapClient {
    // 一部省略。完全なコードはGitHub参照
    @Breaker(fallbackMethod = "fallback")
    public String helloWorld(String name) {
        return helloEndPoint.helloWorld(name);
    }

    String fallback(String name) {
        return DEFAULT_RESPONSE;
    }
}

作成したサンプルコードの一式はGitHubbreaker-sampleに置いています。
思ったよりクラス数が増えてしまったため、ポイントのみ示します。

ブレーカ実装はインターセプタで実現します。

@Interceptor
@Priority(Interceptor.Priority.APPLICATION)
@Breaker
public class BreakerInterceptor {

    @AroundInvoke
    public Object intercept(InvocationContext ic) throws Exception {
        BreakerHolder holder = Breakers.get().breaker(ic.getMethod());
        EventCountCircuitBreaker breaker = holder.breaker();

        if (breaker.checkState()) {
            try {
                return ic.proceed();
            } catch (Exception e) {
                breaker.incrementAndCheckState();
                throw e;
            }
        }

        // exec fallbackMethod
        Method fallback = holder.fallback();
        return fallback.invoke(ic.getTarget(), ic.getParameters());
    }
}

@Breakerはインターセプタバインディング型のユーザ定義アノテーションです。

@InterceptorBinding
@Inherited
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface Breaker {
    @Nonbinding int openingThreshold() default 5;
    @Nonbinding long checkInterval() default 1;
    @Nonbinding TimeUnit checkUnit() default TimeUnit.MINUTES;
    @Nonbinding int closingThreshold() default 5;
    @Nonbinding  String fallbackMethod() default "";
}

interceptメソッドの中でアノテーションが持つブレーカ設定のロードと、ブレーカの初期化を実装しても良いですが、初回リクエスト時のコストが高くなってしまいます。CDI Extensionを使うと、@Breakerが付与されたCDI Beanの一覧を取得して、デプロイ時にアノテーションスキャン処理が実装できます。

以下は@WithAnnotations({Breaker.class})を設定して、@Breakerが付与されたクラス・メソッドのクラス情報を引数にコールバックされるCDI Extensionです。EventCountCircuitBreakerの初期化やブレーカ開放時に実行するfallbackMethodが存在するかのチェック、リフレクションでfallbackMethodのMethodインスタンスを取得してキャッシュなどの処理をしています。クラスの全体はBreakerExtentionクラスより参照できます。

public class BreakerExtention implements Extension {
    ....
    <T> void processAnnotatedType(@Observes @WithAnnotations({Breaker.class}) ProcessAnnotatedType<T> pat) {
        Breakers breakers = Breakers.get();
        if (!pat.getAnnotatedType().getJavaClass().equals(BreakerInterceptor.class)) {
            pat.getAnnotatedType().getMethods().stream()
                    .filter(method -> method.isAnnotationPresent(Breaker.class))
                    .map(method -> method.getJavaMember())
                    .forEach(method -> {
                        BreakerConfig config = createConfig(method);
                        Method fallbackMethod = getFallbackMethod(method.getDeclaringClass(), config.getFallbackMethod());
                        String fqcn = fqcn(method);
                        breakers.put(method, createBreakerHolder(config, fallbackMethod, fqcn));
                        LOG.info("breaker created for " +  fqcn + ", now state is close. " + config);
                    });
        }
    }
   ...

CDI Extensionを有効にするためには、META-INF/services/javax.enterprise.inject.spi.Extensionを含め、Extension実装クラス名を定義します。

sample.breaker.BreakerExtention

Commons Langのブレーカが有効なケース

statsのAPIが欲しい、Webダッシュボードが欲しいなど、ボリュームが膨らみそうな場合はCDIインターセプタ実装を膨らまして劣化 Hystrixにするよりも、素直にHystrixを使う方が適切です。

Commons Langのブレーカの強みはそのコンパクトさです。レガシーなシステムでHystrixを導入するのは周りの同意が得られにくい、Hystrixを導入するとそのメンテナンス自体にも責任を負わなければいけない状況では、軽量なCommons Langであれば新たに含めることに障害が少ない場合も多いと思います。

まとめ

Commons Langによるブレーカ実装と、インターセプタとCDI Extentionを用いて宣言的ブレーカの実装を紹介しました。microprofile.ioによりJava EEサーバにもCircuit Breakerが実装されて、自分で作り込まずに済むことを楽しみにしています。

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

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