1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Libertyがハングしたかを TRAS0112W, TRAS0114W で確認する

Posted at

目的

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

起動したら以下にアクセスします。

image.png

遅い要求

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 のメッセージを確認しました。

1
0
2

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?