目的
Libertyの場合はtWASの時とは違い、featureを有効にしていないと応答がハングしているときのログを出力してくれません。その設定方法を確認します。
tWASとは違ってfeatureを有効にしないとログしないので、その点に気をつけて設定します。
遅い要求およびハング要求の検出方法
マニュアルにも記述はあるのですが、featureを有効にする必要があります。
<feature>requestTiming-1.0</feature>
...
<requestTiming slowRequestThreshold="5s" hungRequestThreshold="10m">
</requestTiming>
これまでも設定には追加していたのだけど改めての紹介です。featureを有効にします。server.xml に構成を追加しましょう。
Libertyテスト環境の自動構築
これまでの方法で既存環境に構成は可能ですが、環境をdockerで用意する方法です。
用意したGitレポジトリをクローンします。
git clone https://github.com/pdprof/crash-heapdump.git
cd crash-heapdump/pdpro-docker
Libertyのイメージをビルドして開始します。
./setup-docker.sh
./pdpro-start.sh
起動したら以下にアクセスします。
遅い要求
Call Sleep Servlet で 15 を Submitします。以下のような TRAS0112W のログとそのときのスタックトレースが出力されます。遅くなっているときのメソッドをこのログから確認します。
このログだと pdpro.hang.MySleep.doSleep が sleep をよびだしている怪しいメソッドだと考えることになります。
[WARNING ] TRAS0112W: Request AAHGdksdckP_AAAAAAAAAAA has been running on thread 0000003d for at least 15008.362ms. The following stack trace shows what this thread is currently running.
at java.base/java.lang.Thread.sleepImpl(Native Method)
at java.base/java.lang.Thread.sleep(Thread.java:991)
at java.base/java.lang.Thread.sleep(Thread.java:974)
at pdpro.hang.MySleep.doSleep(MySleep.java:8)
at pdpro.hang.MySleepServlet.doTask(MySleepServlet.java:44)
at pdpro.hang.MySleepServlet.doPost(MySleepServlet.java:35)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:706)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1260)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:748)
at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:445)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:197)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:100)
at com.ibm.ws.security.jaspi.JaspiServletFilter.doFilter(JaspiServletFilter.java:58)
at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:199)
at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:93)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:1068)
at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1259)
at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:5079)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.handleRequest(DynamicVirtualHost.java:318)
at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1038)
at com.ibm.ws.webcontainer.osgi.DynamicVirtualHost$2.run(DynamicVirtualHost.java:283)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink$TaskWrapper.run(HttpDispatcherLink.java:1248)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.wrapHandlerAndExecute(HttpDispatcherLink.java:470)
at com.ibm.ws.http.dispatcher.internal.channel.HttpDispatcherLink.ready(HttpDispatcherLink.java:429)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:569)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.handleNewRequest(HttpInboundLink.java:503)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.processRequest(HttpInboundLink.java:363)
at com.ibm.ws.http.channel.internal.inbound.HttpInboundLink.ready(HttpInboundLink.java:330)
at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:169)
at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:77)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:516)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:586)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:970)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1059)
at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:247)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:839)
ハング要求
sleep を長くするのもいいのですが、今度はデッドロックを試します。以下のような TRAS0114W のログとjavacoreを出力した事が確認できます。javacoreからハングの原因賭なった処理をみていく事になります。
Duration Operation
600001.084ms + websphere.servlet.service | Hang | MyDeadlockServlet?lock=AB
[WARNING ] TRAS0114W: Request AAHGdksdckP_AAAAAAAAAAC has been running on thread 00000039 for at least 600001.370ms. The following table shows the events that have run during this request.
Duration Operation
600001.501ms + websphere.servlet.service | Hang | MyDeadlockServlet?lock=BA
[AUDIT ] CWWKE0067I: Java dump request received.
JVMDUMP034I User requested Java dump using '/pdprof/share/javacore.20250730.160554.1.0001.txt' through com.ibm.jvm.Dump.javaDumpToFile
JVMDUMP010I Java dump written to /pdprof/share/javacore.20250730.160554.1.0001.txt
今回の場合は javacore に
1LKDEADLOCK Deadlock detected !!!
NULL ---------------------
NULL
2LKDEADLOCKTHR Thread "Default Executor-thread-7" (0x00000000007B3D00)
3LKDEADLOCKWTR is waiting for:
4LKDEADLOCKMON sys_mon_t:0x00007F1EEC594C18 infl_mon_t: 0x00007F1EEC594C98:4LKDEADLOCKOBJ java/lang/Object@0x000000061376B0A8
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "Default Executor-thread-15" (0x0000000000A55E00)
3LKDEADLOCKWTR which is waiting for:
4LKDEADLOCKMON sys_mon_t:0x00007F1EEC2D1F08 infl_mon_t: 0x00007F1EEC2D1F88:4LKDEADLOCKOBJ java/lang/Object@0x000000061376B098
3LKDEADLOCKOWN which is owned by:
2LKDEADLOCKTHR Thread "Default Executor-thread-7" (0x00000000007B3D00)
と Deadlock detected が出力されています。この出力にある
Default Executor-thread-7
Default Executor-thread-15
のスタックトレースからアプリケーションの問題ある部分を確認します。
トラブルシューティング
毎度のことですが、よくつかう dockerコマンドを書いておきます。この文書でもpodman, dockerとまとまりがないですが、Linux では dockerがpodmanを呼び出すようになっていました。
docker ps # 動作中のContainer確認
docker logs -f pdpro # ログ確認
docker restart pdpro # 再起動
docker inspect pdpro # container 確認
docker exec -it pdpro bash # Container内状況確認
まとめ
Libertyでハングが発生したときにログを出力するための feature requestTiming-1.0 と TRAS0112W, TRAS0114W のメッセージを確認しました。