Java程序中线程无故睡眠16分钟,然后继续执行逻辑。不知道什么问题?

问题描述

线上环境中代码无故停顿16分钟左右。就像执行了Thread.sleep(16min)一样。很多地方都出现过。并不固定一个方法。
之前怀疑是redis的问题。后来发现没有使用redis的地方也有这种情况。之前也发过一个提问。

问题出现的环境背景及自己尝试过哪些方法

一开始以为是redis的原因,然后修改过redis部分操作代码。修改过redis配置,然后没有效果。
又修改过tomcat配置如下:

<Service name="Catalina">       
   <Executor 
        name="tomcatThreadPool" 
            namePrefix="catalina-exec-"
                maxThreads="500" 
                    minSpareThreads="10"             maxSpareThreads="50" maxIdleTime="60000" 
                        prestartminSpareThreads = "true"
                            maxQueueSize = "100"
     />
    <Connector executor="tomcatThreadPool" port="8080" protocol="org.apache.coyote.http11.Http11Nio2Protocol"
               connectionTimeout="20000" maxConnections="1000" enableLookups="false" 
               acceptCount="100" maxPostSize="10485760" compression="on"
               disableUploadTimeout="true" acceptorThreadCount="2" 
               redirectPort="8443" URIEncoding="utf-8" />

使用线程池,依然没有效果。
最后修改JVM配置:

JAVA_OPTS="-server -Xms1024m -Xmx1024m -XX:PermSize=128M -XX:MaxPermSize=256m -XX:NewRatio=3"

依然没有效果。不知道问题出在哪。

相关代码

// 请把代码文本粘贴到下方(请勿用图片代替代码)

/**
 * API统一入口
 * 
 * @Description: TODO
 * @author lxlong
 * @Time:2017年11月10日 上午11:55:03
 * @version 1.0
 */
@Controller
@RequestMapping("/xxx")
public class UnifiedController {

    @RequestMapping(value = "/xxx", method = RequestMethod.POST, headers = "Accept=application/json", produces = "application/json;charset=utf-8")
    @ResponseBody
    public String unifiedEntrance(@RequestBody String param) {
        return UnifiedAPIUtil.procAPI(param);
    }
}
public class UnifiedAPIUtil {

    private static Logger log = Logger.getLogger(UnifiedAPIUtil.class);

    /**
     * api统一入口
     * 
     * @Description
     * @author lxlong
     * @param param
     * @return
     */
    public static String procAPI(String param) {
        Result result = new Result();
        RedisLock redisLock = new RedisLock();

        /** 获取请求数据 */
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes())
                .getRequest();
        String token = StringUtil.toString(request.getHeader("token"));//token
        String targetPar = StringUtil.toString(request.getHeader("target"));//类
        String methodPar = StringUtil.toString(request.getHeader("method"));//方法名

        //设置请求头实体
        Header header = new Header();
        header.setTarget(targetPar);
        header.setMethod(methodPar);

        try {
            /* 获取请求报文数据 */
            log.info(targetPar + "." + methodPar + ":请求参数=" + param);

            //获取方法和对象
            String key = header.getTarget() + "_" + header.getMethod();
            Method lyzMethod = serverMethods.get(key);
            if (lyzMethod == null) {
                throw new NoSuchMethodException();
            }
            java.lang.reflect.Method method = lyzMethod.getMethod();
            CommonControl ctrl = (CommonControl) lyzMethod.getTarget();
  
            //加锁
            if (!redisLock.lockKey(userId)) {
                throw new LockOccupiedException();
            }
            
            //执行逻辑
            method.invoke(ctrl, result, header, param); 
            
        } catch (Exception e) {
            log.error("系统异常", e);
            result.setCodeForFail(CodeEum.Code.ERROR);
            //兼容旧版本
            result.setReturnsResult(ReturnMsg.ERROR.key(), ReturnMsg.ERROR.value());
        } finally {
            //释放锁
            log.info(targetPar + "." + methodPar + ":准备释放资源锁");
            if (StringUtil.isNotEmpty(token)) {
                redisLock.unLock(token);
            }
        }
        log.info(targetPar + "." + methodPar + ":响应参数=" + result.getResult());
        return result.getResult();
    }
}

Controller;

public class ApiOrderControl implements CommonControl {
        @Resource
        private IOrderService orderService;
        
        public void createNewOrder(Result result, Header header, String jsonString) throws NotDataException, Exception {
            log.info("=====================提交订单接口=====================");
            //doSomeThing();
            Order order = new Order();
            order.set(xxx);
            order.set(xxx);
            order.set(xxx);
            order.set(xxx);
            orderService.save(order);        
        }
        
        public void recallOrder(Result result, Header header, String jsonString) throws Exception {
            log.info("=====================取消订单接口=====================");
            //doSomeThing()
            order.setStatus(0);
            orderService.update(order);    
        }
    }

Service

public class orderService implements IOrderService {

    @Reousece
    private IOrderDao orderDao;
    
    @Override
    @Transactional
    public void save(Order order) throws NotDataException, Exception {
        orderDao.save(order);
    }
    @Override
    @Transactional
    public void update(Order order) throws NotDataException, Exception {
        order.setUpdateTime(DateUtil.getTime());
        orderDao.update(order);
    }
}

你期待的结果是什么?实际看到的错误信息又是什么?

然后后台日志是这样的

[INFO] 2019-05-10 02:01:45,280 com.leyizhu.api.util.UnifiedAPIUtil - 请求头数据  >>>>> Header [token=083e19b0251c44458e9d729cf535bd86 target=apiOrderControl, method=createNewOrder]
[INFO] 2019-05-10 02:01:45,280 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.createNewOrder:请求参数={"aaaa":"aaaa"}
[INFO] 2019-05-10 02:01:45,294 com.leyizhu.plugin.RedisLockUtil.RedisLock - ---------------LOCK_PREFIX_083e19b0251c44458e9d729cf535bd86加锁成功-------------------
[INFO] 2019-05-10 02:01:45,294 com.leyizhu.api.control.order.ApiOrderControl - =====================提交订单接口=====================
[INFO] 2019-05-10 02:01:45,830 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.createNewOrder:准备释放资源锁
[INFO] 2019-05-10 02:17:49,001 com.leyizhu.plugin.RedisLockUtil.RedisLock - ---------------LOCK_PREFIX_083e19b0251c44458e9d729cf535bd86释放成功-------------------
[INFO] 2019-05-10 02:17:49,001 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.createNewOrder:响应参数={"code":"100","codemsg":"成功""data":{"createTime":"2019-05-10 02:01:45","orderNO":"04440300031905100567635","orderType":1}}

这里在 准备释放资源 和 成功释放资源之间相差了16分钟左右。资源锁是采用redis实现的。
然后还有一次

[INFO] 2019-05-10 02:02:55,924 com.leyizhu.api.util.UnifiedAPIUtil - 请求头数据  >>>>> Header [token=083e19b0251c44458e9d729cf535bd86, method=recallOrder, platform=3]
[INFO] 2019-05-10 02:02:55,924 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.recallOrder:请求参数={"orderNO":"04440300031905100567635","orderType":"1"}
[INFO] 2019-05-10 02:02:55,935 com.leyizhu.plugin.RedisLockUtil.RedisLock - ===================前一锁已超时========================
[INFO] 2019-05-10 02:02:55,937 com.leyizhu.plugin.RedisLockUtil.RedisLock - ---------------LOCK_PREFIX_083e19b0251c44458e9d729cf535bd86加锁成功-------------------
[INFO] 2019-05-10 02:02:55,937 com.leyizhu.api.control.order.ApiOrderControl - =====================取消订单接口=====================
[INFO] 2019-05-10 02:19:01,497 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.recallOrder:准备释放资源锁
[INFO] 2019-05-10 02:19:01,499 com.leyizhu.plugin.RedisLockUtil.RedisLock - ---------------LOCK_PREFIX_083e19b0251c44458e9d729cf535bd86已被其他线程获取/未获取到锁-------------------
[INFO] 2019-05-10 02:19:01,499 com.leyizhu.api.util.UnifiedAPIUtil - apiOrderControl.recallOrder:响应参数={"code":"100","codemsg":"成功","data":{}}

这一次是在 执行逻辑 和 准备释放资源的 时间上相差 16分钟左右

然后查看mysql的binlog发现 取消订单的时候当方法执行到orderService.update()方法里的时候时间确实是2019-05-10 02:02:55,但是update提交事务的时间是2019-05-10 02:19:01 这中间不知道是为什么。而且这也可以看出不是redis的问题。因为两次停顿发生的时间点不一样。取消订单时还未执行到 释放锁 的逻辑。
一开始我以为是redis卡住的提问地址:redis连接拥塞。我不知道这样说对不对?
请求大神解答。

阅读 3.8k
3 个回答
新手上路,请多包涵

怎么锁没有超时时间?

提供两种思路:

  • 自己写继承测试,用 MockMvc 模拟大量请求,找到触发问题的点,一旦找到触发点,问题就迎刃而解了;
  • 生成环境开放 DEBUG 日志(本身的 INFO 日志不足以看出问题)。

看看你RedisLock是如何实现的,你这日志打的完全就是释放锁的时候花了16分钟吧...你释放锁的逻辑是怎么写的呀?

撰写回答
你尚未登录,登录后可以
  • 和开发者交流问题的细节
  • 关注并接收问题和回答的更新提醒
  • 参与内容的编辑和改进,让解决方法与时俱进
推荐问题