PayaraのJMX Monitoring Service
この記事は 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はメトリクスを属性に持っています。
8080ポートで受付中のHTTPリクエストのスレッドプールの現在の利用状況であれば、thread-pool-mon/mon/server-mon[server]/network/http-listener-1/thread-pool/currentthreadbusy.countが現在払い出されているスレッド数を示します。
JMX Monitoring Serviceによるロギングを有効化は、asadmin set-monitoring-configuration --addpropertyをします。
- --addproperty 'name=(attrname) value=(ObjectName)'
- name=は監視したい属性名でcurrentthreadbusyのようなコンポジット型の場合は、.区切りで要素currentthreadsbusy.countを指定すると、該当の要素のみロギングできます。value=はObjectNameで以下のようにjconsoleで監視したいMBeanをクリックすると確認できます。
- --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を組み込む
この記事は 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つの実装クラスThresoldCircuitBreakerとEventCountCircuitBreakerより構成
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です。
タイムアウトのみ設定してブレーカがないと、タイムアウトを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; } }
作成したサンプルコードの一式はGitHubのbreaker-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
コネクションプールの挙動差分によるバグ顕在化
この記事は 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
