排行榜优化之-写读数据不一致问题排查

1️⃣、背景

在营销业务需求中，每个活动的参与用户拥有活动对应的资产，活动期间和活动结束后，在小程序页面都需要展示当前活动下的参与用户资产排行。

排序的逻辑是：用户的总资产+最先参与时间，总资产相同的情况下，最先参与活动的排前面。在活动期间，总资产会随着用户的动作动态变化。

界面展示如下:

 

 

2️⃣、实现方式

  1. 直接从数据库中，通过sql查询排序获取。这种方式实现起来简单，但是也有缺点：每次都从数据库中获取，单表数据量大的时候，查询，排序并不高效。
  2. 获取排行榜接口从redis中取前N排名，在资产管理类中新增事件监听当前用户的资产变化，及时更新到redis中。此种方案涉及到技术难点如下：
    1. 以什么样的数据结构存到redis中。
      1. redis的基于分数的有序集合,命令格式：(ZADD KEY_NAME SCORE1 VALUE1.. SCOREN VALUEN)，可以看到此种数据结构是根据score的值来排序的，而我们的排序条件是个组合条件，如果用这种结构，需要一个算法把组合条件（total+time）的转成一个score值，并且这个value，我们需要存入当前参与用户对象的一些信息。
      2. 在翻看redisson 文档时发现reddisson支持sortset这样一种结构（https://github.com/redisson/redisson/wiki/7.-distributed-collections/#74-sortedset），背后的存入redis的其实是list，排序的方式可以自定义，这个list由reddssion维护，取出来就是已经排好序的列表，所以我选择了这种数据结构。
    2. 用户资产变化时怎么保持排名的正确性。用户资产变化存在以下几种情况。
      1. 用户资产变化，排名不变。并在TopN中。
      2. 用户资产变化，排名变更，名次还在TopN内.
      3. 用户资产变更，之前不在TopN，本次变更在TopN中。
      4. 用户资产变更，排名跌出TopN。缓存变更，当前用户剔除缓存，新用户加入topN。

3️⃣、发现问题

从实现方式可以知道，要通过redis来存当前活动的排行榜数据，需要逻辑来维护这份数据，因为用户的资产在活动期间是动态变化的。在代码中，当用户资产变化的时候，通过一个应用内异步事件拿当前变化的数据更新redis中的数据。实现代码如下：

    public void assetsAdd(Long activityId, Long activityJoinId, ActivityAssetsLogEnums.AssetsLogType type, Integer assetsValue, AssetsCallback callback) throws BusinessException {
        //前置业务
        AssetsCallbackResult callbackResult = callback.callback();
        //资产添加成功
        if (activityJoinDao.assetsIncr(activityJoinId,assetsValue)) {
            activityAssetsLogDao.addLog(activityId,activityJoinId,type.getCode(),assetsValue,callbackResult.getRemark(),callbackResult.getBizId());
			//推送资产变更事件（异步）
            eventBusPublisher.publishAsync(new ActivityJoinAssertChangeEvent(activityId,activityJoinId, ActivityJoinEnums.AssertChangeType.ASSETS_ADD,assetsValue));
        } else {
            throw BusinessExceptionFactory.create(BizErrorCodeEnum.ERROR_CODE_ACTIVITY_ASSETS_COMMON,"参与人不存在");
        }
    }
	//资产变更事件监听
    public void activityJoinAssertChange2Redis(ActivityJoinAssertChangeEvent event) {
        if (event.getAssertChangeType().equals(ActivityJoinEnums.AssertChangeType.ASSETS_CONSUME)) {
            return;
        }
        String key = String.format(USER_JOIN_ACTIVITY_ASSETS_RANK.getKey(), event.getActivityId());
        RSortedSet<ActivityAssetsRankData> dataRSortedSet = redissonHelper.getRedissonClient().getSortedSet(key);
        //数据如果是空的不用管，在调用资产排行接口的时候会初始化
        if (dataRSortedSet.isEmpty()) {
            return;
        }
        List<ActivityAssetsRankData> activityAssetsRankDataList = dataRSortedSet.readAll().stream().collect(Collectors.toList());
		/******读取当前用户的资产********/
        MmsActivityJoinEntity mmsActivityJoinEntity = activityJoinEntityMapper.selectByID(event.getActivityJoinId());
        Optional<ActivityAssetsRankData> activityAssetsRankDataOptional = activityAssetsRankDataList.stream().filter(data -> data.getId().equals(event.getActivityJoinId())).findFirst();
        ActivityAssetsRankData activityAssetsRankData = new ActivityAssetsRankData();
        if (activityAssetsRankDataOptional.isPresent()) {
            activityAssetsRankData = activityAssetsRankDataOptional.get();
            activityAssetsRankDataList.remove(activityAssetsRankData);
        }
        BeanUtils.copyProperties(mmsActivityJoinEntity, activityAssetsRankData);
        activityAssetsRankDataList.add(activityAssetsRankData);
        if (activityAssetsRankDataList.size() > rankConst) {
            activityAssetsRankDataList.sort(activityAssetsRankData);
            activityAssetsRankDataList = activityAssetsRankDataList.subList(0, rankConst);
            if (activityAssetsRankDataList.indexOf(activityAssetsRankData) != -1) {
                dataRSortedSet.clear();
                dataRSortedSet.addAll(activityAssetsRankDataList);
            }
        } else {
            dataRSortedSet.clear();
            dataRSortedSet.addAll(activityAssetsRankDataList);
        }
    }

当用户资产变更是，发布异步事件，异步更新redis中的排行数据。这个逻辑看上去很美好，但是实际测试下来发现当用资产由10变成20时，异步逻辑中有几率读到的资产还是10？这样就导致缓存中数据不正确。

5️⃣、分析问题

 

出现这种问题需要从一下几个方面考虑：

  1. 主从同步延时问题，当更新了数据，马上查询，有可能更新了主库，而查询走从库，导致查询数据不一致。
  2. mybatis缓存问题，mybatis在查询条件一致的情况下，会优先从一级缓存中读取数据。
  3. 事物原因导致数据读取不一致。

while(true)反复分析(程序员)_While_true_程序员_反复_分析表情

6️⃣、排查问题

既然有了怀疑的对象，我们就开始一一排查。

  • 主从同步

从配置中心看，数据库主从都是配的一个地址，并且指向的是ecs实例，因此可能不是主从同步问题导致。

  • mybatis缓存问题

mybatis配置中，有是否开启缓存等配置，有全局的也有局部的，因此我在xml实现了这么一个查询配置（useCache="false" flushCache="true"）不使用缓存，并且刷新缓存。

  <select id="selectByID"  resultMap="cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityMapper.BaseResultMap" useCache="false" flushCache="true">
    select * from mms_activity_join where id=#{activityJoinId}
  </select>

测试下来还是存在读取数据不一致。

  • 事物

要分析是不是事物原因，我们要借助日志，因此首先需要打开相关的日志配置如下：

/**打开数据库操作日志*/ 
<Logger name="com.alibaba.druid" level="DEBUG" additivity="false">
        <AppenderRef ref="STDOUT"/>
        <AppenderRef ref="JAR_LOG_FILE"/>
    </Logger>

    <Logger name="org.mybatis.spring" level="DEBUG" additivity="false">
        <AppenderRef ref="STDOUT"/>
        <AppenderRef ref="JAR_LOG_FILE"/>
    </Logger>

    <Logger name="tk.mybatis" level="DEBUG" additivity="false">
        <AppenderRef ref="STDOUT"/>
        <AppenderRef ref="JAR_LOG_FILE"/>
    </Logger>

    <Logger name="org.apache.ibatis" level="DEBUG" additivity="false">
        <AppenderRef ref="STDOUT"/>
        <AppenderRef ref="JAR_LOG_FILE"/>
    </Logger>
/**关闭缓存同步日志*/
    <Logger name="cn.mwee.base_common.cache.CachePoolHelper" level="INFO" additivity="false" >
    </Logger>
    • 第一步：代码中加入日志打印，
      1. 在资产变更的方法中通过mapper查询当前用户的资产数据，并打印日志。
      2. 在事件监听方法中通过mapper查询当前用户资产数据，并打印日志。

发奖流程：

得到的日志内容如下：

10:28:38,161 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Creating a new SqlSession
10:28:38,162 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@9468e6e] was not registered for synchronization because synchronization is not active
10:28:38,197 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [http-nio-3081-exec-15]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@233e4356] will not be managed by Spring
10:28:38,231 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByExample], SELECT id,activity_id,activity_type,user_id,user_mobile,user_name,head_img,platform,user_open_id,user_union_id,user_level,state,fission_assist_user_count,fission_assist_user_success_count,prize_draw_state,share_qrcode,join_group,join_group_id,join_code,inviter_join_id,order_count,order_amount,activity_assets_total,activity_assets_used,create_time,update_time FROM mms_activity_join WHERE ( ( activity_id = 4001 and user_id = 2035654811 ) ) order by id desc, Spend Time ===> 64 ms
10:28:38,231 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@9468e6e]
10:28:38,521 <cn.mwee.msh.mms.biz.handler.AbstractHandler>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], 转盘抽奖-中奖日志：请求参数{\"activityId\":4001,\"cityId\":258,\"clientIp\":\"39.144.43.212\",\"platform\":\"wechat\",\"shareJoinId\":0,\"unionId\":\"o9BuWjod_YGPlYnBRWKbaspOrr9w\",\"userId\":2035654811,\"userMobile\":\"13788984575\",\"userName\":\"A.祢「一人心」.A11\",\"userOpenId\":\"oSj7-48oOMprjTbtgOBEjhvmRwa4\"}，抽中奖品{\"activityId\":4001,\"createTime\":1663732185000,\"id\":8356,\"prizeDrawCondition\":\"\",\"prizeDrawTimesLimit\":0,\"prizeInventoryTotal\":0,\"prizeInventoryUsed\":0,\"prizeLevel\":1,\"prizeName\":\"吃货币\",\"prizeOps\":\"\",\"prizePercent\":10.00,\"prizePic\":\"\",\"prizePosition\":5,\"prizePrice\":0,\"prizeQuantity\":10,\"prizeRemark\":\"\",\"prizeShowCondition\":\"\",\"prizeType\":\"asset_coin\",\"prizeValue\":\"\"}
创建事物🔵10:28:38,663 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Creating a new SqlSession
注册事物🔵10:28:38,664 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
10:28:38,666 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [http-nio-3081-exec-15]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@5f1edc47] will be managed by Spring
增加资产🔴10:28:38,706 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.assetsIncr], UPDATE mms_activity_join SET activity_assets_total = activity_assets_total+10 WHERE id = 259242, Spend Time ===> 41 ms, Affect Count ===> 1
10:28:38,706 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
10:28:38,707 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1] from current transaction
10:28:38,737 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByID], select * from mms_activity_join where id=259242, Spend Time ===> 30 ms
10:28:38,738 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
打印用户资产🔴10:28:38,740 <cn.mwee.msh.mms.biz.service.ActivityAssetsBizService>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], mmsActivityJoinEntity-assetsAdd=>{\"activityAssetsTotal\":40,\"activityAssetsUsed\":0,\"activityId\":4001,\"activityType\":\"rotaryDraw\",\"createTime\":1663811353000,\"fissionAssistUserCount\":0,\"fissionAssistUserSuccessCount\":0,\"id\":259242,\"inviterJoinId\":0,\"joinCode\":\"4001\",\"joinGroup\":0,\"orderAmount\":0,\"orderCount\":0,\"platform\":\"wechat\",\"prizeDrawState\":1,\"shareQrcode\":\"\",\"state\":2,\"userId\":2035654811,\"userLevel\":0,\"userMobile\":\"13788984575\",\"userName\":\"A.祢「一人心」.A11\",\"userOpenId\":\"oSj7-48oOMprjTbtgOBEjhvmRwa4\",\"userUnionId\":\"o9BuWjod_YGPlYnBRWKbaspOrr9w\"}
使用当前事物🔴10:28:38,741 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1] from current transaction
写入资产日志🔴10:28:38,805 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityAssetsLogEntityExtMapper.insertSelective], INSERT INTO mms_activity_assets_log ( id,activity_id,activity_join_id,type,assets_value,remark,biz_id,create_time ) VALUES( 112896,4001,259242,'exchange_prize',10,'活动中奖，系统发放吃货币','','2022-09-22 10:28:38' ), Spend Time ===> 64 ms, Affect Count ===> 1
10:28:38,806 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
10:28:38,808 <cn.mwee.msh.mms.common.eventbus.IMmsEventListener>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], event listener ActivityEventListener_activityJoinAssertChangeEventListener receive event :{\"activityId\":4001,\"activityJoinId\":259242,\"assertChangeType\":\"ASSETS_ADD\",\"assetsValue\":10,\"eventId\":\"20220922_102838140_442955ab6f48498c902054c31320d8d3\"}
10:28:38,809 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1] from current transaction
创建事物⚫️10:28:38,878 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: Creating a new SqlSession
⚫️10:28:38,879 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@23a455e7] was not registered for synchronization because synchronization is not active
写入发奖记录🔴10:28:38,899 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-15]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityPrizeDrawEntityExtMapper.insertSelective], INSERT INTO mms_activity_prize_draw ( id,activity_id,activity_join_id,user_id,user_mobile,user_name,fetch_time,fetch_source,fetch_source_id,fetch_source_remark,prize_id,prize_type,prize_value,state,create_time ) VALUES( 292487,4001,259242,2035654811,'13788984575','A.祢「一人心」.A11','2022-09-22 10:28:38','','','',8356,'asset_coin','10',0,'2022-09-22 10:28:38' ), Spend Time ===> 78 ms, Affect Count ===> 1
释放事物🔵10:28:38,899 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
提交事物🔵10:28:38,903 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
打印事物🔵10:28:38,903 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@233e4356] will not be managed by Spring
卸载事物🔵10:28:38,903 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
关闭事物🔵10:28:38,903 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-15]: Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@29b92da1]
查询当前用户资产⚫️10:28:38,926 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByID], select * from mms_activity_join where id=259242, Spend Time ===> 45 ms
关闭事物⚫️10:28:38,926 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@23a455e7]
打印用户资产⚫️10:28:38,927 <cn.mwee.msh.mms.biz.service.ActivityJoinBizService>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_102838140_442955ab6f48498c902054c31320d8d3], mmsActivityJoinEntity=>{\"activityAssetsTotal\":30,\"activityAssetsUsed\":0,\"activityId\":4001,\"activityType\":\"rotaryDraw\",\"createTime\":1663811353000,\"fissionAssistUserCount\":0,\"fissionAssistUserSuccessCount\":0,\"id\":259242,\"inviterJoinId\":0,\"joinCode\":\"4001\",\"joinGroup\":0,\"orderAmount\":0,\"orderCount\":0,\"platform\":\"wechat\",\"prizeDrawState\":1,\"shareQrcode\":\"\",\"state\":2,\"userId\":2035654811,\"userLevel\":0,\"userMobile\":\"13788984575\",\"userName\":\"A.祢「一人心」.A11\",\"userOpenId\":\"oSj7-48oOMprjTbtgOBEjhvmRwa4\",\"userUnionId\":\"o9BuWjod_YGPlYnBRWKbaspOrr9w\"}

从日志中我们可以看到，

🔴的记录，在资产变更的逻辑中读取到的用资产是40，而在异步事件监听中读到了30。

🔵看出从抽奖-资产变更-发奖，都在一个事物中。

⚫️异步监听中创建了一个新的事物，发奖事物提交在异步监听事物后面。

所以极有可能是mysql的事物隔离导致数据读取不一致的问题，然后查看下当前数据库的事物隔离级别：

show variables like '%isolation%'，当前数据库的事物隔离级别为：READ-COMMITTED，表示B事物能读到A事物的提交后的数据。也就能解释为什么异步监听中读不到最新的数据，因为异步监听触发后，资产变更事务未提交。

7️⃣、解决问题

从上面我们得知问题的原因，由此可以知道要解决当前问题有几种方式：

  1. 在资产变更事务中，查询当前用的资产数据作为参数，传到异步事件中。
  2. 更新用户资产的逻辑，开启一个新的事物，完成更新并提交。
  3. 更新用户资产的逻辑事物配置为PROPAGATION_NOT_SUPPORTED，即当前逻辑不使用事物提交。

分析下来：个人觉得方式1能解决当前问题，方式2能解决资产变更逻辑中读取不一致的问题。因此采用方式2来解决。

    public boolean assetsIncr(Long id,Integer assetsValue) {
        DefaultTransactionDefinition defaultTransactionDefinition= new DefaultTransactionDefinition();
        defaultTransactionDefinition.setPropagationBehavior(PROPAGATION_REQUIRES_NEW);
        TransactionStatus status =  platformTransactionManager.getTransaction(defaultTransactionDefinition);
        boolean success=false;
        try {
            success= mapper.assetsIncr(id, assetsValue) > 0;
            platformTransactionManager.commit(status);
        } catch (Exception e) {
            platformTransactionManager.rollback(status);
            throw e;
        }
        return success;
    }

日志输出如下：

12:59:58,726 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Creating a new SqlSession
12:59:58,728 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4c39e382] was not registered for synchronization because synchronization is not active
12:59:58,742 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [http-nio-3081-exec-14]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@233e4356] will not be managed by Spring
12:59:58,761 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByExample], SELECT id,activity_id,activity_type,user_id,user_mobile,user_name,head_img,platform,user_open_id,user_union_id,user_level,state,fission_assist_user_count,fission_assist_user_success_count,prize_draw_state,share_qrcode,join_group,join_group_id,join_code,inviter_join_id,order_count,order_amount,activity_assets_total,activity_assets_used,create_time,update_time FROM mms_activity_join WHERE ( ( activity_id = 4001 and user_id = 2035654813 ) ) order by id desc, Spend Time ===> 29 ms
12:59:58,761 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@4c39e382]
12:59:58,976 <cn.mwee.msh.mms.biz.handler.AbstractHandler>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], 转盘抽奖-中奖日志：请求参数{\"activityId\":4001,\"cityId\":258,\"clientIp\":\"39.144.43.212\",\"platform\":\"wechat\",\"shareJoinId\":0,\"unionId\":\"o9BuWjod_YGPlYnBRWKbaspOrr9w\",\"userId\":2035654813,\"userMobile\":\"13788984575\",\"userName\":\"A.祢「一人心」.A13\",\"userOpenId\":\"oSj7-48oOMprjTbtgOBEjhvmRwa4\"}，抽中奖品{\"activityId\":4001,\"createTime\":1663732185000,\"id\":8357,\"prizeDrawCondition\":\"\",\"prizeDrawTimesLimit\":0,\"prizeInventoryTotal\":0,\"prizeInventoryUsed\":0,\"prizeLevel\":1,\"prizeName\":\"吃货币\",\"prizeOps\":\"\",\"prizePercent\":10.00,\"prizePic\":\"\",\"prizePosition\":6,\"prizePrice\":0,\"prizeQuantity\":10,\"prizeRemark\":\"\",\"prizeShowCondition\":\"\",\"prizeType\":\"asset_coin\",\"prizeValue\":\"\"}
🔴12:59:59,050 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Creating a new SqlSession
🔴12:59:59,051 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5d277e63]
🔴12:59:59,053 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [http-nio-3081-exec-14]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@45d6d9f6] will be managed by Spring
🔴12:59:59,091 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.assetsIncr], UPDATE mms_activity_join SET activity_assets_total = activity_assets_total+10 WHERE id = 259248, Spend Time ===> 40 ms, Affect Count ===> 1
🔴12:59:59,091 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5d277e63]
🔴12:59:59,091 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5d277e63]
🔴12:59:59,092 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5d277e63]
🔴12:59:59,092 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5d277e63]
🔵12:59:59,150 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Creating a new SqlSession
🔵12:59:59,151 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
🔵12:59:59,151 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [http-nio-3081-exec-14]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@5f1edc47] will be managed by Spring
🔵12:59:59,175 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByID], select * from mms_activity_join where id=259248, Spend Time ===> 24 ms
🔵12:59:59,176 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
🔵12:59:59,176 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95] from current transaction
🔵12:59:59,226 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.🔵MmsActivityAssetsLogEntityExtMapper.insertSelective], INSERT INTO mms_activity_assets_log ( id,activity_id,activity_join_id,type,assets_value,remark,biz_id,create_time ) VALUES( 112984,4001,259248,'exchange_prize',10,'活动中奖，系统发放吃货币','','2022-09-22 12:59:59' ), Spend Time ===> 48 ms, Affect Count ===> 1
🔵12:59:59,226 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
⚫️12:59:59,227 <cn.mwee.msh.mms.common.eventbus.IMmsEventListener>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], event listener ActivityEventListener_activityJoinAssertChangeEventListener receive event :{\"activityId\":4001,\"activityJoinId\":259248,\"assertChangeType\":\"ASSETS_ADD\",\"assetsValue\":10,\"eventId\":\"20220922_125958686_6c407706d94245e2acd5710bfde7253b\"}
🔵12:59:59,227 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95] from current transaction
⚫️12:59:59,274 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: Creating a new SqlSession
⚫️12:59:59,275 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5f64ecb7] was not registered for synchronization because synchronization is not active
🔵12:59:59,293 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [http-nio-3081-exec-14]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityPrizeDrawEntityExtMapper.insertSelective], INSERT INTO mms_activity_prize_draw ( id,activity_id,activity_join_id,user_id,user_mobile,user_name,fetch_time,fetch_source,fetch_source_id,fetch_source_remark,prize_id,prize_type,prize_value,state,create_time ) VALUES( 292521,4001,259248,2035654813,'13788984575','A.祢「一人心」.A13','2022-09-22 12:59:59','','','',8357,'asset_coin','10',0,'2022-09-22 12:59:59' ), Spend Time ===> 60 ms, Affect Count ===> 1
🔵12:59:59,293 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
🔵12:59:59,294 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
🔵12:59:59,300 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization deregistering SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
🔵12:59:59,301 <org.mybatis.spring.SqlSessionUtils> DEBUG [http-nio-3081-exec-14]: Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@81f1d95]
⚫️12:59:59,301 <org.mybatis.spring.transaction.SpringManagedTransaction> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@233e4356] will not be managed by Spring
⚫️12:59:59,318 <cn.mwee.base_common.helper.mybatis.plugins.SqlInterceptor>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], Mapper Method ===> [cn.mwee.msh.mms.data.mapper.MmsActivityJoinEntityExtMapper.selectByID], select * from mms_activity_join where id=259248, Spend Time ===> 42 ms
⚫️12:59:59,318 <org.mybatis.spring.SqlSessionUtils> DEBUG [mwee-pool-asyncEventBusThread-thread-0]: Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@5f64ecb7]
⚫️12:59:59,325 <cn.mwee.msh.mms.biz.service.ActivityJoinBizService>  INFO [mwee-pool-asyncEventBusThread-thread-0]: TraceID[20220922_125958686_6c407706d94245e2acd5710bfde7253b], mmsActivityJoinEntity=>-activityJoinEntityMapper{\"activityAssetsTotal\":200,\"activityAssetsUsed\":0,\"activityId\":4001,\"activityType\":\"rotaryDraw\",\"createTime\":1663817915000,\"fissionAssistUserCount\":0,\"fissionAssistUserSuccessCount\":0,\"id\":259248,\"inviterJoinId\":0,\"joinCode\":\"4001\",\"joinGroup\":0,\"orderAmount\":0,\"orderCount\":0,\"platform\":\"wechat\",\"prizeDrawState\":1,\"shareQrcode\":\"\",\"state\":2,\"userId\":2035654813,\"userLevel\":0,\"userMobile\":\"13788984575\",\"userName\":\"A.祢「一人心」.A13\",\"userOpenId\":\"oSj7-48oOMprjTbtgOBEjhvmRwa4\",\"userUnionId\":\"o9BuWjod_YGPlYnBRWKbaspOrr9w\"}

8️⃣、总结&思考

在业务中使用事物，需要多关注事物传播和事物隔离级别的问题。

在更新用户的资产直接使用@Transactional行不行？

spring的事物隔离级别与数据的的隔离级别不一致会有什么问题？

posted @ 2022-09-27 12:52  AlanCoder  阅读(132)  评论(0)  编辑  收藏  举报
View Code