Concurrency problems and analysis of multithreading in project

Here is a brief description of the problem,

Scenario: another thread is created in one thread to handle part of the business,

The main thread performs a new operation on the database. After the operation, it starts a new thread to query the inserted data, and finds that the data has no query.

Let's go straight to the code:

@Service
@Transactional
@Slf4j
public class RPatientService extends BaseService<RPatient, RPatientExample> {

    @Autowired
    private SequenceIdGenerator sequenceIdGenerator;

    @Autowired
    private WeChatMessageService weChatMessageService;

    @Autowired
    private RPatientMapper rPatientMapper;

    @Autowired
    private RReportIllnessService rReportIllnessService;
    @Autowired
    private ImSessionUserService imSessionUserService;

    @Autowired
    private RDoctorService rDoctorService;

    
    public void registerPS(String openId, String doctorId, byte status) {
        //Query users by openId
        synchronized (openId.intern()) {
            RUser rUser = rUserService.getRUserByOpenId(openId);
            RPatient rPatient = null;
            if (rUser == null) {
                //User does not exist insert user
                rUser = rUserService.createUserByOpenIdAndPS(openId, Constant.RUSER_TYPE_0_PATIENT, status);
                //New patients
                rPatient = initPatient(rUser);
                log.info("[RPatientService]:new patient join:{}", JsonUtil.toJson(rUser));
            } else if (rUser.getType() == Constant.RUSER_TYPE_1_DOCTOR) {
                //Doctor scan doctor QR code, do not process
                return;
            }

            if (rPatient == null) {
                rPatient = this.getPatientByUserId(rUser.getId());
                if(rPatient == null){
                    log.error("[RPatientService]: patient not exist:{}", JsonUtil.toJson(rUser));
                    return ;
                }
            }

            Long rDoctorId = null;
            if (!StringUtils.isEmpty(doctorId)) {
                //Check in associated doctors and patients to generate report
                rDoctorId = Long.valueOf(doctorId);
                RDoctor rDoctor = rDoctorService.getDoctorById(rDoctorId);
                if(rDoctor == null){
                    log.error("[RPatientService]: doctor not exist:doctorId:{}", doctorId);
                    return;
                }
                rReportService.report(rDoctorId, rPatient.getId());
            }
            eventBus.post(new PatientEvent(rUser.getId(), rDoctorId));
            //new
            //this.registerEvent(new PatientEvent(rUser.getId(), rDoctorId));
        }
    }

    //EventBus execution
    @Subscribe
    @AllowConcurrentEvents
    public void registerEvent(PatientEvent patientEvent) {
        log.info("[PatientEvent]:{}", JsonUtil.toJson(patientEvent));
        Long rUserId = patientEvent.getrUserId();
        if (rUserId == null) {
            return;
        }
        RUser rUser = rUserService.selectByPrimaryKey(rUserId);
        RPatient rPatient = this.getPatientByUserId(rUserId);
//        RReport rReport = rReportService.getByPatientId(rPatient.getId());
        if (StringUtils.isEmpty(rPatient.getPhone())) {
            //Prompt user for authentication
            weChatMessageService.sendToIdentityVerificationKFMsgForPatient(rUser.getVxopenid());
        } else if (patientEvent.getrDoctorId() != null) {

            //Create session
            rReportService.createNewSession(rPatient.getId());

            //Associated doctor, prompt to select disease
            weChatMessageService.sendToChoiceIllnessKFMsgForPatient(rUser.getVxopenid(), patientEvent.getrDoctorId());

        }
    }



}

 

Code of new operation:

@Service
@Transactional
@Slf4j
public class RReportService extends BaseService<RReport, RReportExample> {

    @Autowired
    private SequenceIdGenerator sequenceIdGenerator;
    @Autowired
    private RReportMapper rReportMapper;

    @Autowired
    private RPatientService patientService;

    @Autowired
    private ImSessionService imSessionService;

    public RReport report(Long doctorId, Long patientId) {
        RReport rReport = getByDoctorIdPatientId(doctorId, patientId);
        if (rReport == null) {
            rReport = initRReport(doctorId, patientId);
            log.info("new report generate:{}", JsonUtil.toJson(rReport));
        }
        return rReport;
    }

    //insert data
    private RReport initRReport(Long doctorId, Long patientId) {
        RReport rReport = new RReport();
        rReport.setRdoctorid(doctorId);
        rReport.setRpatientid(patientId);
        rReport.setCreatetime(new Date());
        insertOrUpdate(rReport);
        return rReport;
    }

    
    //Code for new transaction execution of EventBus
    public void createNewSession(Long patientId) {
        RPatient rPatient = patientService.selectByPrimaryKey(patientId);
        if (StringUtils.isEmpty(rPatient.getPhone())) {
            log.info("Patients do not improve their personal information, so they need to improve their personal information first!");
            return;//Incomplete information processing
        }
        RReportExample rReportExample = new RReportExample();
        rReportExample.createCriteria().andRpatientidEqualTo(patientId).andImsessionidIsNull();
        List<RReport> rReportList = this.selectByExample(rReportExample);
        log.info("Query hidden danger report relationship." + "Quantity can only have one:" + rReportList.size() + "Record information=" + rReportList.toString());
        if (rReportList != null && rReportList.size() != 0) {
            for (RReport rReport : rReportList) {
                Long doctorId = rReport.getRdoctorid();
                //Create session
                ImSession imSession = imSessionService.createNewSession(doctorId, patientId);
                rReport.setImsessionid(imSession.getId());
                this.insertOrUpdate(rReport);//Update session ID
            }
        }
        ImSessionExample imSessionExample = new ImSessionExample();
        imSessionExample.createCriteria().andCreateuseridEqualTo(patientId).andSessiontypeEqualTo((byte) 2);
        ImSession a = imSessionService.selectOneByExample(imSessionExample);
        if (a == null) {
            //Create customer service
            imSessionService.createNewSession2(424987751667077198L, patientId);
        }
    }

}

 

 

Let's take a look at my analysis server and make a log

############A transaction 35ea154e http-nio-8081-exec-10 thread number is created here
2020-01-11 11:13:47.834 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Creating new transaction with name [com.framework.code.service.report.RPatientService.registerPS]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2020-01-11 11:13:47.836 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]] for JDBC transaction
########Switch JDBC transaction and give it to Spring for management
2020-01-11 11:13:47.837 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Switching JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]] to manual commit
############Participate in the current transaction 35ea154e
2020-01-11 11:13:47.837 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Participating in existing transaction
2020-01-11 11:13:47.838 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RUserMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]
#######Querying users through openid
2020-01-11 11:13:47.838 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RUserMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, VxHeadUrl_, VxNickName_, VxSex_, VxOpenid_, VxProvince_, VxCity_, VxCountry_, Type_, PromotionSource_ from r_user WHERE ( VxOpenid_ = ? ) 
2020-01-11 11:13:47.839 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RUserMapper.selectByExample | ==> Parameters: oMGuv5uRcp03ycIgyjclwpZfr1Eg(String)
##########Use current transaction 35ea154e
2020-01-11 11:13:47.842 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]
#######Query patient information according to user Id
2020-01-11 11:13:47.842 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, RUserId_, RegisterTime_, Name_, Phone_, CardNo_, Age_, Illness_, Irritability_, Inheritance_, IsBindFinished_, Sex_, VxHeadUrl_, PfksShopUserId_ from r_patient WHERE ( RUserId_ = ? ) 
2020-01-11 11:13:47.843 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ==> Parameters: 458690345937539120(Long)
#############This means that AOP is used to call other transactions and judge whether there is a current transaction. The current transaction is used directly by default
2020-01-11 11:13:47.844 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Participating in existing transaction
############Continue to use current transaction 35ea154e
2020-01-11 11:13:47.845 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RDoctorMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]
#######Query doctor information through doctor Id
2020-01-11 11:13:47.845 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RDoctorMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, RUserId_, Name_, NamePY_, RHospitalId_, RDepartmentId_, PositionCode_, Phone_, RegisterTime_, CheckStatus_, CheckTime_, CheckUserName_, CheckRemark_, Speciality_, Profile_, VxHeadUrl_, Dtype_, PfksShopUserId_, RDocCareType_ from r_doctor WHERE ( Id_ = ? ) 
2020-01-11 11:13:47.846 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.doctor.RDoctorMapper.selectByExample | ==> Parameters: 463413442003472478(Long)

#############Use AOP again to call other transactions to determine whether there is a current transaction. Then the current transaction is used by default
2020-01-11 11:13:47.849 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Participating in existing transaction
#########Continue to use current transaction 35ea154e
2020-01-11 11:13:47.851 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]

#########Query the information of the doctor-patient report form through the doctor ID and the patient ID
2020-01-11 11:13:47.852 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, RPatientId_, RDoctorId_, CreateTime_, IMSessionId_, IllnessName_, RDoctorNameRemark_, RPatientNameRemark_ from r_report WHERE ( RDoctorId_ = ? and RPatientId_ = ? ) 
2020-01-11 11:13:47.853 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.selectByExample | ==> Parameters: 463413442003472478(Long), 458690345958510641(Long)
##############Continue to use current transaction 35ea154e
2020-01-11 11:13:47.854 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.insert | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]
#############Add a record of the patient report table patient id = 45869034595510641 IMSessionId? Is null	
2020-01-11 11:13:47.857 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.insert | ==>  Preparing: insert into r_report (Id_, RPatientId_, RDoctorId_, CreateTime_, IMSessionId_, IllnessName_, RDoctorNameRemark_, RPatientNameRemark_) values (?, ?, ?, ?, ?, ?, ?, ?) 
2020-01-11 11:13:47.858 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.mapper.report.RReportMapper.insert | ==> Parameters: 481834561777569793(Long), 458690345958510641(Long), 463413442003472478(Long), 2020-01-11 11:13:47.853(Timestamp), null, null, null, null

###########Log output here
2020-01-11 11:13:47.861 | myHost | INFO  | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | com.framework.code.service.report.RReportService | new report generate:{"id":481834561777569793,"rpatientid":458690345958510641,"rdoctorid":463413442003472478,"createtime":1578712427853,"imsessionid":null,"illnessname":null,"rdoctornameremark":null,"rpatientnameremark":null}

########Commit started transactions
2020-01-11 11:13:47.861 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Initiating transaction commit


#########Here we need to create a new transaction 7fb1091a thread number pool-1-thread-7
2020-01-11 11:13:47.861 | myHost | DEBUG | pool-1-thread-7 | [] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Creating new transaction with name [com.framework.code.service.report.RPatientService.registerEvent]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT

########Commit transaction of previous thread
2020-01-11 11:13:47.861 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Committing JDBC transaction on Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]]

################This is our new business 7fb1091a
2020-01-11 11:13:47.862 | myHost | DEBUG | pool-1-thread-7 | [] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Acquired Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]] for JDBC transaction
2020-01-11 11:13:47.862 | myHost | DEBUG | pool-1-thread-7 | [] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Switching JDBC Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]] to manual commit

######Here is the log output
2020-01-11 11:13:47.862 | myHost | INFO  | pool-1-thread-7 | [] | com.framework.code.service.report.RPatientService | [PatientEvent]:{"rUserId":458690345937539120,"rDoctorId":463413442003472478}

##########Use current transaction
2020-01-11 11:13:47.862 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.doctor.RUserMapper.selectByPrimaryKey | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]]

##########Query user information by user Id
2020-01-11 11:13:47.862 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.doctor.RUserMapper.selectByPrimaryKey | ==>  Preparing: select Id_, VxHeadUrl_, VxNickName_, VxSex_, VxOpenid_, VxProvince_, VxCity_, VxCountry_, Type_, PromotionSource_ from r_user where Id_ = ? 
2020-01-11 11:13:47.863 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.doctor.RUserMapper.selectByPrimaryKey | ==> Parameters: 458690345937539120(Long)


######Previous thread releases JDBC connection
2020-01-11 11:13:47.867 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Releasing JDBC Connection
[com.mchange.v2.c3p0.impl.NewProxyConnection@5c225ae5 [wrapping: com.mysql.jdbc.JDBC4Connection@35ea154e]] after transaction
2020-01-11 11:13:47.867 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.jdbc.datasource.DataSourceUtils | Returning JDBC Connection to DataSource
2020-01-11 11:13:47.867 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.web.servlet.DispatcherServlet | Completed 200 OK


####Log input blocked by AOP's section
2020-01-11 11:13:47.867 | myHost | INFO  | pool-1-thread-8 | [] | com.framework.web.eventbus.LogSubscribe | [LogSubscribe]:{"threadName":"http-nio-8081-exec-10","className":"com.framework.code.controller.webchat.WeChartController","methodName":"receiveEvent","argsMap":{"request":"ServletRequest","response":"ServletResponse"},"argsJson":"{\"request\":\"ServletRequest\",\"response\":\"ServletResponse\"}","happenTime":1578712427867,"throwable":null,"throwableString":null,"traceId":"436ed24f998d411ab5150b1258b22cd0","result":null,"useTime":33}

2020-01-11 11:13:47.867 | myHost | DEBUG | http-nio-8081-exec-10 | [436ed24f998d411ab5150b1258b22cd0] | org.springframework.session.web.http.SessionRepositoryFilter.SESSION_LOGGER | No session found by id: Caching result for getSession(false) for this HttpServletRequest.



########Use current transaction 7fb1091a
2020-01-11 11:13:47.867 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]]

###Query patient information through user ID
2020-01-11 11:13:47.867 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, RUserId_, RegisterTime_, Name_, Phone_, CardNo_, Age_, Illness_, Irritability_, Inheritance_, IsBindFinished_, Sex_, VxHeadUrl_, PfksShopUserId_ from r_patient WHERE ( RUserId_ = ? ) 
2020-01-11 11:13:47.869 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByExample | ==> Parameters: 458690345937539120(Long)


##########Use AOP to call other transactions and judge that there are currently transactions. Then, the current transaction 7fb1091a is used by default
2020-01-11 11:13:47.870 | myHost | DEBUG | pool-1-thread-7 | [] | org.springframework.jdbc.datasource.DataSourceTransactionManager | Participating in existing transaction
2020-01-11 11:13:47.876 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByPrimaryKey | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]]

######Query patient information through user ID
2020-01-11 11:13:47.876 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByPrimaryKey | ==>  Preparing: select Id_, RUserId_, RegisterTime_, Name_, Phone_, CardNo_, Age_, Illness_, Irritability_, Inheritance_, IsBindFinished_, Sex_, VxHeadUrl_, PfksShopUserId_ from r_patient where Id_ = ? 
2020-01-11 11:13:47.876 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RPatientMapper.selectByPrimaryKey | ==> Parameters: 458690345958510641(Long)

##########Use current transaction 7fb1091a
2020-01-11 11:13:47.878 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RReportMapper.selectByExample | ooo Using Connection [com.mchange.v2.c3p0.impl.NewProxyConnection@75935acf [wrapping: com.mysql.jdbc.JDBC4Connection@7fb1091a]]
##########Query patient report information table through patient ID 45869034595510641
2020-01-11 11:13:47.878 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RReportMapper.selectByExample | ==>  Preparing: select 'true' as QUERYID, Id_, RPatientId_, RDoctorId_, CreateTime_, IMSessionId_, IllnessName_, RDoctorNameRemark_, RPatientNameRemark_ from r_report WHERE ( RPatientId_ = ? and IMSessionId_ is null ) 
2020-01-11 11:13:47.878 | myHost | DEBUG | pool-1-thread-7 | [] | com.framework.code.mapper.report.RReportMapper.selectByExample | ==> Parameters: 458690345958510641(Long)

########Output query results 
2020-01-11 11:13:47.879 | myHost | INFO  | pool-1-thread-7 | [] | com.framework.code.service.report.RReportService | Query hidden danger report relationship.Quantity can only have one:0 Record information=[]

 

 

After reading the log, we can see that the main program has executed the new operation and released the JDBC connection. In the new transaction of the EventBus thread, we have not found the data we want to insert....

In the normal logic, this is a dead cycle...... I have finished the new operation and released the connection to the connection pool.. Why can't I find data in a new transaction.

 

Personal analysis may take a short time for the database to come out, because the time for the main thread to insert data and the time for the EventBus thread to query is only 0.02 seconds, and the data may not be written to the completion operation. My solution is to give up EventBus and use the main thread to process all businesses at one time, so that the response time of an interface call is longer, so as to reduce the concurrent problems.

46 original articles published, 20 praised, 30000 visited+
Private letter follow

Tags: JDBC MySQL Session Database

Posted on Sat, 11 Jan 2020 10:21:35 -0500 by Greaser9780