破案现场:记一次压测异常排查--Redisson锁失效的场景

Posted Java小海.

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了破案现场:记一次压测异常排查--Redisson锁失效的场景相关的知识,希望对你有一定的参考价值。

异常现场回顾

7月7日对小驴班级推送视频任务功能进行压测。 压测过程中发现有一部分接口请求失败。 小驴端上报推送失败异常如下:

这个异常日志是小驴端收到的。 异常内容是网校网关返回的异常页面, 如何看出来是网校网关的呢? 看回到首页前面有一个url,这个跳转到的url正是网校的主页

班级任务推送主要是to B的,老师们使用, 并发量并不大,10并发,25次, 一共250个任务。 并发量并不大,到底为什么异常,怎么出的异常呢?

首先,我们来看ELK日志监控。

先来查询网关日志,搜索对内网关,查询条件是:对内网关+请求路径,查看并发情况。

我们看到一共并发请求了207次, 目测都是成功的。 但预计是250次,实际只有207次呢?再来查询异常情况。 如何查询呢? 查询条件:

  1. project.key is cloudlearn-gateway-inner
  2. response is not 200

发现问题了,这里有21条请求500的日志。

第二步:进入网关查询异常原因。

根据在elk中失败请求的traceId查询网关日志,燃鹅并没有什么收获。 于是带着这个traceId去业务服务器查找

第三步: 查找业务服务器日志。

业务服务器抛出异常, 获取锁失败。

异常原因分析及解决

回想昨天小驴端异常数据,我们看到有好几个小驴id都抛了异常。这里加了一个redisson锁,这个锁的key是:paperId+lvTaskId+originType. 案例来说,压测的lvTaskId应该都不一样才对呀。 怎么会出现锁住的情况呢。

线上日志不全面,为了能够模拟这个问题,在本地启动jemeter进行压测。测试范围lvTaskId从100000-999999随机生成20个。id重复的概率很小了,很快有效果了

20个请求,有两个请求失败了。复现了压测现场出现的问题。 这就好办了,分析原因:

第一步: 查看本地日志,发现异常日志

和线上压测所报异常一样。

第二步:确定随机生成的lvTaskId是否有重复。

    因为Redisson锁的key不允许重复, 如果重复将进行等待, 等待超时,就会抛获取锁失败。

    排查结果: 没有重复的lvTaskId
复制代码

第三步:排查Redisson源码,在异常处打断点,逐步排查。

@Around("controllerAspect(lock)")
public Object aroundAdvice(ProceedingJoinPoint proceedingJoinPoint, Lock lock) throws Throwable 
    String[] keys = lock.keys();
    if (keys.length == 0) 
        throw new RuntimeException("keys不能为空");
    
    String[] parameterNames = new LocalVariableTableParameterNameDiscoverer().getParameterNames(((MethodSignature) proceedingJoinPoint.getSignature()).getMethod());
    Object[] args = proceedingJoinPoint.getArgs();

    long attemptTimeout = lock.attemptTimeout();
    if (attemptTimeout == 0) 
        attemptTimeout = redissonProperties.getAttemptTimeout();
    
    long lockWatchdogTimeout = lock.lockWatchdogTimeout();
    if (lockWatchdogTimeout == 0) 
        lockWatchdogTimeout = redissonProperties.getLockWatchdogTimeout();
    
    LockModel lockModel = lock.lockModel();
    if (lockModel.equals(LockModel.AUTO)) 
        LockModel lockModel1 = redissonProperties.getLockModel();
        if (lockModel1 != null) 
            lockModel = lockModel1;
         else if (keys.length > 1) 
            lockModel = LockModel.MULTIPLE;
         else 
            lockModel = LockModel.REENTRANT;
        
    
    if (!lockModel.equals(LockModel.MULTIPLE) && !lockModel.equals(LockModel.REDLOCK) && keys.length > 1) 
        throw new RuntimeException("参数有多个,锁模式为->" + lockModel.name() + ".无法锁定");
    
    log.info("锁模式->,等待锁定时间->秒.锁定最长时间->秒",lockModel.name(),attemptTimeout/1000,lockWatchdogTimeout/1000);
    boolean res = false;
    RLock rLock = null;
    //一直等待加锁.
    switch (lockModel) 
        case FAIR:
            rLock = redissonClient.getFairLock(getVauleBySpel(keys[0],parameterNames,args));
            break;
        case REDLOCK:
            RLock[] locks=new RLock[keys.length];
            int index=0;
            for (String key : keys) 
                locks[index++]=redissonClient.getLock(getVauleBySpel(key,parameterNames,args));
            
            rLock = new RedissonRedLock(locks);
            break;
        case MULTIPLE:
            RLock[] locks1=new RLock[keys.length];
            int index1=0;
            for (String key : keys) 
                locks1[index1++]=redissonClient.getLock(getVauleBySpel(key,parameterNames,args));
            
            rLock = new RedissonMultiLock(locks1);
            break;
        case REENTRANT:
            rLock= redissonClient.getLock(getVauleBySpel(keys[0],parameterNames,args));
            break;
        case READ:
            RReadWriteLock rwlock = redissonClient.getReadWriteLock(getVauleBySpel(keys[0],parameterNames,args));
            rLock = rwlock.readLock();
            break;
        case WRITE:
            RReadWriteLock rwlock1 = redissonClient.getReadWriteLock(getVauleBySpel(keys[0],parameterNames,args));
            rLock = rwlock1.writeLock();
            break;
    

    //执行aop
    if(rLock!=null) 
        try 
            if (attemptTimeout == -1) 
                res = true;
                //一直等待加锁
                rLock.lock(lockWatchdogTimeout, TimeUnit.MILLISECONDS);
             else 
                res = rLock.tryLock(attemptTimeout, lockWatchdogTimeout, TimeUnit.MILLISECONDS);
            
            if (res) 
                Object obj = proceedingJoinPoint.proceed();
                return obj;
            else
                throw new LockException("获取锁失败");
            
         finally 
           if (res) 
              rLock.unlock();
           
        
    
    throw new LockException("获取锁失败");

复制代码

异常就出在这段代码里,于是仔细阅读这段代码。如何生成key,如何上锁,如何重试。 突然,注意到解析key的代码段

public String getVauleBySpel(String key, String[] parameterNames, Object[] values) 

    if(!key.startsWith("#"))
        return key;
    
    //spel解析器
    ExpressionParser parser = new SpelExpressionParser();
    //spel上下文
    EvaluationContext context = new StandardEvaluationContext();
    for (int i = 0; i < parameterNames.length; i++) 
        context.setVariable(parameterNames[i], values[i]);
    
    Expression expression = parser.parseExpression(key);
    Object value = expression.getValue(context);
    log.info("key=,value=",key,value);
    if(value!=null)
        return value.toString();
    
    return "";

复制代码

第一句话:if(!key.startsWith("#"))return key; 如果redisson的key不是以#开头,那么将不对key的参数进行解析。问题就在这里了。

通常,我们在定义key的时候,会在变量前面加一个常量。可以方便日志排查。如下图:

也正是这个问题,导致了所有并发请求始终都是一把锁。最后出现等待超时的问题。

第四步:修改锁,将常量放在后面

再次压测,结果正常。

总结

redisson锁在设置key的时候,如果加常量, 切忌不可加载前面, 要加在后面, 要是修改源码的话那就另说了。

其实,在redisson-spring-boot-starter文档中也有提说可以使用常量。 一方面这个提示是在注释中写的,另一方面没有明确说常量应该放在那里。对于常用redis且习惯将常量放在前面的我们来说,这确实是一个坑。

至此,这次异常排查结束,记录这次排查过程,希望后面大家再使用Redisson的时候,能够避免趟类似的坑。


作者:summerSunShine
链接:https://juejin.cn/post/7061152891528019981
 

以上是关于破案现场:记一次压测异常排查--Redisson锁失效的场景的主要内容,如果未能解决你的问题,请参考以下文章

记一次Redisson连接异常引起的OOM

记一次Redisson连接异常引起的OOM

记一次中间件导致的慢SQL排查过程

解Bug之路-记一次中间件导致的慢SQL排查过程

记一次OOM排查解决

TPS低,CPU高--记一次storm压测问题排查过程