Can anybody shed some light on this, please? Any thoughts on where to look?
Geoff -----Original Message----- From: Geoff Whittaker [mailto:[email protected]] Sent: Monday, October 20, 2014 11:12 AM To: [email protected] Subject: [cas-user] CAS 3.5.2 - SQL Deadlocks - Not cleanup related Configuration: 2 - CAS 3.5.2 frontends on Tomcat 7 behind a netscaler load balancer 1 - Shared MS SQL server 2014 database w/AlwaysOn using the MS JDBC driver v.4 for ticket and service registries I have built a load-balanced highly-available CAS cluster using SQL server and tomcat. The database is shared, meaning that both servers read/write from the same db. I have also enabled session replication in Tomcat. During my initial testing, the servers worked perfectly. Load was well distributed and individual CAS front-end failures were inconsequential. My problem came when we moved this configuration to production. Once under load, we started seeing DB deadlocks reported in the CAS.log. The deadlocks are happening frequently enough to be a problem, but not so frequently as to warrant the cluster's removal from service. I've investigated a couple of possibilities with no luck. --I had already created the indexes mentioned in the JPATicketRegistry page https://wiki.jasig.org/display/CASUM/JpaTicketRegistry back when I first built this out. --It's not the ticket cleaner process. I tried disabling that on both CAS front-ends and still got the deadlocks. --I thought perhaps it was an issue with the round-robin algorithm, but I found out we're using round-robin with Source-IP-hashing for session affinity. So, it shouldn't be an issue of TGT records not being committed before the ST requests come in from another server that reference them. I'm at a loss to determine the cause. Any input would be appreciated. Below, I have included an example of what we're seeing in the logs. 2014-10-20 11:09:13,328 ERROR [org.jasig.cas.ticket.registry.JpaTicketRegistry] - Error getting ticket TGT-9446-Y5yULrrCddmLP69Xv7ATBqQZGfsMdM2dNebAHSB9SBPVAiy2d3-02 from registry. javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: Transaction (Process ID 138) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1360) at org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:817) at org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:780) at sun.reflect.GeneratedMethodAccessor79.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:240) at com.sun.proxy.$Proxy32.find(Unknown Source) at org.jasig.cas.ticket.registry.JpaTicketRegistry.getRawTicket(JpaTicketRegistry.java:128) at org.jasig.cas.ticket.registry.JpaTicketRegistry.getTicket_aroundBody4(JpaTicketRegistry.java:122) at org.jasig.cas.ticket.registry.JpaTicketRegistry.getTicket_aroundBody5$advice(JpaTicketRegistry.java:57) at org.jasig.cas.ticket.registry.JpaTicketRegistry.getTicket(JpaTicketRegistry.java:1) at org.jasig.cas.ticket.registry.AbstractTicketRegistry.getTicket_aroundBody0(AbstractTicketRegistry.java:48) at org.jasig.cas.ticket.registry.AbstractTicketRegistry.getTicket_aroundBody1$advice(AbstractTicketRegistry.java:57) at org.jasig.cas.ticket.registry.AbstractTicketRegistry.getTicket(AbstractTicketRegistry.java:1) at sun.reflect.GeneratedMethodAccessor83.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:196) at com.sun.proxy.$Proxy33.getTicket(Unknown Source) at org.jasig.cas.CentralAuthenticationServiceImpl.destroyTicketGrantingTicket_aroundBody0(CentralAuthenticationServiceImpl.java:158) at org.jasig.cas.CentralAuthenticationServiceImpl.destroyTicketGrantingTicket_aroundBody1$advice(CentralAuthenticationServiceImpl.java:57) at org.jasig.cas.CentralAuthenticationServiceImpl.destroyTicketGrantingTicket(CentralAuthenticationServiceImpl.java:1) at sun.reflect.GeneratedMethodAccessor129.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:318) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80) at org.perf4j.aop.AbstractTimingAspect$1.proceed(AbstractTimingAspect.java:47) at org.perf4j.aop.AgnosticTimingAspect.runProfiledMethod(AgnosticTimingAspect.java:53) at org.perf4j.aop.AbstractTimingAspect.doPerfLogging(AbstractTimingAspect.java:45) at sun.reflect.GeneratedMethodAccessor60.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610) at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80) at com.github.inspektr.audit.AuditTrailManagementAspect.handleAuditTrail(AuditTrailManagementAspect.java:126) at sun.reflect.GeneratedMethodAccessor59.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610) at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) at com.sun.proxy.$Proxy46.destroyTicketGrantingTicket(Unknown Source) at org.jasig.cas.web.LogoutController.handleRequestInternal(LogoutController.java:83) at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153) at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882) at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:778) at javax.servlet.http.HttpServlet.service(HttpServlet.java:621) at javax.servlet.http.HttpServlet.service(HttpServlet.java:728) at org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody2(SafeDispatcherServlet.java:128) at org.jasig.cas.web.init.SafeDispatcherServlet.service_aroundBody3$advice(SafeDispatcherServlet.java:57) at org.jasig.cas.web.init.SafeDispatcherServlet.service(SafeDispatcherServlet.java:1) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.github.inspektr.common.web.ClientInfoThreadLocalFilter.doFilter(ClientInfoThreadLocalFilter.java:63) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:222) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:123) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:611) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:99) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:953) at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:680) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at org.apache.catalina.ha.tcp.ReplicationValve.invoke(ReplicationValve.java:335) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1023) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:589) at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:312) at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) Caused by: org.hibernate.exception.LockAcquisitionException: Transaction (Process ID 138) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. at org.hibernate.exception.internal.SQLStateConversionDelegate.convert(SQLStateConversionDelegate.java:139) at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110) at org.hibernate.engine.jdbc.internal.proxy.AbstractResultSetProxyHandler.continueInvocation(AbstractResultSetProxyHandler.java:108) at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81) at com.sun.proxy.$Proxy39.next(Unknown Source) at org.hibernate.loader.Loader.doQuery(Loader.java:848) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:289) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259) at org.hibernate.loader.Loader.loadEntity(Loader.java:2042) at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:82) at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:72) at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3710) at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:439) at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:420) at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:204) at org.hibernate.event.internal.DefaultLoadEventListener.lockAndLoad(DefaultLoadEventListener.java:361) at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:151) at org.hibernate.internal.SessionImpl.fireLoad(SessionImpl.java:992) at org.hibernate.internal.SessionImpl.access$1900(SessionImpl.java:170) at org.hibernate.internal.SessionImpl$IdentifierLoadAccessImpl.load(SessionImpl.java:2329) at org.hibernate.internal.SessionImpl.get(SessionImpl.java:947) at org.hibernate.ejb.AbstractEntityManagerImpl.find(AbstractEntityManagerImpl.java:790) ... 93 more Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Transaction (Process ID 138) was deadlocked on lock resources with another process and has been chosen as the deadlock victim. Rerun the transaction. at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:216) at com.microsoft.sqlserver.jdbc.SQLServerResultSet$FetchBuffer.nextRow(SQLServerResultSet.java:4853) at com.microsoft.sqlserver.jdbc.SQLServerResultSet.fetchBufferNext(SQLServerResultSet.java:1781) at com.microsoft.sqlserver.jdbc.SQLServerResultSet.next(SQLServerResultSet.java:1034) at com.mchange.v2.c3p0.impl.NewProxyResultSet.next(NewProxyResultSet.java:2859) at sun.reflect.GeneratedMethodAccessor23.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) at java.lang.reflect.Method.invoke(Unknown Source) at org.hibernate.engine.jdbc.internal.proxy.AbstractResultSetProxyHandler.continueInvocation(AbstractResultSetProxyHandler.java:104) ... 112 more -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user
