记录一次@Cacheable导致死锁问题排查过程

记录一次@Cacheable导致死锁问题排查过程 情景再现

最近同事的一个项目在测试环境出来了一个奇怪的问题，说项目一登录就卡死，接口一直没响应，也不报错，正式环境也没有这个问题，感觉很奇怪，他找了很长时间找不出问题，让我帮忙排查一下是什么原因，排查了一上午的时间终于找到原因了，代码逻辑其实很简单，大致逻辑如下模拟代码：

    @Cacheable(cacheNames = {"user","user"},key = "#id",sync =true)
    public String getById(String id) {
        System.out.println("get from db");
        return "user:" + id;
    }

重要线索

他说只要把 @Cacheable去掉就不卡，加上就卡，这是一条非常重要的线索，肯定是这个导致的卡卡死，首先可以确定，不是数据库查询问题。

排查步骤

查看缓存有没有数据
我在想这肯定是走缓存了，那就打开redis 客户端看看有没有这个缓存，发现有一个user~lock这个Key 它的值为locked，看来是Redis线程死锁了，如果他看一下Redis数据库估计也就找到原因。

找到CacheAspectSupport
有个execute()方法，有个 if (contexts.isSynchronized())判断，如果设置了sync=true的话，设置Redis缓存时会加锁

找到死锁代码 RedisCache waitForLock()方法
这里就是个死循环，每隔300毫秒去Redis查询一下有没有 user~lock这个key,而且这个 key的有效期是永久的，所以就是卡在这里一直循环出不去了。

解决方法

redis中删除 lock这个Key 就OK了

问题出现的原因

在RedisWriteThroughCallback 的 doInRedis中会先lock一个，在 finally会unlock(connection);
我猜测应该是测试环境停用服务使用的是 kill -9 导致finally中的unlock方法没有执行， 而且这个key没有设置过期时间，所以就永久死循环了，如果不加sync =true 也不会加锁了。

	static class RedisWriteThroughCallback extends AbstractRedisCacheCallback {

		public RedisWriteThroughCallback(BinaryRedisCacheElement element, RedisCachemetadata metadata) {
			super(element, metadata);
		}

		@Override
		public byte[] doInRedis(BinaryRedisCacheElement element, RedisConnection connection) throws DataAccessException {
			try {
				lock(connection);
				try {
					byte[] value = connection.get(element.getKeyBytes());
					if (value != null) {
						return value;
					}
					.........
					return value;
				} catch (RuntimeException e) {
					if (!isClusterConnection(connection)) {
						connection.discard();
					}
					throw e;
				}
			} finally {
				unlock(connection);
			}
		}
	};