MyBatis的设计思想很简单,可以看做是对JDBC的一次封装,并提供强大的动态SQL映射功能。但是由于它本身也有一些缓存、事务管理等功能,所以实际使用中还是会碰到一些问题——另外,最近接触了JFinal,其思想和Hibernate类似,但要更简洁,和MyBatis的设计思想不同,但有一点相同:都是想通过简洁的设计最大限度地简化开发和提升性能——说到性能,前段时间碰到两个问题:
第一个问题是偶尔会出现,在实验环境无论如何也重现不了,经过分析MyBatis的逻辑,估计是两个DAO分别拿到了两个不同的Connection,第二个语句比第一个更早的被提交,导致了主键冲突,有待进一步的分析和验证。对于第二个问题,本文将尝试通过分析源代码和实验找到它的root cause,主要涉及到以下内容:
整个系统是微服务架构,这里讨论的「项目」是指一个单独的服务。单个项目的框架基本是Spring+MyBatis,具体版本如下:
Spring 3.2.9/4.3.5 + Mybatis 3.2.6 + mybatis-spring 1.2.2 + mysql connector 5.1.20 + commons-dbcp 1.4
与MyBatis和事务相关的配置如下:
//代码1 <!-- bean#1--> <bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close"> <!-- 一些数据库信息配置--> <!-- 一些DBCP连接池配置 --> //在这里设置是否自动提交 <property name="defaultAutoCommit" value="${dbcp.defaultAutoCommit}" /> </bean> <!-- bean#2--> <bean id="sqlSessionFactory" class="org.mybatis.spring.SqlSessionFactoryBean"> <property name="dataSource" ref="dataSource" /> <property name="mapperLocations" value="classpath*:path/to/mapper/**/*.xml" /> </bean> <!-- bean#3 --> <bean id="transactionManager" class="org.springframework.jdbc.datasource.DataSourceTransactionManager"> <property name="dataSource" ref="dataSource" /> </bean> <!-- bean#4--> <bean class="org.mybatis.spring.mapper.MapperScannerConfigurer"> <property name="basePackage" value=".path.to.mapper" /> <property name="sqlSessionFactoryBeanName" value="sqlSessionFactory"/> </bean> <!-- bean5 --> <tx:annotation-driven transaction-manager="transactionManager" />复制代码
一倍的时间差挺严重的,平均到每次调用,正常的大约在6到10几 ms
,慢的要近20 ms
,由于调用次数很多,导致整体性能会有很大的差别。经过仔细比对这几个项目,发现DAO执行慢的项目的数据源配置(bean#1)中 defaultAutoCommit
的配置都是 false
。而且将此配置改为 true
之后就恢复了正常。
由此推断是在MyBatis在执行「非自动提交」语句时,进行等待,或者多提交了一次,导致实际调用数据库API次数增多。但是这个推断也有个问题,由于整个项目是在Spring环境中运行的,而且也开启了Spring的事务管理,所以还是需要详细的看一下MyBatis到底是如何装配DAO方法与管理事务的,才能彻底解开谜团。
首先写一个Service,其中调用了同一个mapper类的两个方法分别2次, insertModelList()
会在数据库中插入两条记录, delModels()
方法会删除这两条记录,代码如下:
//代码2 //@Transactional public void testIS(){ List<Model> models= new ArrayList<>(); //省略一些数据工作。。。 modelMapper.insertModelList(50001l, models); modelMapper.delModels(50001); if (CollectionUtils.isNotEmpty(models)) modelMapper.insertModelList(50001, models); modelMapper.delModels(50001); } public void testOther(){ System.out.println("加载类:"); System.out.println(modelMapper.getClass().getClassLoader()); modelMapper.delModels(50001); }复制代码
实际项目中使用cat来进行执行时间的统计,这里也仿照cat,使用一个单独的AOP类实现时间的计算:
//代码3 public class DaoTimeAdvice { private long time = 0; private long num = 0; public Object calcTime(ProceedingJoinPoint joinPoint) throws Throwable { long then = System.nanoTime(); Object object = joinPoint.proceed(); long now = System.nanoTime(); setTime(getTime() + (now-then)); setNum(getNum() + 1); return object; } //省略getter & setter。。。 public void printInfo() { System.out.println("总共次数:" + num); System.out.println("总共时间:" + time); System.out.println("平均时间:" + time / num); } }复制代码
测试代码:
//代码4 public static void test(){ System.out.println(new SimpleDateFormat("[yyyy-MM-dd HH:mm:ss]").format(new Date()) + " 开始测试!"); for (int i = 0; i < TEST_NUM; i++) { ItemStrategyServiceTest ist = (ItemStrategyServiceTest) context.getBean("isTS"); ist.testIS(); if (i % 1000 == 0) { System.out.println("1000次"); } } DaoTimeAdvice ad = (DaoTimeAdvice) context.getBean("daoTimeAdvice"); ad.printInfo(); ItemStrategyServiceTest ist = (ItemStrategyServiceTest) context.getBean("isTS"); ist.testOther(); System.exit(1); }复制代码
测试结果:
defaultAutoCommit |
循环次数 | 共消耗时间(ns) | 平均时间(ns) |
---|---|---|---|
17831088316 | |||
17881589992 | |||
27280458229 | |||
27237413893 |
defaultAutoCommit为 false
时的执行时间是 true
的近1.5倍,并没有重现2倍的时间消耗,估计是在cat统计或者其他AOP方法的执行时还有其他消耗,从而扩大了 false
和 true
之间的区别。
按照第一节中的配置文件,整个MyBatis中DAO的bean的装配应该是这样的:
dataSource
。 这个bean很简单,就是实例化并注册到Spring的上下文中。
dataSource
来创建 sqlSessionFactory
(bean#2),这个bean创建时会扫描MyBatis的语句映射文件并解析。 在MyBatis中,真正的数据库读写操作是通过SqlSession的实例来实现的,而SqlSession要通过SQLSessionFactory来管理。这里的 org.mybatis.spring.SqlSessionFactoryBean
实现了FactoryBean类(这个类比较特殊,与主题无关,这里不再赘述),Spring会从这个bean中会获取真正的SQLSessionFactory的实例,源代码中显示,实际返回的对象是DefaultSqlSessionFactory的实例。
sqlSessionFactory
这个工厂类来创建mapper扫描器(bean#4),并创建含有DAO方法的实例。 为了让上层方法可以通过普通的方法调用来使用DAO方法,需要往Spring上下文里注册相应的bean,而在MyBatis的普通使用场景中是没有mapper的实现类的(具体的SQL语句映射通过注解或者XML文件来实现),只有接口,在MyBatis中这些接口是通过动态代理实现的。这里使用的类是 org.mybatis.spring.mapper.MapperScannerConfigurer
,它实现了 org.springframework.beans.factory.support.BeanDefinitionRegistryPostProcessor
接口,所以会在Spring中「所有的bean定义全部注册完成,但还没有实例化」之前,调用方法向Spring上下文注册mapper实现类(动态代理的对象)。具体代码如下:
//代码5 @Override public void postProcessBeanDefinitionRegistry(BeanDefinitionRegistry registry) { if (this.processPropertyPlaceHolders) { processPropertyPlaceHolders(); } ClassPathMapperScanner scanner = new ClassPathMapperScanner(registry); //设置一些属性 scanner.scan(StringUtils.tokenizeToStringArray(this.basePackage, ConfigurableApplicationContext.CONFIG_LOCATION_DELIMITERS)); } /** * Perform a scan within the specified base packages. * @param basePackages the packages to check for annotated classes * @return number of beans registered */ public int scan(String... basePackages) { int beanCountAtScanStart = this.registry.getBeanDefinitionCount(); doScan(basePackages); // Register annotation config processors, if necessary. if (this.includeAnnotationConfig) { AnnotationConfigUtils.registerAnnotationConfigProcessors(this.registry); } return (this.registry.getBeanDefinitionCount() - beanCountAtScanStart); }复制代码
在源代码里可以看到,真正的mapper实现类是 org.mybatis.spring.mapper.MapperFactoryBean
,具体的逻辑在方法 org.mybatis.spring.mapper.ClassPathMapperScanner.processBeanDefinitions(Set
里。最后,每一个方法的执行,最终落入了 org.mybatis.spring.SqlSessionTemplate
的某个方法中,并被如下这个拦截器拦截:
//代码6 /** * Proxy needed to route MyBatis method calls to the proper SqlSession got * from Spring's Transaction Manager * It also unwraps exceptions thrown by {@code Method#invoke(Object, Object...)} to * pass a {@code PersistenceException} to the {@code PersistenceExceptionTranslator}. */ private class SqlSessionInterceptor implements InvocationHandler { @Override public Object invoke(Object proxy, Method method, Object[] args) throws Throwable { SqlSession sqlSession = getSqlSession( SqlSessionTemplate.this.sqlSessionFactory, SqlSessionTemplate.this.executorType, SqlSessionTemplate.this.exceptionTranslator); try { Object result = method.invoke(sqlSession, args); if (!isSqlSessionTransactional(sqlSession, SqlSessionTemplate.this.sqlSessionFactory)) { // force commit even on non-dirty sessions because some databases require // a commit/rollback before calling close() sqlSession.commit(true); } return result; } catch (Throwable t) { //省略一些错误处理 throw unwrapped; } finally { if (sqlSession != null) { closeSqlSession(sqlSession, SqlSessionTemplate.this.sqlSessionFactory); } } } }复制代码
从源代码中知道真正的SqlSessionFactory使用的是 org.apache.ibatis.session.defaults.DefaultSqlSessionFactory
的实例,同时,事务管理使用 org.mybatis.spring.transaction.SpringManagedTransactionFactory
。但是在代码1的配置中,还添加了Spring事务管理的配置,就是在某个Service方法(或某个其他可被扫描到的方法)上加上 @Transactional
注解,那么Spring的事务管理会自动创建事务,那么它和MyBatis的事务之间是怎么协作的呢?
可以看到在代码6中的方法 isSqlSessionTransactional()
,它会返回上层代码中是否有Spring的事务,如果有,将不会执行下边的 commit()
。在我的项目中的实际情况是没有Spring事务,所以肯定是走到了下面的 commit()
,这个方法最终落到了 SpringManagedTransactionFactory
中的 commit()
,看代码:
//代码7 private void openConnection() throws SQLException { this.connection = DataSourceUtils.getConnection(this.dataSource); this.autoCommit = this.connection.getAutoCommit(); this.isConnectionTransactional = DataSourceUtils.isConnectionTransactional(this.connection, this.dataSource); } public void commit() throws SQLException { if (this.connection != null && !this.isConnectionTransactional && !this.autoCommit) { if (LOGGER.isDebugEnabled()) { LOGGER.debug("Committing JDBC Connection [" + this.connection + "]"); } this.connection.commit(); } }复制代码
可以看到,此处是否要执行 commit()
操作是由3个变量决定的,如果DataSource的 autoCommit
是 false
,则其结果一定为 true
,控制台也会看到一行日志: Committing JDBC Connection [xxxxxx]
,刚好与项目中遇到的情况相同。这个提交动作是需要和数据库交互的,比较耗时。
由上一节分析得出,造成DAO方法执行时间变长的原因是会多执行一次提交,那么如果上层方法被Spring事务管理器托管(或者数据源的 defaultAutoCommit
为 true
,这个条件已经在刚开始的问题重现被验证),则不会执行MyBatis的提交动作,DAO方法应该相应的执行时间会变短。于是将Service方法加上 @transactional
注解,分别测试 true
和 false
的情况。结果:
可以看到执行的时间已经基本接近,由此基本可以确定是这个原因造成的。这里仍然有几个疑点,尤其是问题重现时没有出现2倍的时间消耗,如果你有别的想法,也欢迎提出来讨论。