Spring cache + redis 项目偶发死锁异常浅析

转：https://blog.csdn.net/xiaofanl/article/details/77018085

非常感谢原作者的分享

问题描述：

在使用@Cacheable注解配置value名称之后，在读取或写入该value下任意key对应的值时，当前线程卡死直到超时。伴随着卡死线程的不断增加系统会抛出RedisConnectionFailureException。

org.springframework.data.redis.RedisConnectionFailureException | Cannot get Jedis connection; nested exception is redis.clients.jedis.exceptions.JedisConnectionException: Could not get a resource from the pool
看似这个问题是redis连接池满了导致的，也有很多文章提到使用Spring data redis时，使用事务的连接会出现连接不释放的问题。 
然而还有另一种情况也会导致上述情况的发生，即这个value名称对应的所有key都被锁死了，听起来很扯淡但是事情就是这个样子。

问题分析：

使用redis客户端登录打出monitor命令后，发现一连串的Exists命令在不断刷新

1502245422.108774 [0 10.10.197.15:33919] "EXISTS" "group_info_cache~lock"
我们的请求由于某种原因导致服务不间断的像redis服务器确认"group_info_cache~lock"这个key是否存在。那么这个~lock后缀的key是干啥用的呢。其实是spring cache默认作为锁存在的key，~lock前面的是我们在@Cacheable注解中配置的value名称。对同一个value下key的操作其实是用这个~lock后缀的key进行加锁的。一个针对该cache的完整操作通常伴随着四个步骤： 
1, Exists命令确认锁是否存在  

2, 如果锁不存在，使用Set命令设定锁

3,执行对于对应key的操作

4,del命令删除锁

然而如果由于某种原因使得第四步del命令没有执行。便会导致不一致性问题的发生，作为锁存在的~lock key无法被删除。后续项目中所有针对该value的缓存操作都会卡死在第一步。而且非常遗憾的是这个~lock后缀作为锁存在的key似乎是没有过期时间的。

说到这个问题产生的原因还要从redistemplate源码中的execute()方法说起。

public <T> T execute(RedisCallback<T> action, boolean exposeConnection, boolean pipeline) {
        Assert.isTrue(initialized, "template not initialized; call afterPropertiesSet() before using it");
        Assert.notNull(action, "Callback object must not be null");

        RedisConnectionFactory factory = getConnectionFactory();
        RedisConnection conn = null;
        try {

            if (enableTransactionSupport) {
                // only bind resources in case of potential transaction synchronization
                conn = RedisConnectionUtils.bindConnection(factory, enableTransactionSupport);
            } else {
                conn = RedisConnectionUtils.getConnection(factory);
            }

            boolean existingConnection = TransactionSynchronizationManager.hasResource(factory);

            RedisConnection connToUse = preProcessConnection(conn, existingConnection);

            boolean pipelineStatus = connToUse.isPipelined();
            if (pipeline && !pipelineStatus) {
                connToUse.openPipeline();
            }

            RedisConnection connToExpose = (exposeConnection ? connToUse : createRedisConnectionProxy(connToUse));
            T result = action.doInRedis(connToExpose);

            // close pipeline
            if (pipeline && !pipelineStatus) {
                connToUse.closePipeline();
            }

            // TODO: any other connection processing?
            return postProcessResult(result, connToUse, existingConnection);
        } finally {
            RedisConnectionUtils.releaseConnection(conn, factory);
        }
    }

可以看到整个过程中，所有的异常处理在finally中以释放连接为结束。看起来连接总能得到释放，然而真的是这样吗？

可以看到该方法中的核心部分action.doInRedis(connToExpose)通过回调执行针对redis不同的操作。在RedisCache中设定的默认回调是AbstractRedisCacheCallback类。这个方法中的doInRedis如下所示：

public T doInRedis(RedisConnection connection) throws DataAccessException {
            waitForLock(connection);
            return doInRedis(element, connection);
        }

可以看到首先等待连接锁释放，然后进行对应元素的redis操作。在waitForLock的方法中
protected boolean waitForLock(RedisConnection connection) {

            boolean retry;
            boolean foundLock = false;
            do {
                retry = false;
                if (connection.exists(cacheMetadata.getCacheLockKey())) {
                    foundLock = true;
                    try {
                        Thread.sleep(WAIT_FOR_LOCK_TIMEOUT);
                    } catch (InterruptedException ex) {
                        Thread.currentThread().interrupt();
                    }
                    retry = true;
                }
            } while (retry);

            return foundLock;
        }

这里cacheMetadata.getCacheLockKey()的返回值便是我们配置的cache名称加上~lock后缀，而这个connection.exists()方法其实就是像redis发送Exists命令确认该key存在。看到这里，大概我们就能理解为何锁死的时候，redis服务器会不断刷出Exists命令了。罪魁祸首就是这里的这个死循环。如果作为锁存在的~lock后缀key没有被删除，那么我们的线程将每隔300毫秒执行一次Exists方法。

那么导致锁死的原因是什么呢。 如果在后续doInRedis()方法中，没有进行适当的异常处理，会直接抛出异常进入redistemplate方法中的finally模块，并释放连接。然而连接释放了，用来加锁的key并没有删掉，这样便可能导致上述锁死的发生。

然而目前也还有一些没有搞明白的地方，在doInRedis()的所有重写方法中，只有RedisWriteThroughCallback中引用了unlock方法

public byte[] doInRedis(BinaryRedisCacheElement element, RedisConnection connection) throws DataAccessException {

            try {

                lock(connection);

                try {

                    byte[] value = connection.get(element.getKeyBytes());

                    if (value != null) {
                        return value;
                    }

                    if (!isClusterConnection(connection)) {

                        connection.watch(element.getKeyBytes());
                        connection.multi();
                    }

                    value = element.get();

                    if (value.length == 0) {
                        connection.del(element.getKeyBytes());
                    } else {
                        connection.set(element.getKeyBytes(), value);
                        processKeyExpiration(element, connection);
                        maintainKnownKeys(element, connection);
                    }

                    if (!isClusterConnection(connection)) {
                        connection.exec();
                    }

                    return value;
                } catch (RuntimeException e) {
                    if (!isClusterConnection(connection)) {
                        connection.discard();
                    }
                    throw e;
                }
            } finally {
                unlock(connection);
            }
        }
    };
然而这个方法在调用lock方法时，锁对应的key的value与我这次遇到的问题日志记录中的value并不一致。并不能确认确实有调用这个方法，然而别的doInRedis()的重写方法中又并没有出现异常的处理与unlock方法的调用。这里需要继续对源码进行研究。

问题解决：

直接手动删掉~lock后缀的key