Loading...

Type: Bug
Resolution: Done
Priority: Critical
Fix Version/s: 30.0.0.Beta1, 30.0.0.Final
Affects Version/s: 29.0.1.Final
Component/s: Clustering
Labels:
None

Story Points:
5
[QE] How to address?:
---
[QE] Why QE missed?:
---

Session expiration events are currently handled via a queue-less cached thread pool. However, since the processing of an expiration event can be costly, and even unpredictable, as they involve application callbacks, concurrent events processing can easily create too many threads.

Ideally, expiration events should be queued, with a fixed pool for processing the events. For EAP 7.4, we will hard code this - and add configuration in EAP8.

2023-08-31T19:34:04.066726858+09:00 [0m[392.422s][warning][os,thread] Failed to start thread "Unknown thread" - pthread_create failed (EAGAIN) for attributes: stacksize: 1024k, guardsize: 0k, detached.
2023-08-31T19:34:04.066726858+09:00 [392.422s][warning][os,thread] Failed to start the native thread for java.lang.Thread "HotRodSessionFactory - 31043"
2023-08-31T19:34:04.066726858+09:00 [31m19:34:03,915 ERROR [org.infinispan.HOTROD] (HotRod-client-async-pool-1) ISPN004038: Unexpected error consuming event ExpiredEventImpl(key=SessionAccessMetaDataKey(mWgOIfp9ZfuJ6CziRLy5O2dCD1nRtOjkVQISIHZ_)): org.infinispan.commons.CacheListenerException: ISPN004035: Caught exception [java.lang.reflect.InvocationTargetException] while invoking method [public void org.wildfly.clustering.web.hotrod.session.HotRodSessionFactory.expired(org.infinispan.client.hotrod.event.ClientCacheEntryExpiredEvent)] on listener instance: org.wildfly.clustering.web.hotrod.session.HotRodSessionFactory@2d52fbd0
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientEventDispatcher$ClientListenerInvocation.invoke(ClientEventDispatcher.java:156)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientEventDispatcher.invokeCallbacks(ClientEventDispatcher.java:120)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientEventDispatcher.invokeEvent(ClientEventDispatcher.java:111)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientEventDispatcher.invokeEvent(ClientEventDispatcher.java:31)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientListenerNotifier.invokeEvent(ClientListenerNotifier.java:197)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.invokeEvent(HeaderDecoder.java:198)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.decode(HeaderDecoder.java:167)
2023-08-31T19:34:04.066726858+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.impl.transport.netty.HintedReplayingDecoder.callDecode(HintedReplayingDecoder.java:94)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
2023-08-31T19:34:04.066796299+09:00     at io.netty//io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-08-31T19:34:04.066796299+09:00     at org.jboss.as.clustering.common@7.4.10.GA-redhat-00002//org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49)
2023-08-31T19:34:04.066796299+09:00     at org.jboss.as.clustering.common@7.4.10.GA-redhat-00002//org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70)
2023-08-31T19:34:04.066796299+09:00     at org.jboss.as.clustering.common@7.4.10.GA-redhat-00002//org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49)
2023-08-31T19:34:04.066796299+09:00     at org.jboss.as.clustering.common@7.4.10.GA-redhat-00002//org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.lang.Thread.run(Thread.java:829)
2023-08-31T19:34:04.066796299+09:00 Caused by: java.lang.reflect.InvocationTargetException
2023-08-31T19:34:04.066796299+09:00     at jdk.internal.reflect.GeneratedMethodAccessor7.invoke(Unknown Source)
2023-08-31T19:34:04.066796299+09:00     at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.lang.reflect.Method.invoke(Method.java:566)
2023-08-31T19:34:04.066796299+09:00     at org.infinispan.client.hotrod@11.0.17.Final-redhat-00001//org.infinispan.client.hotrod.event.impl.ClientEventDispatcher$ClientListenerInvocation.invoke(ClientEventDispatcher.java:154)
2023-08-31T19:34:04.066796299+09:00     ... 33 more
2023-08-31T19:34:04.066796299+09:00 Caused by: java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached
2023-08-31T19:34:04.066796299+09:00     at java.base/java.lang.Thread.start0(Native Method)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.lang.Thread.start(Thread.java:798)
2023-08-31T19:34:04.066796299+09:00     at org.jboss.threads@2.4.0.Final-redhat-00001//org.jboss.threads.JBossThread.start(JBossThread.java:570)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:937)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1354)
2023-08-31T19:34:04.066796299+09:00     at java.base/java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:118)
2023-08-31T19:34:04.066796299+09:00     at org.wildfly.clustering.web.hotrod@7.4.10.GA-redhat-00002//org.wildfly.clustering.web.hotrod.session.HotRodSessionFactory.expired(HotRodSessionFactory.java:144)
2023-08-31T19:34:04.066796299+09:00     ... 37 more
stack of the created HotRodSessionFactory thread 
file: 20230831.tar\20230831\high-cpu-tdump.out_from_imsi04-124-2qpc5
"HotRodSessionFactory - 583" #897 prio=5 os_prio=0 cpu=0.26ms elapsed=0.32s tid=0x000055f130fe8000 nid=0xaa8 waiting on condition  [0x00007f044cb4d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@11.0.18/Native Method)
    - parking to wait for  <0x00000000841008c0> (a java.util.concurrent.CompletableFuture$Signaller)
    at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.18/LockSupport.java:234)
    at java.util.concurrent.CompletableFuture$Signaller.block(java.base@11.0.18/CompletableFuture.java:1798)
    at java.util.concurrent.ForkJoinPool.managedBlock(java.base@11.0.18/ForkJoinPool.java:3128)
    at java.util.concurrent.CompletableFuture.timedGet(java.base@11.0.18/CompletableFuture.java:1868)
    at java.util.concurrent.CompletableFuture.get(java.base@11.0.18/CompletableFuture.java:2021)
    at org.infinispan.client.hotrod.impl.Util.await(Util.java:51)
    at org.infinispan.client.hotrod.impl.RemoteCacheSupport.remove(RemoteCacheSupport.java:251)
    at org.wildfly.clustering.web.hotrod.session.HotRodSessionFactory$1.run(HotRodSessionFactory.java:122)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.18/Executors.java:515)
    at java.util.concurrent.FutureTask.run(java.base@11.0.18/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.18/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.18/ThreadPoolExecutor.java:628)
    at org.jboss.as.clustering.context.ContextReferenceExecutor.execute(ContextReferenceExecutor.java:49)
    at org.jboss.as.clustering.context.ContextualExecutor$1.run(ContextualExecutor.java:70)
    at java.lang.Thread.run(java.base@11.0.18/Thread.java:829)
    at org.jboss.threads.JBossThread.run(JBossThread.java:513)
   Locked ownable synchronizers:
    - <0x0000000084106b40> (a java.util.concurrent.ThreadPoolExecutor$Worker)

The lsof results show that many TCP sockets have been created.

java 2166371 10006700 1079u sock 0,9 0t0 79039301 protocol: TCP
java 2166371 10006700 1080u sock 0,9 0t0 79035217 protocol: TCP
java 2166371 10006700 1081u sock 0,9 0t0 79038232 protocol: TCP
java 2166371 10006700 1082u sock 0,9 0t0 79073486 protocol: TCP
java 2166371 10006700 1083u sock 0,9 0t0 79039303 protocol: TCP
java 2166371 10006700 1084u sock 0,9 0t0 79070371 protocol: TCP
java 2166371 10006700 1085u sock 0,9 0t0 79034315 protocol: TCP
java 2166371 10006700 1086u sock 0,9 0t0 79055465 protocol: TCP
java 2166371 10006700 1087u sock 0,9 0t0 79063258 protocol: TCP

Details

Description

Attachments

Activity

People

Dates