java 处理线上bug_记一次线上bug处理-mybatis一级缓存引起

问题：

线上riskProvision定时任务,计算出的金额不对

定位问题：

查看日志

4.13 riskProvision

2017-04-13 01:10:00.009 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] from current transaction

2017-04-13 01:10:00.010 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] for iBATIS operation

2017-04-13 01:10:00.010 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

2017-04-13 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] from current transaction

2017-04-13 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] for iBATIS operation

2017-04-13 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Creating SqlSession with JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@43c10cbc]

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.Connection] DEBUG ooo Connection Opened

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SpringManagedTransaction] DEBUG JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@43c10cbc] will be managed by Spring

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1159e5ac]

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1159e5ac] for iBATIS operation

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Executing: select sum(a.TRAN_AMT) from FIN_FUND_TRAN a join outcome_flow b on a.pt_no = b.pt_no and a.ser_no = b.bus_ser where '1' = a.TRAN_ACC and a.TRAN_REA = '1' and (b.RECO_STATE = 'U'or b.RECO_STATE = '0' or b.RECO_STATE = '5') and a.pt_no = ?

2017-04-13 01:10:00.012 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Parameters: 002(String)

2017-04-13 01:10:00.014 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.ResultSet] DEBUG <== Columns: 1

好像也执行了,但是金额为什么和数据库的表里的不一致,再查整个的定时任务日志

4.13 cron

2017-04-13 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] from current transaction

2017-04-13 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] for iBATIS operation

2017-04-13 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

2017-04-13 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [net.tangdi.gxseas.service.AutoRecon] INFO === 日切日期：2017-04-07

2017-04-13 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [net.tangdi.gxseas.service.AutoRecon] INFO 任务号:A,任务执行步骤:A01,日切日期:20170407

4月13日应该执行4.12日的,为什么执行了4.07日的了?

查下数据库定时任务日期控制表也是4,12,诡异啊?

不对,日志为什么没有执行的sql记录呢?

异常的话也不应该执行下去啊,莫名其妙,陷入了无头绪的状态.

因为mybatis的调用时用的第三方小厂家封装框架,出于对于它的不信任,看起了源码,在BaseExecutor发现看玄机

public List query(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler) throws SQLException {

ErrorContext.instance().resource(ms.getResource()).activity("executing a query").object(ms.getId());

if (closed) throw new ExecutorException("Executor was closed.");

// Flush the internal cache is force is true

if (ms.isFlushCacheRequired()) {

clearLocalCache();

}

List list;

try {

queryStack++;

CacheKey key = createCacheKey(ms, parameter, rowBounds);

list = resultHandler == null ? (List) localCache.getObject(key) : null;

if (list != null) {

handleLocallyCachedOutputParameters(ms, key, parameter);

} else {

list = queryFromDatabase(ms, parameter, rowBounds, resultHandler, key);

}

} finally {

queryStack--;

}

if (queryStack == 0) {

for (DeferredLoad deferredLoad : deferredLoads) {

deferredLoad.load();

}

}

return list;

}

调用方resultHandler传入的默认全是null,说明它会缓存拿.

因为上面的sql都没有参数,key是一定的,所以第二次之后会查缓存，但是数据时会变的,造成缓存和数据库的数据不一致.

继续看mybatis源码,发现localCache是SqlSession的成员变量.那么就可以断定如果相同的sql在同一个SqlSession执行,就会命中缓存,为了证实我的猜想,继续翻日志

4.10 rishProvision

2017-04-10 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] from current transaction

2017-04-10 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] for iBATIS operation

2017-04-10 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Executing: SELECT PT_NO, ACC_AMT, BOON_AMT, CUST_AMT, PRO_AMT, FEE_AMT, MX_AMT, LT_AMT, FXJT_AMT, PT_DEP_AMT, PRO_DEP_AMT, PROCOUNT, FINCOUNT, INVCOUNT, BOUNS_RATIO, LOANSUM_AMT, REPAY_RAT, LEVER_RAT, OVERDUE_RAT, OVERDUE_PRO_RAT, UPDATE_DATE, CORE_MANA_AMT, CORE_WAIT_AMT, PT_WAIT_AMT, CORE_RESULT, CORE_GUARA_AMT, CORE_BOND_WAIT_AMT, PT_BOND_WAIT_AMT, BOND_RESULT FROM PALTFORMACCOUNT

2017-04-10 01:10:00.011 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Parameters:

2017-04-10 01:10:00.013 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.ResultSet] DEBUG <== Columns: PT_NO, ACC_AMT, BOON_AMT, CUST_AMT, PRO_AMT, FEE_AMT, MX_AMT, LT_AMT, FXJT_AMT, PT_DEP_AMT, PRO_DEP_AMT, PROCOUNT, FINCOUNT, INVCOUNT, BOUNS_RATIO, LOANSUM_AMT, REPAY_RAT, LEVER_RAT, OVERDUE_RAT, OVERDUE_PRO_RAT, UPDATE_DATE, CORE_MANA_AMT, CORE_WAIT_AMT, PT_WAIT_AMT, CORE_RESULT, CORE_GUARA_AMT, CORE_BOND_WAIT_AMT, PT_BOND_WAIT_AMT, BOND_RESULT

2017-04-10 01:10:00.014 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.ResultSet] DEBUG <== Row: 006, 17115160.20, 1316359.13, 12149570.66, 3057572.01, 1638003.75, 61413.78, 0.00, 208600.00, 1316359.13, 0.00, 61841, 61841, 5, 0.00, 453419406.77, 0.68, 0.070, 0.020, 0.000, 2015-09-07 10:07:26.292735, 19534686.720, null, null, 0, 851068.580, null, null, 0

2017-04-10 01:10:00.015 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

4.10 cron

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [net.tangdi.gxseas.service.AutoRecon] INFO 数据迁移到历史表,当前主机域名:znq133

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] from current transaction

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28] for iBATIS operation

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Executing: SELECT TO_CHAR(MAX(DT),'YYYY-MM-DD') FROM WORK_HOLIDAY WHERE TRASTATUS = '1'

2017-04-10 01:10:00.004 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.PreparedStatement] DEBUG ==> Parameters:

2017-04-10 01:10:00.005 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.ResultSet] DEBUG <== Columns: 1

2017-04-10 01:10:00.005 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [java.sql.ResultSet] DEBUG <== Row: 2017-04-07

2017-04-10 01:10:00.005 [org.springframework.scheduling.quartz.SchedulerFactoryBean#0_Worker-6] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@12af9e28]

可以看出这几个SQLSession都是@12af9e28，且错误执行的数据就是这几天日志查处的,证实了我的想法

解决问题

了解下mybatis 的一级缓存,select语句默认开启,由MappedStatement的flushCache属性控制.

那么怎么把mybatis的一级缓存关闭呢?

官网说

1.sql级别

2.全局FlushCache

mybatis->configuration.xml->setting标签添加

单条关闭不适合现在的存量项目,sql太多了,排查不方便,全局吧,一运行发现mybatis3.0.6版本不支持此属性

3.mybatis插件

全局拦截MappedStatement使flushCache=true

import org.apache.ibatis.executor.Executor;

import org.apache.ibatis.mapping.MappedStatement;

import org.apache.ibatis.plugin.Interceptor;

import org.apache.ibatis.plugin.Intercepts;

import org.apache.ibatis.plugin.Invocation;

import org.apache.ibatis.plugin.Plugin;

import org.apache.ibatis.plugin.Signature;

import org.apache.ibatis.session.ResultHandler;

import org.apache.ibatis.session.RowBounds;

import java.util.Properties;

/**

* 关掉Mybatis所有查询的一级缓存

* Created by mumubin 2017/4/13.

*/

@Intercepts(@Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class,

RowBounds.class, ResultHandler.class}))

public class FlushCacheInterceptor implements Interceptor {

@Override

public Object intercept(Invocation invocation) throws Throwable {

MappedStatement mappedStatement = (MappedStatement) invocation.getArgs()[0];

MappedStatement copy = copyMappedStatementFlushCache(mappedStatement);

invocation.getArgs()[0] = copy;

return invocation.proceed();

}

/**

* 复制MappedStatement 并设置FlushCache=true

* @param mappedStatement

* @return

*/

private MappedStatement copyMappedStatementFlushCache(MappedStatement mappedStatement) {

MappedStatement.Builder builder = new MappedStatement.Builder(mappedStatement.getConfiguration(),

mappedStatement.getId(), mappedStatement.getSqlSource(), mappedStatement.getSqlCommandType());

builder.resource(mappedStatement.getResource());

builder.fetchSize(mappedStatement.getFetchSize());

builder.statementType(mappedStatement.getStatementType());

builder.keyGenerator(mappedStatement.getKeyGenerator());

builder.keyProperty(mappedStatement.getKeyProperty());

builder.timeout(mappedStatement.getTimeout());

builder.resultMaps(mappedStatement.getResultMaps());

builder.resultSetType(mappedStatement.getResultSetType());

builder.cache(mappedStatement.getCache());

builder.useCache(mappedStatement.isUseCache());

builder.parameterMap(mappedStatement.getParameterMap());

builder.flushCacheRequired(true);

return builder.build();

}

@Override

public Object plugin(Object o) {

return Plugin.wrap(o, this);

}

@Override

public void setProperties(Properties properties) {

}

}

单元测试测试下吧,查缓存的日志

2017-04-14 09:00:21.495 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Creating SqlSession with JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@3541d281]

2017-04-14 09:00:21.496 [main] [java.sql.Connection] DEBUG ooo Connection Opened

2017-04-14 09:00:21.500 [main] [com.tangdi.jump.bp.service.sqlmap.support.SpringManagedTransaction] DEBUG JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@3541d281] will be managed by Spring

2017-04-14 09:00:27.437 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf]

2017-04-14 09:00:27.442 [main] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf] for iBATIS operation

2017-04-14 09:00:37.826 [main] [java.sql.PreparedStatement] DEBUG ==> Executing: SELECT TO_CHAR(MAX(DT),'YYYY-MM-DD') FROM WORK_HOLIDAY WHERE TRASTATUS = '1'

2017-04-14 09:00:37.826 [main] [java.sql.PreparedStatement] DEBUG ==> Parameters:

2017-04-14 09:00:37.842 [main] [java.sql.ResultSet] DEBUG <== Columns: 1

2017-04-14 09:00:37.842 [main] [java.sql.ResultSet] DEBUG <== Row: 2017-04-05

2017-04-14 09:00:37.846 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf]

aa:2017-04-05

2017-04-14 09:00:59.856 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf] from current transaction

2017-04-14 09:00:59.856 [main] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf] for iBATIS operation

2017-04-14 09:00:59.857 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf]

bb:2017-04-05

2017-04-14 09:00:59.857 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf]

2017-04-14 09:00:59.858 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@53372fcf]

加入插件,FlushCache后的日志

2017-04-14 09:51:04.864 [main] [java.sql.Connection] DEBUG ooo Connection Opened

2017-04-14 09:51:04.867 [main] [com.tangdi.jump.bp.service.sqlmap.support.SpringManagedTransaction] DEBUG JDBC Connection [com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl@7722306c] will be managed by Spring

2017-04-14 09:51:04.879 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21]

2017-04-14 09:51:04.880 [main] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21] for iBATIS operation

2017-04-14 09:51:07.890 [main] [java.sql.PreparedStatement] DEBUG ==> Executing: SELECT TO_CHAR(MAX(DT),'YYYY-MM-DD') FROM WORK_HOLIDAY WHERE TRASTATUS = '1'

2017-04-14 09:51:07.890 [main] [java.sql.PreparedStatement] DEBUG ==> Parameters:

2017-04-14 09:51:07.905 [main] [java.sql.ResultSet] DEBUG <== Columns: 1

2017-04-14 09:51:07.905 [main] [java.sql.ResultSet] DEBUG <== Row: 2017-04-14

2017-04-14 09:51:07.909 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21]

aa:2017-04-14

2017-04-14 09:51:09.837 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Fetched SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21] from current transaction

2017-04-14 09:51:09.838 [main] [com.tangdi.jump.bp.service.sqlmap.impl.SqlMapImpl] DEBUG Opened SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21] for iBATIS operation

2017-04-14 09:51:09.839 [main] [java.sql.PreparedStatement] DEBUG ==> Executing: SELECT TO_CHAR(MAX(DT),'YYYY-MM-DD') FROM WORK_HOLIDAY WHERE TRASTATUS = '1'

2017-04-14 09:51:09.840 [main] [java.sql.PreparedStatement] DEBUG ==> Parameters:

2017-04-14 09:51:09.844 [main] [java.sql.ResultSet] DEBUG <== Columns: 1

2017-04-14 09:51:09.844 [main] [java.sql.ResultSet] DEBUG <== Row: 2017-04-14

2017-04-14 09:51:09.845 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Releasing transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21]

bb:2017-04-14

2017-04-14 09:51:09.846 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Transaction synchronization committing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21]

2017-04-14 09:51:09.848 [main] [com.tangdi.jump.bp.service.sqlmap.support.SqlSessionUtils] DEBUG Transaction synchronization closing SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@1011dc21]

ok,大功告成,bug完美解决，所以sql查询都必须查询数据库了

总结

吐槽下mybatis的设计问题,ORM好好做数据库的事情,关于缓存的事情不要做,交给redis好了,功能做就做了,但是默认开启就不对了!!! 不管是什么开源项目,都需在保证正确性的下再考虑提示性能.在提示性能有可能引入数据错误的功能应默认关闭!!!!