高并发下Transactional事务导致Lock4j锁失效的解决方案

Scroll Down

问题产生产生?

高并发下使用Lock4j来进行实现并发锁,在项目中使用EnableTransactionManagement来进行开启事务。在同一个方法上添加@Lock4j和@Transactional时候发现锁失效。

@Lock4j(keys = "#id")
@Transactional
@Override
public int testLock(String id) {
    Date date = new Date();
    int result = myMapper.updateTest(date, id);
    return result;
}

重写Lock4j中的一些类

因为lock4j中的日志打印不是太完整,所以我们重写下lock4j中的一些类打印出日志。

@Slf4j
@Component
public class RedisTemplateLockExecutor implements LockExecutor {

    private static final RedisScript<String> SCRIPT_LOCK = new DefaultRedisScript<>("return redis.call('set',KEYS[1],ARGV[1],'NX','PX',ARGV[2])", String.class);
    private static final RedisScript<String> SCRIPT_UNLOCK = new DefaultRedisScript<>("if redis.call('get',KEYS[1]) == ARGV[1] then return tostring(redis.call('del', KEYS[1])==1) else return 'false' end", String.class);
    private static final String LOCK_SUCCESS = "OK";
    private static final String PROCESS_ID = LockUtil.getLocalMAC() + LockUtil.getJvmPid();

    @Autowired
    private RedisTemplate redisTemplate;

    @Override
    public LockInfo tryLock(String key, long expire, long timeout) throws Exception {
        // 打印日志
        log.info("get lock:{}", key);
        Assert.isTrue(timeout > 0, "tryTimeout must more than 0");
        long start = System.currentTimeMillis();
        int tryCount = 0;
        String lockId = PROCESS_ID + Thread.currentThread().getId();
        while (System.currentTimeMillis() - start < timeout) {
            Object lockResult = redisTemplate.execute(SCRIPT_LOCK,
                    redisTemplate.getStringSerializer(),
                    redisTemplate.getStringSerializer(),
                    Collections.singletonList(key),
                    lockId, String.valueOf(expire));
            tryCount++;
            if (LOCK_SUCCESS.equals(lockResult)) {
                return new LockInfo(lockId, key, expire, timeout, tryCount);
            }
            Thread.sleep(50);
        }
        log.info("lock failed, try {} times", tryCount);
        return null;
    }


    @Override
    public boolean releaseLock(LockInfo lockInfo) {
        // 解锁
        log.info("release lock:{}", JSONObject.toJSONString(lockInfo));
        Object releaseResult = redisTemplate.execute(SCRIPT_UNLOCK,
                redisTemplate.getStringSerializer(),
                redisTemplate.getStringSerializer(),
                Collections.singletonList(lockInfo.getKey()),
                lockInfo.getLockId());
        return Boolean.valueOf(releaseResult.toString());
    }

}

配置日志打印

logging:
  level:
    org.mybatis.spring: debug
    com.wsy.pro.mapper: debug

执行产生日志分析

2020-04-10 11:44:11.763  INFO 10636 --- [nio-8080-exec-2] c.w.p.config.RedisTemplateLockExecutor   : get lock:com.wsy.pro.anno.MyServiceImpl.testLock1
2020-04-10 11:44:12.011  INFO 10636 --- [nio-8080-exec-2] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-04-10 11:44:12.013  INFO 10636 --- [nio-8080-exec-2] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-04-10 11:44:12.369 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Creating a new SqlSession
2020-04-10 11:44:12.377 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@72fd8177]
2020-04-10 11:44:12.394 DEBUG 10636 --- [nio-8080-exec-2] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@834444900 wrapping com.mysql.cj.jdbc.ConnectionImpl@79c083ab] will be managed by Spring
2020-04-10 11:44:12.420 DEBUG 10636 --- [nio-8080-exec-2] com.wsy.pro.mapper.MyMapper.updateTest   : ==>  Preparing: update test_t set update_time = ? where id = 1 
2020-04-10 11:44:12.463 DEBUG 10636 --- [nio-8080-exec-2] com.wsy.pro.mapper.MyMapper.updateTest   : ==> Parameters: 2020-04-10 11:44:12.361(Timestamp)
2020-04-10 11:44:12.472 DEBUG 10636 --- [nio-8080-exec-2] com.wsy.pro.mapper.MyMapper.updateTest   : <==    Updates: 1
2020-04-10 11:44:12.473 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@72fd8177]
2020-04-10 11:44:12.573  INFO 10636 --- [nio-8080-exec-2] c.w.p.config.RedisTemplateLockExecutor   : release lock:{"expire":30000,"key":"com.wsy.pro.anno.MyServiceImpl.testLock1","lockId":"1063641","tryCount":1,"tryTimeout":3000}
2020-04-10 11:44:12.582 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@72fd8177]
2020-04-10 11:44:12.582 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@72fd8177]
2020-04-10 11:44:12.583 DEBUG 10636 --- [nio-8080-exec-2] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@72fd8177]

分析上面日志发现获取锁在事务之前执行,但是发现了先释放了锁,后提交了事务。这时候另外一个线程进来时,直接获取了锁,这时候事务还没有提交就会造成数据的错误。

解决方案

发现了问题,是因为锁在事务提交前就释放了。lock4j和transactional都是通过 AOP 来实现的,他们使用同一个切面。默认情况下的Order都是Integer.MAX_VALUE,排序的话就会按照类加载顺序进行排序,那么Lock4j就有可能在Transactional的后面。所以可能就会造成先释放锁,后提交事务。AOP可以看做一个同心圆,那么order越小的也就最先执行,最先执行的也就可以看做是最外层的圆,释放的时候也就是最后释放的。

修改排序

@Bean
public LockAnnotationAdvisor lockAnnotationAdvisor(LockInterceptor lockInterceptor) {
    LockAnnotationAdvisor lockAnnotationAdvisor = new LockAnnotationAdvisor(lockInterceptor);
    lockAnnotationAdvisor.setOrder(Integer.MAX_VALUE - 10);
    return lockAnnotationAdvisor;
}

执行结果验证

2020-04-10 12:02:09.426  INFO 10725 --- [nio-8080-exec-1] c.w.p.config.RedisTemplateLockExecutor   : get lock:com.wsy.pro.anno.MyServiceImpl.testLock1
2020-04-10 12:02:09.782  INFO 10725 --- [nio-8080-exec-1] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2020-04-10 12:02:09.785  INFO 10725 --- [nio-8080-exec-1] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2020-04-10 12:02:10.451 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Creating a new SqlSession
2020-04-10 12:02:10.457 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@61690258]
2020-04-10 12:02:10.472 DEBUG 10725 --- [nio-8080-exec-1] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@260553929 wrapping com.mysql.cj.jdbc.ConnectionImpl@252cb465] will be managed by Spring
2020-04-10 12:02:10.497 DEBUG 10725 --- [nio-8080-exec-1] com.wsy.pro.mapper.MyMapper.updateTest   : ==>  Preparing: update test_t set update_time = ? where id = 1 
2020-04-10 12:02:10.549 DEBUG 10725 --- [nio-8080-exec-1] com.wsy.pro.mapper.MyMapper.updateTest   : ==> Parameters: 2020-04-10 12:02:10.443(Timestamp)
2020-04-10 12:02:10.554 DEBUG 10725 --- [nio-8080-exec-1] com.wsy.pro.mapper.MyMapper.updateTest   : <==    Updates: 1
2020-04-10 12:02:10.555 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@61690258]
2020-04-10 12:02:10.555 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@61690258]
2020-04-10 12:02:10.556 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@61690258]
2020-04-10 12:02:10.556 DEBUG 10725 --- [nio-8080-exec-1] org.mybatis.spring.SqlSessionUtils       : Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@61690258]
2020-04-10 12:02:10.833  INFO 10725 --- [nio-8080-exec-1] c.w.p.config.RedisTemplateLockExecutor   : release lock:{"expire":30000,"key":"com.wsy.pro.anno.MyServiceImpl.testLock1","lockId":"1072551","tryCount":1,"tryTimeout":3000}

分析日志发现没有问题大工告成!

图形分析

image