Payara の Request Tracing Service

この記事は、Payara Advent Calendar 2016 の 8 日目です。昨日は「Payara の Notification Service」です。

前々回から Payara が持つ監視機能についてご紹介しており、今回がその最終回となります。Payara には現在、以下の 3 種類の監視機能が備わっています。

  • Health Check Service
  • Nortification Service
  • Request Tracing Service

今回は Request Tracing Service について取り上げます。

1. Request Tracing Service とは

Request Tracing Service は、Payara の HTTP 通信を監視して、一定の閾値を超えているものを server.log へ出力するための機能です。Payara が持つ 3 種類の監視機能では最も新しく、プレビュー版が Payara 4.1.1.163 で導入され、Payara 4.1.1.164 から正式版となりました。

Request Tracing Service の監視対象は HTTP 通信が関わるあらゆるサービスで、具体的には以下のものが該当します。

  • REST (JAX-RS エンドポイント)
  • Servlet (HTTP リクエスト処理)
  • SOAP Web サービス・リクエスト
  • WebSocket
  • EJB タイマーの実行
  • Message-Driven Bean (MDB) が処理するインバウンドの JMS メッセージ
  • JBatch ジョブの作成
  • Managed Executor による新しいタスクの実行

Request Tracing Service は監視範囲が広く大きな効果が得られる一方で、Payara への負荷も高くなります。Health Check Service や Notification Service のように常時有効化することは想定されておらず、トラブルシューティングのための監視機能と割り切って使用した方が良いでしょう。

2. Request Tracing Service の設定

2.1. Request Tracing Service の有効化/無効化

Request Tracing Service は既定で無効となっています。有効化するには管理コンソールまたは asadmin コマンドを使用します。

最も簡単な方法として、管理コンソールの Request Tracing Configuration 画面 (figure 1) から機能を有効化できます。チェックボックス 1 箇所の設定であるため、非常に簡単です。

Request Tracing Configuration.png
figure 1 - Request Tracing Configuration 画面

asadmin コマンドの場合は、requesttracing-configure サブコマンドを使用します。以下に例を示します。

$ asadmin requesttracing-configure --enabled=true --thresholdValue=30 --thresholdUnit="SECONDS" --dynamic=true

--thresholdValue と --thresholdUnit で閾値を指定します。この例では 30 秒を閾値としています。なお、これらの値は requesttracing-configure の既定値です。--dynamic=true は設定の即時反映を行うためのオプションです。

無効化する場合は、管理コンソールでチェックボックスを外すか、以下のコマンドを実行します。

$ asadmin requesttracing-configure --enabled=false --dynamic=true

2. Request Tracing Service の実際

Request Tracing Service は、既に Payara が実装している SQL トレース機能 (Slow SQL Logger) に続くトレース機能です。閾値を超える HTTP 通信が発生すると、その内容を server.log へ出力します。

Request Tracing Service の特徴のひとつとして、ログに出力するトレース情報が JSON 形式となっている点が上げられます。下記に Payara Blog に掲載されているログ出力例を転載します。全体が JSON 形式となっているわけではないため多少の加工は必要ですが、トレース情報を分析する上で有利に働きます。

[2016-09-01T13:02:13.456+0200] [Payara 4.1] [INFO] [] [fish.payara.nucleus.notification.service.LogNotifierService] [tid: _ThreadID=100 _ThreadName=http-thread-pool(5)] [timeMillis: 1472727733456] [levelValue: 800] [[
  Request execution time: 6286(ms) exceeded the acceptable threshold - {"RequestTrace": {"startTime":"1472727727170","elapsedTime":"6286",
"TraceEvent": {"eventType": "TRACE_START","eventName":"StartTrace","id=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727170","Server": "server","Domain": "domain1","traceTime=":"0"},
"TraceEvent": {"eventType": "REQUEST_EVENT","eventName":"RESTWSRequest","id=":"a85caaf3-34eb-4c99-bc8d-3aded9acac4d","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727171","accept-language": "[en-US,en;q=0.5]","cookie": "[__utma=111872281.148356872.1462355409.1471938946.1472580408.6; __utmz=111872281.1462355409.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); JSESSIONID=50143d92a74d317aaeb825691234; treeForm_tree-hi=treeForm:tree:configurations:server-config:notification; __utmc=111872281]","host": "[localhost:8080]","connection": "[keep-alive]","Method": "GET","URL": "http://localhost:8080/SimpleWAR/rest/request","accept-encoding": "[gzip, deflate]","user-agent": "[Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:48.0) Gecko/20100101 Firefox/48.0]","accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8]","traceTime=":"1"},
"TraceEvent": {"eventType": "REQUEST_EVENT","eventName":"EJBMethod-ENTER","id=":"322fd38a-cf4e-44e6-a361-cea077c24526","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727415","EJBMethod": "execute","ComponentType": "STATELESS_SESSION_BEAN","ApplicationName": "null","ModuleName": "SimpleWAR","ComponentName": "DemoEJB","EJBClass": "demo.requesttracing.DemoEJB","TX-ID": "JavaEETransactionImpl: txId=402 nonXAResource=null jtsTx=null localTxStatus=0 syncs=[com.sun.ejb.containers.ContainerSynchronization@7a4d066a]","CallerPrincipal": "ANONYMOUS","traceTime=":"245"},
"TraceEvent": {"eventType": "REQUEST_EVENT","eventName":"EJBMethod-EXIT","id=":"68f391db-493d-4d01-bcd8-20e1797beee3","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727416","EJBMethod": "execute","ComponentType": "STATELESS_SESSION_BEAN","ApplicationName": "null","ModuleName": "SimpleWAR","ComponentName": "DemoEJB","EJBClass": "demo.requesttracing.DemoEJB","TX-ID": "JavaEETransactionImpl: txId=402 nonXAResource=null jtsTx=null localTxStatus=0 syncs=[com.sun.ejb.containers.ContainerSynchronization@7a4d066a]","CallerPrincipal": "ANONYMOUS","traceTime=":"246"},
"TraceEvent": {"eventType": "REQUEST_EVENT","eventName":"InterceptedCdiRequest-ENTER","id=":"c0ab2f7a-ca37-4dfd-82de-27a07117b525","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727452","MethodName": "execute","TargetClass": "demo.requesttracing.DemoTrackedCDI$Proxy$_$$_WeldSubclass","traceTime=":"282"},
"TraceEvent": {"eventType": "REQUEST_EVENT","eventName":"InterceptedCdiRequest-EXIT","id=":"ae52efcd-761a-4d5a-971d-f704169c66a6","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727727453","MethodName": "execute","TargetClass": "demo.requesttracing.DemoTrackedCDI$Proxy$_$$_WeldSubclass","traceTime=":"283"},
"TraceEvent": {"eventType": "TRACE_END","eventName":"TraceEnd","id=":"288a524c-3d4f-492c-beda-c3accf5d502c","conversationId=":"dc0d27e5-d8eb-41cc-9b7f-89a230b0dfa4","timestamp=":"1472727733456","traceTime=":"6286"}}}]]

Payara Blog には Payara 4.1.1.163 のプレビュー版ベースですが Request Tracing Service の詳細が掲載されています。より深く知りたい場合は是非ご覧ください。