Issue with threads being blocked.

[havenwang]

Hello,

I'm running into an issue where the RedisJobStore blocks for long periods of time (>1 minute) during execution of storeJobAndTrigger(...). It seems to be when we are acquiring the JedisLock.

I've created a small test that recreates the issue, and I've included the code below. Hopefully it should be pretty clear.

Test code:

public class TestHanging extends TestEnv {
    private static final Logger LOGGER = Logger.getLogger(TestJedisHanging.class);

    private static JedisPoolConfig config = new JedisPoolConfig();
    private static JedisPool pool = new JedisPool(config, "localhost", 6381, Protocol.DEFAULT_TIMEOUT);
    private static JedisLock lockPool = new JedisLock(pool.getResource(), "TestLock", 10 * 60 * 1000);

    @Test
    public void testSendScheduledMessagesBig() throws InterruptedException {

        TestHelper.threadTesting(5, () -> {
            for (int i = 0; i < 200; i++) {
                doSomething();
            }
        });
    }

    public void doSomething() throws InterruptedException {
        try (Jedis jedis = pool.getResource()) {
            lockPool.acquire();
            LOGGER.fatal("HI");
        } finally {
            LOGGER.fatal("BYE");
            lockPool.release();
        }
    }
}

Some log output:

2018-01-21 22:22:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:22:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:23:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:23:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:24:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:24:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:25:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:25:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:26:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:26:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:26:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:26:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:26:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:26:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:27:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:27:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:27:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:27:43 FATAL TestJedisHanging:35 - BYE
2018-01-21 22:28:43 FATAL TestJedisHanging:33 - HI
2018-01-21 22:28:43 FATAL TestJedisHanging:35 - BYE

In the test, I have 5 threads that run the simple function of acquiring the JedisLock, writing some log output, then releasing it.

I've observed that execution gets blocked for 1 minute intervals, before my lock/unlock function runs for a seemingly random number of times.

Do you have any idea why this might be happening?

[havenwang]

I'm using jedis version 2.9.0.