Elastic {ON} 2017 3/7 ノート(1日目)
今日からElastic {ON}が始まった。会場はサンフランシスコのPier48という、AT&Tパーク近くの倉庫のようなイベント会場。キーノートを行う一番大きなセッション部屋はそれなりに大きい。
キーノート
日本のElastic {ON} Tourでもお見かけしたことのある、CTOのShay Banonさんを中心に話は進む。
新しい機能の紹介に絞ると、以下のような話題がある。
- Kibanaの新しいVisualize
- Filebeat module (coming in 5.3)
- Machine Learning (coming in 5.4)
- Elastic Cloud Enterprise (Beta now)
- Elastic SQL (coming soon)
- Kibana canvasプラグイン (coming soon)
Kibanaの新しいVisualize
導入時期については聞き取れず。以下のダッシュボードのような、今までにないVisualizeが追加される。
新しいVisualizeの1つであるtime series。Inboundのトラフィックを中心線より上、Outboundを下にグラフ化し、In/Outの割合がわかりやすくなる。
Filebeat module (coming in 5.3)
詳細はGithubのissuehttps://github.com/elastic/beats/issues/3159 に書かれていたが、Filebeat moduleとは、ざっくりいうと、以下のような設定をまとめたもの。
- Filebeatのprospectorのyml設定
- ElasticsearchのInjest Nodeのパイプライン定義
- Elasticsearchのフィールド定義(各フィールドの型情報など)
- Kibanaダッシュボード
これは、キーノートの後に行われたセッションで説明されていたが、今までのログの取り込みからは可視化までは、以下のようなフローを"ログごとに"繰り返し行う必要があった。
- beatの設定をして
- LogstashでGrok書いて (またはInjest Nodeにパイプライン定義して)
- Elasticsearchのtemplate書いてスキーマ定義して
- KibanaでVisualizeとダッシュボード作る
Filebeat moduleはこれらの"繰り返し"行う作業を一つの既成のモジュールにまとめて、以下のようにbeatの-setupオプションを実行すると、今までやっていたような設定を1コマンドでやってくれるらしい。
Filebeat moduleのデモとして、Nginxログのダッシュボード、SSHアクセスログ(ログイン成功/失敗数など)、sudo実行履歴の分析が紹介されていた。
masterブランチのFilebeat moduleのドキュメントには、Apache2、MySQL、Nginx、Systemの各モジュールがあると示されている。
Machine Learning (comping in 5.4)
日本のElasticのイベントではPrelertという名前で紹介されていた、機械学習プラグインがMachine Learningという名前で紹介された。*1
IT Operationデータと呼ばれていた、仮想的な業務に対するデータ傾向分析のデモ。KibanaのMachine Learningプラグインでは、Jobという単位でタスクを作成。過去のデータから自動的に傾向を抽出し、特異点を発見する。デモの範囲では、いつもの折れ線グラフを作る場合と同じぐらいの入力をしただけで、過去のデータが傾向を抽出。左からデータが増えるごとに、傾向を示す薄い色の範囲が狭くなり、画面右側のようにデータが大きく動くと、また傾向の範囲の精度が荒くなっている。
特異点は、heat map chartのような図で、赤や青で上下に値が振れ過ぎているのを可視化していた。
ここは私の想像の部分だが、以下のような用途で使えるかなぁと思った。
- 一般消費者向けのお店(スーパーとか衣類店など)で、雨降った日に必要以上に売り上げが落ち込んでいる店を一発で可視化する
- システムリソース解析で、色んなサービスがRESTやSOAPで絡み合っているシステムにおいて、業務量がそれほど増えてないのに、他サービスと比較してリソース消費量が多いサービスを一発で抽出する(アプリケーションに性能バグがないか抽出)
Elastic Cloud Enterprise (Beta now)
Elastic Cloudはフルマネージドなサービスに対して、自分の好きなpublic or privateクラウド、またはベアメタルのハード上で、Elastic Cloudのような管理機能を持つクラスタを構築するためのもの。既にBeta1が出ており、ドキュメントは以下から参照できる。
What Is Elastic Cloud Enterprise? | Elastic Cloud Enterprise Reference [1.0.0-beta1] | Elastic
自分の所属している組織で考えると、Elasticスタックを初めて使うプロジェクトに対して、お試し環境として貸し出し用に使いたいなと考えた。外に出せないデータ向けの、オンプレミスのお試し環境は欲しい。プロダクション環境用途として使われると、一人で運用管理するのは少々荷が重い。
Elasticsearch SQL (coming soon)
ElasticsearchクエリにSQLが使えるAPI /_sql の導入。
SELECT文だけでなく、DESCRIBEによるスキーマ情報の確認、EXPLAINによるクエリ実行計画の確認もできる。RDBMSライクに操作可能。
Kibana canvasプラグイン (coming soon)
pptスライドやポスターのようなダッシュボードが作れるプラグイン。以下のスライドのようなものに含まれる、グラフはVisualizeで作成したもので、文字の部分はpptのようにオブジェクトして埋め込んで操作していた。
縦書きの例も紹介。
動画は撮れなかったため、文字では伝わりにくいが、通常のダッシュボードと同様に毎秒更新のような設定をしておくと、グラフが毎秒最新のデータで更新される。ライブデータでプレゼンできるので、人に見せる時にはインパクトがある。
今までのダッシュボードはKibanaっていうのが一目でわかる見た目しか実現できなかったため、システムにあまり詳しくはない、ビジネス寄りの方へのレポート作成として重宝できるプラグインと思われる。
各セッションについては後日追記予定。
What's Evolving in Elasticsearch?
TODO
セッションの前半はElasticsearch5.2までの振り返り。セッション後半が今後の話。
Elasticsearch 6 and beyond
- Doc Value 2.0 (Lucene 7)
- Index Sorting (Lucene 7) https://github.com/elastic/elasticsearch/issues/6720
- Sequence Number (Internal use)
- Rolling Upgrades 6.0
- 5.x系最新から6.x系最新へのアップデート時はクラスタ全体のリスタートが不要に
- ユーザがアップストリームについて来やすいようになる
- Cross Manjor Version Search
- 異なるメジャーバージョンの並行運用が可能。Kibana -> Elasticsearch6.x -> Elasticsearch5.xの流れのように、新しいElasticsearchから古いElasticsearchにリクエストを転送することで、メジャーバージョンが共存したクラスタへのクエリを実現する。
What's Cookin' in Kibana?
TODO
こちらもセッションの前半はKibana5.2までの振り返り。tag cloudやheatmap chart、Logstash Monitoring、I18N(ロシア語などへの一次対応)、5.1.1のKibana高速化など。
セッション後半が今後の話。
- Log event context https://github.com/elastic/kibana/issues/275
- query+filterバーによる補完
- CSVエクスポート
- Top hits aggregations
- Chart Improvement
- 折れ線グラフと棒グラフを1つのVisualizeに描画
What's Brewing in Beats?
TODO
- Filebeat moduleのデモ (MySQL)
- Metricbeatの応用
- PrometheusとMetricbeatを連携させて、アプリケーションレイヤ(注文数など)のメトリクス収集
- jolokiaと組み合わせてJMXメトリクス収集
- Heartbeatの導入
- DockerへのMetricbeat
- DockerコンテナとしてMetricbeatを起動すると、同じホスト内のそれぞれのコンテナの状態を監視できる
将来的なテーマ
*1:言葉で言ってたかは聞き取れなかったが、少なくともキーノートのスライドにはどこにもPrelertって書いてなかった気がする
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)
グラフ項目の色指定
凡例の項目をクリックするとカラーパレットが表示され、グラフ項目を好きな色に変更できるようになった。このような可視化ツールを人に見せると、真っ先に挙がる要望にグラフ色の変更があるが、対応できるようになった。