线上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这里又去更新同样的记录就得等待锁释放了