Infinispan HOTROD客户端抛出间歇性java.net.SocketTimeoutException:Get



我正在使用Infinispan HOTROD将java应用程序与JDK8一起运行在IBM Liberty应用服务器上。

HOTROD客户端(lib 12.1.11.Final-redhat-00001版本(通过`实现

org.infinispan.jcache.remote.JCachingProvider:

@PostConstruct
private void setUp() {
LOGGER.info("START [setUp] CACHE");

File conf = new File(System.getenv("CLIENT_HOTROD_FILE_PATH"));

URI uri = conf.toURI();

// Retrieve the system wide cache manager via org.infinispan.jcache.remote.JCachingProvider
javax.cache.CacheManager cacheManager = Caching.getCachingProvider("org.infinispan.jcache.remote.JCachingProvider")
.getCacheManager(uri, this.getClass().getClassLoader(), null);

this.cache = cacheManager.getCache(DATAGRIDKEY);

LOGGER.info("END [setUp] cache " + this.cache.getName() );
}

HOT-ROD客户端配置文件

infinispan.client.hotrod.server_list=server1.x.xx.xxx:11222;server2.x.xx.xxx:11222;server3..x.xx.xxx:11222;server4..x.xx.xxx:11222
infinispan.client.hotrod.auth_username=user-app
infinispan.client.hotrod.auth_password=password
infinispan.client.hotrod.auth_realm=default
infinispan.client.hotrod.sasl_mechanism=SCRAM-SHA-512
infinispan.client.hotrod.client_intelligence=HASH_DISTRIBUTION_AWARE

HOT-ROD客户端配置属性可用

否则,config服务器REDHAT数据网格(8.2.3版本(如下:

{
"distributed-cache": {
"mode": "ASYNC",
"remote-timeout": 17500,
"state-transfer": {
"timeout": 60000
},
"encoding": {
"key": {
"media-type": "text/plain"
},
"value": {
"media-type": "application/x-protostream"
}
},
"locking": {
"concurrency-level": 1000,
"acquire-timeout": 15000,
"striping": false
},
"statistics": true
}
}  

有时,当应用程序在日志应用程序端有一些请求时,会出现java.net.SocketTimeoutException:GetOperation问题,如下所示:stacktrace:

[2/15/22 17:24:39:445 CET] 00000573 HOTROD W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0x9a1a8fb2, L:/10.0.20.160:55295 ! R:10.0.18.97/10.0.18.97:11222] due to transport error java.net.SocketTimeoutException: GetOperation{Cache-Name-Test, key=[B0x4A6C636F6D2E6475636174692E77612E..[110], flags=1, connection=10.0.18.97/10.0.18.97:11222} timed out after 60000 ms
at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:822) 

当应用程序接收到大量的GET KEY请求时,该问题会更频繁,但有时该问题会发生在未处理的加载请求期间。

你能知道如何解决这个问题吗?你知道什么建议吗?

感谢

我试图编辑客户端配置HOT-ROD以了解客户端的行为,下面我想总结一下新的配置更改:

infinispan.client.hotrod.server_list=server1:11222;server2:11222;server3:11222;server4:11222
infinispan.client.hotrod.auth_username=user-app
infinispan.client.hotrod.auth_password=password
infinispan.client.hotrod.auth_realm=default
infinispan.client.hotrod.sasl_mechanism=SCRAM-SHA-512
infinispan.client.hotrod.socket_timeout=15000
infinispan.client.hotrod.connect_timeout=60000
infinispan.client.hotrod.max_retries=5
# Connection pool
infinispan.client.hotrod.connection_pool.max_active=50
infinispan.client.hotrod.connection_pool.exhausted_action=WAIT
infinispan.client.hotrod.connection_pool.max_wait=20000
infinispan.client.hotrod.connection_pool.min_idle=10
#default is 1800000
infinispan.client.hotrod.connection_pool.min_evictable_idle_time=600000
infinispan.client.hotrod.connection_pool.max_pending_requests=846

我注意到更改infinispan.client.hotrod.socket_timeout=15000毫秒。Whatching应用程序日志文件我看到了同样的错误,但目前,60000毫秒,是到15000毫秒的socketTimeoutException。使用新设置,即使记录了异常,线程请求也会成功完成线程请求。

我认为要理解的是,有时在池中似乎有连接失效,客户端搜索并尝试另一个活跃的连接到池中,重试GetOperation。

如在org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation类代码中写入库热棒:

/**
* Base class for all the operations that need retry logic: if the operation fails due to connection problems, try with
* another available connection.
*
* @author Mircea.Markus@jboss.com
* @since 4.1
*/

简而言之,我需要保持池中的连接,我不知道数据网格客户端HOT-ROD的属性是什么。下一步我想尝试设置infinispan.client.hotrod.tcp_keep_alive=true测试行为是否发生了变化,之后我会更新帖子。

考虑到重试操作和超时之间的合理权衡,我试图更改一些配置属性。

HOT-ROD客户端配置:

infinispan.client.hotrod.server_list=server1:11222;server2:11222;server3:11222;server4:11222
infinispan.client.hotrod.auth_username=app-user
infinispan.client.hotrod.auth_password=password
infinispan.client.hotrod.auth_realm=default
infinispan.client.hotrod.sasl_mechanism=SCRAM-SHA-512

infinispan.client.hotrod.socket_timeout=5000
infinispan.client.hotrod.connect_timeout=20000
infinispan.client.hotrod.max_retries=5
# Connection pool
infinispan.client.hotrod.connection_pool.max_active=100
infinispan.client.hotrod.connection_pool.exhausted_action=WAIT
infinispan.client.hotrod.connection_pool.max_wait=20000
infinispan.client.hotrod.connection_pool.min_idle=50
#default is 1800000
infinispan.client.hotrod.connection_pool.min_evictable_idle_time=600000
infinispan.client.hotrod.connection_pool.max_pending_requests=846
infinispan.client.hotrod.client_intelligence=HASH_DISTRIBUTION_AWARE
infinispan.client.hotrod.force_return_values=false
#default is false
infinispan.client.hotrod.tcp_keep_alive=true 

已经完成的更改是:

  • infinispan.client.hotrod.socket_timeout减少到5000ms
  • infinispan.client.hotrod.connection_pool.min_idle增加到50
  • infinispan.client.hotrod.connect_timeout减少到20000ms
  • infinispan.client.hotrod.max_retries将减少到5
  • infinispan.client.hotrod.connection_pool.max_active增加到100

在QA环境和日志应用程序中测试,我可以说HOT-ROD客户端在4次RetryOnFailureOperations后很少获得

java.net.SocketTimeoutException: GetOperation`timed out after 5000 ms

发生updateTopologyInfo操作客户端HOT-ROD端。这个HOT-ROD客户端策略似乎只是异步线程生成的日志在后台运行,以检查套接字是否仍然有效。

[2/23/22 9:06:12:923 CET] 000001ab HOTROD        W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0xa5345361, L:/10.0.20.160
:44021 - R:10.0.18.102/10.0.18.102:11222] due to transport error
java.net.SocketTimeoutException: GetOperation{MY-CACHE, key=[B0x4A4B636F6D2E6475636174692E77612E..[77], flags=1, connection=10.0.18.102/10.0.18.102:11222} timed out a
fter 5000 ms
at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:822)
[2/23/22 9:06:17:924 CET] 000001a5 HOTROD        W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0x54dacb9b, L:/10.0.20.160:42115 - R:10.0.18.97/10.0.18.97:11222] due to transport error
java.net.SocketTimeoutException: GetOperation{MY-CACHE, key=[B0x4A4B636F6D2E6475636174692E77612E..[77], flags=1, connection=10.0.18.97/10.0.18.97:11222} timed out after 5000 ms
at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:822)
[2/23/22 9:06:22:925 CET] 000001a5 HOTROD        W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0xe3e6fd98, L:/10.0.20.160:43629 - R:10.0.18.101/10.0.18.101:11222] due to transport error
java.net.SocketTimeoutException: GetOperation{MY-CACHE, key=[B0x4A4B636F6D2E6475636174692E77612E..[77], flags=1, connection=10.0.18.101/10.0.18.101:11222} timed out after 5000 ms
at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:822)
[2/23/22 9:06:27:926 CET] 000001ab HOTROD        W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0x52a4bd4a, L:/10.0.20.160:32912 - R:10.0.18.96/10.0.18.96:11222] due to transport error
java.net.SocketTimeoutException: GetOperation{MY-CACHE, key=[B0x4A4B636F6D2E6475636174692E77612E..[77], flags=1, connection=10.0.18.96/10.0.18.96:11222} timed out after 5000 ms
at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:822)
[2/23/22 9:06:27:927 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(server4:11222), adding to the pool.
[2/23/22 9:06:27:927 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(server2:11222), adding to the pool.
[2/23/22 9:06:27:928 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(server3:11222), adding to the pool.
[2/23/22 9:06:27:928 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(server1:11222), adding to the pool.
[2/23/22 9:06:27:928 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.101:11222), removing from the pool.
[2/23/22 9:06:27:928 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.102:11222), removing from the pool.
[2/23/22 9:06:27:928 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.96:11222), removing from the pool.
[2/23/22 9:06:27:929 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.97:11222), removing from the pool.
[2/23/22 9:06:27:929 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.101:11222), removing from the pool.
[2/23/22 9:06:27:929 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.102:11222), removing from the pool.
[2/23/22 9:06:27:929 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.96:11222), removing from the pool.
[2/23/22 9:06:27:929 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(10.0.18.97:11222), removing from the pool.
[2/23/22 9:06:28:059 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.protocol.Codec20 readNewTopologyAndHash ISPN004006: Server sent new topology view (id=108, age=0) containing 4 addresses: [10.0.18.101:11222, 10.0.18.102:11222, 10.0.18.96:11222, 10.0.18.97:11222]
[2/23/22 9:06:28:060 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(10.0.18.101:11222), adding to the pool.
[2/23/22 9:06:28:062 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(10.0.18.102:11222), adding to the pool.
[2/23/22 9:06:28:063 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(10.0.18.96:11222), adding to the pool.
[2/23/22 9:06:28:065 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory updateTopologyInfo ISPN004014: New server added(10.0.18.97:11222), adding to the pool.
[2/23/22 9:06:28:082 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(server4:11222), removing from the pool.
[2/23/22 9:06:28:083 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(server2:11222), removing from the pool.
[2/23/22 9:06:28:083 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(server3:11222), removing from the pool.
[2/23/22 9:06:28:083 CET] 000001ab HOTROD        I org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory closeChannelPools ISPN004016: Server not in cluster anymore(server1:11222), removing from the pool.
16576429:[2/23/22 9:06:33:056 CET] 000001ab HOTROD        W org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation handleException ISPN004098: Closing connection [id: 0x4299851e, L:/10.0.20.160:45567 ! R:server4/10.0.18.102:11222] due to transport error
16576703-                                 java.net.SocketTimeoutException: GetOperation{MY-CACHE, key=[B0x4A4B636F6D2E6475636174692E77612E..[77], flags=1, connection=server4/10.0.18.102:11222} timed out after 5000 ms
16576925-       at org.infinispan.client.hotrod.impl.operations.HotRodOperation.run(HotRodOperation.java:185)
16577020-       at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
16577090-       at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
16577173-       at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
16577268-       at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
16577371-       at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
16577442-       at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
16577539-       at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
16577617-       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
16577701-       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
16577785-       at java.lang.Thread.run(Thread.java:822)

注意

HOTROD字后的字符表示LOG级别

示例:

[2/22年2月23日9:06:28:083欧洲中部时间]000001ab HOTROD

  • I=信息
  • W=警告
  • D=调试
  • E=错误

最新更新