How to debug hanging hasKey call [DATAREDIS-859] #1434
Description
srm opened DATAREDIS-859 and commented
Initially posted on JEDIS github but was redirected here:
Using jedis 2.9.0 with Spring-Data-Redis 1.8.7
Calling redisTemplate.hasKey() leads to a stacktrace that keeps haning forever (now 9 hours) while working before flawlesly (~200k calls).
How can I continue to investigate the current situation. I have root access to the instance running the java process and the redis server.
Both are local to each other.
The java process and Redis are running on the same machine.
There's also a repeating thread/task in the java process that checks for a certain size for a key which works perfectly.
I've checked the redis server ith redis-cli and see multiple client connections.
127.0.0.1:6379> CLIENT LIST
id=27 addr=127.0.0.1:40616 fd=16 name= age=4 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=32768 obl=0 oll=0 omem=0 events=r cmd=client
id=20 addr=127.0.0.1:34673 fd=11 name= age=93477 idle=62746 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=set
id=21 addr=127.0.0.1:34701 fd=12 name= age=92450 idle=72813 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=rpush
id=22 addr=127.0.0.1:34795 fd=13 name= age=90386 idle=63831 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=hset
id=23 addr=127.0.0.1:35059 fd=14 name= age=84332 idle=64742 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=rpush
id=17 addr=127.0.0.1:34665 fd=8 name= age=93618 idle=93617 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=dbsize
id=24 addr=127.0.0.1:35811 fd=15 name= age=70817 idle=68771 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=rpush
id=18 addr=127.0.0.1:34667 fd=9 name= age=93617 idle=93617 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=dbsize
id=19 addr=127.0.0.1:34668 fd=10 name= age=93615 idle=1 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=0 omem=0 events=r cmd=llen
MEMORY DOCTOR reports no problems
MONITOR shows te repeating thread working fine
127.0.0.1:6379> monitor
OK
1534011319.682913 [0 127.0.0.1:34668] "LLEN" "ASSIGNMENT_QUEUE_KEY"
1534011321.683274 [0 127.0.0.1:34668] "LLEN" "ASSIGNMENT_QUEUE_KEY"
1534011323.683664 [0 127.0.0.1:34668] "LLEN" "ASSIGNMENT_QUEUE_KEY"
... every ~2 seconds
See Stacktrace of the call at the end.
The application creates 4 redistemplates in total on startup. See following snippets.
The connectionFactory:
JedisConnectionFactory jedisConnectionFactory = new JedisConnectionFactory();
The instantiations of the templates:
Class A:
redisTemplate = new RedisTemplate<>();
redisTemplate.setConnectionFactory(jedisConnectionFactory);
redisTemplate.setEnableTransactionSupport(true);
redisTemplate.afterPropertiesSet();
lastBlockIdTemplate = new RedisTemplate<>();
lastBlockIdTemplate.setConnectionFactory(jedisConnectionFactory);
lastBlockIdTemplate.setEnableTransactionSupport(true);
lastBlockIdTemplate.afterPropertiesSet();
Class B:
this.redisTemplate = new RedisTemplate<>();
this.redisTemplate.setConnectionFactory(connectionFactory);
this.redisTemplate.setKeySerializer(new StringRedisSerializer());
this.redisTemplate.setEnableTransactionSupport(true);
this.redisTemplate.afterPropertiesSet();
Class C:
this.redisTemplate = new RedisTemplate<>();
redisTemplate.setConnectionFactory(redisConnectionFactory);
redisTemplate.setKeySerializer(new StringRedisSerializer());
redisTemplate.setValueSerializer(new JdkSerializationRedisSerializer());
redisTemplate.setEnableTransactionSupport(true);
redisTemplate.afterPropertiesSet();
Running REDIS 4.0.8 on a Debian instance virtualized on KVM/libvirt.
Redis Server TOP values:
Prio: 20
Nice: 0
Virt: 1043120
Res: 737180
SHR: 1496
S: S
%Mem: 18.2
-
Expected behavior
- Call returns quickly
-
Actual behavior
- As described, the call seems to be stuck for ~9 hours
-
Redis / Jedis Configuration
- Redis: default config after "make"
- Jedis: default config via JedisConnectionFactory via spring data redis
- spring-data-redis: as mentioned, just a plain JedisConnectionFactory on a plain RedisTemplate
**
-
Jedis version: 2.9.0
-
Redis version: 4.0.8
-
spring-redis-data version: 1.8.7
-
Java version:
- java version "1.8.0_161"
- Java(TM) SE Runtime Environment (build 1.8.0_161-b12)
- Java HotSpot(TM) 64-Bit Server VM (build 25.161-b12, mixed mode)
Related thread-dump:
2018-08-11_09:19:18.45343 "pool-3-thread-5" #1989 prio=5 os_prio=0 tid=0x00007f860c7d9800 nid=0xb12 waiting on condition [0x00007f86248de000]
2018-08-11_09:19:18.45343 java.lang.Thread.State: WAITING (parking)
2018-08-11_09:19:18.45344 at sun.misc.Unsafe.park(Native Method)
2018-08-11_09:19:18.45345 - parking to wait for <0x00000007006e36d8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
2018-08-11_09:19:18.45345 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
2018-08-11_09:19:18.45346 at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
2018-08-11_09:19:18.45347 at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:583)
2018-08-11_09:19:18.45349 at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:442)
2018-08-11_09:19:18.45350 at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:363)
2018-08-11_09:19:18.45351 at redis.clients.util.Pool.getResource(Pool.java:49)
2018-08-11_09:19:18.45352 at redis.clients.jedis.JedisPool.getResource(JedisPool.java:226)
2018-08-11_09:19:18.45353 at redis.clients.jedis.JedisPool.getResource(JedisPool.java:16)
2018-08-11_09:19:18.45353 at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:194)
2018-08-11_09:19:18.45354 at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:348)
2018-08-11_09:19:18.45355 at org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:129)
2018-08-11_09:19:18.45355 at org.springframework.data.redis.core.RedisConnectionUtils.bindConnection(RedisConnectionUtils.java:67)
2018-08-11_09:19:18.45356 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:192)
2018-08-11_09:19:18.45357 at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:169)
2018-08-11_09:19:18.45359 at org.springframework.data.redis.core.RedisTemplate.hasKey(RedisTemplate.java:658)
Initial issue redis/jedis#1844 (comment)
No further details from DATAREDIS-859