线上crm导出一份报表时长时没反应，日志一看：
1 2017-09-25 13:45:58 [http-nio-8080-exec-60] ERROR: jdbc.sqltiming#exceptionOccured : 1469. PreparedStatement.executeBatch() FAILED! batching 3 statements: 1: update uwc_applyloan_attach set ATTACH_ID=112103 where ID=44602 2: 2 update uwc_applyloan_attach set ATTACH_ID=112106 where ID=44603 3: update uwc_applyloan_attach 3 set ATTACH_ID=112109 where ID=44604 4 {FAILED after 135899 msec} 5 java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction 6 at com.mysql.jdbc.SQLError.createBatchUpdateException(SQLError.java:1167) 7 at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1778) 8 at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1262) 9 at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:970) 10 at net.sf.log4jdbc.StatementSpy.executeBatch(StatementSpy.java:526) 11 at sun.reflect.GeneratedMethodAccessor387.invoke(Unknown Source) 12 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 13 at java.lang.reflect.Method.invoke(Method.java:601) 14 at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114) 15 at com.sun.proxy.$Proxy33.executeBatch(Unknown Source) 16 at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70) 17 at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268) 18 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268) 19 at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:185) 20 at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:321) 21 at org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:64) 22 at org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:1185) 23 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1261) 24 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102) 25 at com.upg.ucars.framework.base.AbstractHibernateDAO$1.doInHibernate(AbstractHibernateDAO.java:172) 26 at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:406) 27 at org.springframework.orm.hibernate3.HibernateTemplate.executeFind(HibernateTemplate.java:343) 28 at com.upg.ucars.framework.base.AbstractHibernateDAO.queryByParam(AbstractHibernateDAO.java:147) 29 at com.upg.ucars.framework.base.AbstractHibernateDAO.queryByParam(AbstractHibernateDAO.java:92) 30 at com.upg.tenant.yuntao.core.UwcApplyloanAttachDaoImpl.getByApplyId(UwcApplyloanAttachDaoImpl.java:19) 31 at com.upg.es.seal.core.EsSealServiceImpl.generateDownloadData(EsSealServiceImpl.java:568) 32 at com.upg.es.seal.core.EsSealServiceImpl$$FastClassByCGLIB$$f4dc2f5b.invoke(<generated>) 33 at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) 34 at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689) 35 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) 36 at org.springframework.aop.framework.adapter.ThrowsAdviceInterceptor.invoke(ThrowsAdviceInterceptor.java:124) 37 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 38 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110) 39 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 40 at org.springframework.aop.framework.adapter.ThrowsAdviceInterceptor.invoke(ThrowsAdviceInterceptor.java:124) 41 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 42 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110) 43 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 44 at org.springframework.aop.framework.adapter.ThrowsAdviceInterceptor.invoke(ThrowsAdviceInterceptor.java:124) 45 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 46 at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110) 47 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 48 at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90) 49 at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) 50 at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622) 51 at com.upg.es.seal.core.EsSealServiceImpl$$EnhancerByCGLIB$$1d4e14b1.generateDownloadData(<generated>)
UwcApplyloanAttachDaoImpl.getByApplyId(UwcApplyloanAttachDaoImpl.java:19)这句造成了锁超时，但奇怪的是这个是个查询语句。
分析了下Hibernate源码，原来在查询中还需要先Flush一下，看org.hibernate.impl.SessionImpl源码：
public List list(String query, QueryParameters queryParameters) throws HibernateException { errorIfClosed(); checkTransactionSynchStatus(); queryParameters.validateParameters(); HQLQueryPlan plan = getHQLQueryPlan( query, false ); autoFlushIfRequired( plan.getQuerySpaces() ); List results = CollectionHelper.EMPTY_LIST; boolean success = false; dontFlushFromFind++; //stops flush being called multiple times if this method is recursively called try { results = plan.performList( queryParameters, this ); success = true; } finally { dontFlushFromFind--; afterOperation(success); } return results; }
/** * detect in-memory changes, determine if the changes are to tables * named in the query and, if so, complete execution the flush */ protected boolean autoFlushIfRequired(Set querySpaces) throws HibernateException { errorIfClosed(); if ( ! isTransactionInProgress() ) { // do not auto-flush while outside a transaction return false; } AutoFlushEvent event = new AutoFlushEvent(querySpaces, this); AutoFlushEventListener[] autoFlushEventListener = listeners.getAutoFlushEventListeners(); for ( int i = 0; i < autoFlushEventListener.length; i++ ) { autoFlushEventListener[i].onAutoFlush(event); } return event.isFlushRequired(); }
org.hibernate.event.def.AbstractFlushingEventListener
protected void performExecutions(EventSource session) throws HibernateException { log.trace("executing flush"); try { session.getJDBCContext().getConnectionManager().flushBeginning(); // we need to lock the collection caches before // executing entity inserts/updates in order to // account for bidi associations session.getActionQueue().prepareActions(); session.getActionQueue().executeActions(); } finally { session.getJDBCContext().getConnectionManager().flushEnding(); } }
org.hibernate.jdbc.AbstractBatcher
public void executeBatch() throws HibernateException { if (batchUpdate!=null) { try { try { doExecuteBatch(batchUpdate); } finally { closeStatement(batchUpdate); } } catch (SQLException sqle) { throw JDBCExceptionHelper.convert( factory.getSQLExceptionConverter(), sqle, "Could not execute JDBC batch update", batchUpdateSQL ); } finally { batchUpdate=null; batchUpdateSQL=null; } } }
看到这里就明白了， doExecuteBatch(batchUpdate); 如果有待Flush的update操作存在，前面一次操作的长事务还没结束而同时另外一个长事务操作又开始了，到了getByApplyId这里又去更新同样的记录就得等待锁释放了