tx-lcn icon indicating copy to clipboard operation
tx-lcn copied to clipboard
verified publisher icon codingapi

浏览器请求调用方服务超时后，数据死锁问题

Open longxiaonan opened this issue 5 years ago • 5 comments

问题描述：

依照下面的代码进行描述，我在调用方服务中设置Thread.sleep(10000)来模拟浏览器调用超时的情况。浏览器请求controller，访问调用方服务的startFlow方法，第一次请求log如下：

18:02:09.730 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.selectDetail - ==>  Preparing: select dtl.*, ifnull(mb.weight, 0) weight FROM pr_purchase_plan_apply_order_detail dtl left join b_material_basic mb on mb.id = dtl.material_id and mb.tenant_id = ? where dtl.tenant_id = ? and dtl.bus_type = ? and dtl.del_flag = 0 and dtl.order_id in ( ? ) 
18:02:09.732 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.selectDetail - ==> Parameters: b45551e5f8de4efc800e3677ef68cb39(String), b45551e5f8de4efc800e3677ef68cb39(String), 0(String), 768dec70f065d51d23476c4ddea50ad3(String)
18:02:09.740 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.selectDetail - <==      Total: 1
18:02:09.752 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.updateById - ==>  Preparing: UPDATE pr_purchase_plan_order SET approval_status=? WHERE id=? 
18:02:09.753 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.updateById - ==> Parameters: 1(Short), 768dec70f065d51d23476c4ddea50ad3(String)
18:02:09.756 DEBUG 19228 --- [nio-8120-exec-8] c.z.l.w.p.d.P.updateById - <==    Updates: 1
18:02:13.719 ERROR 19228 --- [nio-8120-exec-8] c.z.c.e.GlobalExceptionHandler - java.lang.NullPointerException: null
	at com.codingapi.txlcn.tc.core.checking.DefaultDTXExceptionHandler.handleNotifyGroupBusinessException(DefaultDTXExceptionHandler.java:93)
	at com.codingapi.txlcn.tc.core.template.TransactionControlTemplate.notifyGroup(TransactionControlTemplate.java:156)
	at com.codingapi.txlcn.tc.core.transaction.lcn.control.LcnStartingTransaction.postBusinessCode(LcnStartingTransaction.java:69)
	at com.codingapi.txlcn.tc.core.DTXServiceExecutor.transactionRunning(DTXServiceExecutor.java:108)
	at com.codingapi.txlcn.tc.aspect.weave.DTXLogicWeaver.runTransaction(DTXLogicWeaver.java:96)
	at com.codingapi.txlcn.tc.aspect.TransactionAspect.transactionRunning(TransactionAspect.java:83)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
	at com.zhirui.lmwy.warehouse.purchase_plan_order.service.impl.PurchasePlanOrderServiceImpl$$EnhancerBySpringCGLIB$$f9197350.startFlow(<generated>)
	at com.zhirui.lmwy.warehouse.purchase_plan_order.controller.PurchasePlanOrderController.flowStart(PurchasePlanOrderController.java:54)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:879)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)

浏览器再次请求，log如下：

18:12:23.324 DEBUG 19228 --- [io-8120-exec-10] c.z.l.w.p.d.P.selectDetail - ==>  Preparing: select dtl.*, ifnull(mb.weight, 0) weight FROM pr_purchase_plan_apply_order_detail dtl left join b_material_basic mb on mb.id = dtl.material_id and mb.tenant_id = ? where dtl.tenant_id = ? and dtl.bus_type = ? and dtl.del_flag = 0 and dtl.order_id in ( ? ) 
18:12:23.325 DEBUG 19228 --- [io-8120-exec-10] c.z.l.w.p.d.P.selectDetail - ==> Parameters: b45551e5f8de4efc800e3677ef68cb39(String), b45551e5f8de4efc800e3677ef68cb39(String), 0(String), 768dec70f065d51d23476c4ddea50ad3(String)
18:12:23.331 DEBUG 19228 --- [io-8120-exec-10] c.z.l.w.p.d.P.selectDetail - <==      Total: 1
18:12:23.339 DEBUG 19228 --- [io-8120-exec-10] c.z.l.w.p.d.P.updateById - ==>  Preparing: UPDATE pr_purchase_plan_order SET approval_status=? WHERE id=? 
18:12:23.341 DEBUG 19228 --- [io-8120-exec-10] c.z.l.w.p.d.P.updateById - ==> Parameters: 1(Short), 768dec70f065d51d23476c4ddea50ad3(String)
18:12:26.299 INFO  19228 --- [.12.11.240_8848] c.a.n.c.config.impl.ClientWorker - get changedGroupKeys:[]
18:12:56.413 INFO  19228 --- [.12.11.240_8848] c.a.n.c.config.impl.ClientWorker - get changedGroupKeys:[]
18:13:14.372 ERROR 19228 --- [io-8120-exec-10] c.c.txlcn.tc.core.DTXServiceExecutor - business code error @group(c7a477c4d48537)
18:13:14.376 ERROR 19228 --- [io-8120-exec-10] c.z.c.e.GlobalExceptionHandler - java.lang.NullPointerException: null
	at com.codingapi.txlcn.tc.core.checking.DefaultDTXExceptionHandler.handleNotifyGroupBusinessException(DefaultDTXExceptionHandler.java:93)
	at com.codingapi.txlcn.tc.core.template.TransactionControlTemplate.notifyGroup(TransactionControlTemplate.java:156)
	at com.codingapi.txlcn.tc.core.transaction.lcn.control.LcnStartingTransaction.postBusinessCode(LcnStartingTransaction.java:69)
	at com.codingapi.txlcn.tc.core.DTXServiceExecutor.transactionRunning(DTXServiceExecutor.java:108)
	at com.codingapi.txlcn.tc.aspect.weave.DTXLogicWeaver.runTransaction(DTXLogicWeaver.java:96)
	at com.codingapi.txlcn.tc.aspect.TransactionAspect.transactionRunning(TransactionAspect.java:83)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
	at com.zhirui.lmwy.warehouse.purchase_plan_order.service.impl.PurchasePlanOrderServiceImpl$$EnhancerBySpringCGLIB$$f9197350.startFlow(<generated>)
	at com.zhirui.lmwy.warehouse.purchase_plan_order.controller.PurchasePlanOrderController.flowStart(PurchasePlanOrderController.java:54)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:879)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)

debug查看到是卡在mapper.updateById(order);这里，在mysql执行SELECT * FROM INFORMATION_SCHEMA.INNODB_TRX;可以看到这个的update语句出现了lock wait。等大概20秒左右，lock wait消失，页面请求失败。后面页面每次请求都是这个死锁的情况。

调用方代码：

    @Transactional(rollbackFor = Exception.class)
    @Override
    @TxTransaction
    public com.zhirui.core.model.result.ResultModel startFlow(String id) {
        try {
            Thread.sleep(10000);
        } catch (Exception e) {
            e.printStackTrace();
        }
        List<PurchasePlanOrderVO> list = listByAll(searchVO);
        // 修改单据状态为审核中
        PurchasePlanOrder order = new PurchasePlanOrder();
        order.setId(id);
        order.setApprovalStatus((short) 1);
        mapper.updateById(order);
    }

    @Override
    @Transactional(propagation = Propagation.NOT_SUPPORTED)
    public List<PurchasePlanOrderVO> listByAll(PurchasePlanOrderSearchVO searchVO) {
        searchVO.setTenantId(UserHelper.getTenantId());
        List<PurchasePlanOrderVO> list = mapper.listByAll(searchVO);
        return list;
}

被调用方代码：

    @Override
    @TxTransaction
    @Transactional(rollbackFor = Exception.class)
    public FlowInstanceDTO startProcess(Map map, String tenantId) throws Exception {
        // 1.构造业务数据
        // 获取当前用户
        TUser user = UserHelper.getSecUser();
        FlowInstance flowInstance = generateFlowInstance(map, user);

        // 2.查询流程定义
        ProcessDefinition processDefinition = repositoryService.createProcessDefinitionQuery()
                .processDefinitionKey(flowInstance.getProcessKey())
                .latestVersion().singleResult();
        // 省略...
    }

longxiaonan avatar Oct 13 '20 10:10 longxiaonan

@1991wangliang 作者大大帮忙看看，用在生产了，项目在上线了，比较急：0

longxiaonan avatar Oct 13 '20 10:10 longxiaonan

好像暂时没有更好的方案了，只能把超时时间改长一点 修改tm配置:

# 分布式事务执行总时间(ms). 默认为36000
tx-lcn.manager.dtx-time=60000

https://github.com/codingapi/tx-lcn/issues/353

chelsen avatar Jan 11 '21 10:01 chelsen

@longxiaonan 哥们 你好 请问你的问题解决了吗 我们生产也出现和你一样的问题，求解

PowellZhang avatar Jan 14 '21 02:01 PowellZhang

@longxiaonan 哥们 你好 请问你的问题解决了吗 我们生产也出现和你一样的问题，求解

不好意思，没关注到消息，后面我们用的seata了

longxiaonan avatar Dec 09 '22 12:12 longxiaonan

您好，您的来信我已收到！谢谢！ Best  Wishes!                                 ——孔祥亮

ElevenKong avatar Dec 09 '22 12:12 ElevenKong