Andrew,
This is an interesting discovery. Apparently, the
DefaultTicketRegistryCleaner, as it's iterating through every ticket in
the database, attempted to delete a ticket whose state has in the
meantime changed (or was it deleted?) My simple-minded initial
reaction was to change the transaction isolation level, but that could
result in blocking other ticket operations for excessively long time.
Another approach would be to write a custom JpaTicketRegistryCleaner
that would cleverly, if at all possible, retrieve only expired
tickets. I don't have enough spare cycles at the moment to consider
the feasibility of such an approach.
This brings up another potential issue. I think that every distributed
TicketRegistry implementation may be subject to this issue. That is,
concurrent updates to a ticket from multiple threads or, more
challengingly, from multiple JVMs. With DefaultTicketRegistry, this is
nicely addressed by using ConcurrentHashMap. I could not tell what
behavior other distributed TicketRegistry implementations have.
Perhaps Hibernate gives us a hint here: the optimistic locking feature
should be considered for all distributed TicketRegistry
implementations. If the registry cleaner detects an update to stale
data, the cleaner could ignore this ticket and perhaps pick it up on
the next pass.
Adam
Andrew Bruno wrote:
And I also see these errors in logs
ERROR 2008-10-27 04:53:44,833 [DefaultQuartzScheduler_Worker-8]
org.quartz.core.ErrorLogger - Job
(DEFAULT.jobDetailTicketRegistryCleaner threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
[See nested exception:
org.springframework.scheduling.quartz.JobMethodInvocationFailedException:
Invocation of method 'clean' on target class [class $Proxy72] failed;
nested exception is
org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException:
Batch update returned unexpected row count from update [0]; actual row
count: 0; expected: 1; nested exception is
org.hibernate.StaleStateException: Batch update returned unexpected row
count from update [0]; actual row count: 0; expected: 1]
at org.quartz.core.JobRunShell.run(JobRunShell.java:214)
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
* Nested Exception (Underlying Cause) ---------------
org.springframework.scheduling.quartz.JobMethodInvocationFailedException:
Invocation of method 'clean' on target class [class $Proxy72] failed;
nested exception is
org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException:
Batch update returned unexpected row count from update [0]; actual row
count: 0; expected: 1; nested exception is
org.hibernate.StaleStateException: Batch update returned unexpected row
count from update [0]; actual row count: 0; expected: 1
at
org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:269)
at
org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
at
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
Caused by:
org.springframework.orm.hibernate3.HibernateOptimisticLockingFailureException:
Batch update returned unexpected row count from update [0]; actual row
count: 0; expected: 1; nested exception is
org.hibernate.StaleStateException: Batch update returned unexpected row
count from update [0]; actual row count: 0; expected: 1
at
org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:657)
at
org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:95)
at
org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:212)
at
org.springframework.orm.jpa.JpaAccessor.translateIfNecessary(JpaAccessor.java:152)
at
org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:189)
at
org.springframework.orm.jpa.JpaTemplate.executeFind(JpaTemplate.java:151)
at
org.springframework.orm.jpa.JpaTemplate.findByNamedParams(JpaTemplate.java:325)
at
org.jasig.cas.ticket.registry.JpaTicketRegistry.deleteTicketAndChildren(JpaTicketRegistry.java:70)
at
org.jasig.cas.ticket.registry.JpaTicketRegistry.deleteTicket(JpaTicketRegistry.java:63)
at
org.jasig.cas.ticket.registry.support.DefaultTicketRegistryCleaner.clean(DefaultTicketRegistryCleaner.java:73)
at sun.reflect.GeneratedMethodAccessor94.invoke(Unknown
Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at $Proxy72.clean(Unknown Source)
at sun.reflect.GeneratedMethodAccessor92.invoke(Unknown
Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:276)
at
org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:260)
... 3 more
Caused by: org.hibernate.StaleStateException: Batch update returned
unexpected row count from update [0]; actual row count: 0; expected: 1
at
org.hibernate.jdbc.Expectations$BasicExpectation.checkBatched(Expectations.java:61)
at
org.hibernate.jdbc.Expectations$BasicExpectation.verifyOutcome(Expectations.java:46)
at
org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:24)
at
org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2520)
at
org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2697)
at
org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:74)
at
org.hibernate.engine.ActionQueue.execute(ActionQueue.java:250)
at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:234)
at
org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:146)
at
org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
at
org.hibernate.event.def.DefaultAutoFlushEventListener.onAutoFlush(DefaultAutoFlushEventListener.java:41)
at
org.hibernate.impl.SessionImpl.autoFlushIfRequired(SessionImpl.java:969)
at
org.hibernate.impl.SessionImpl.list(SessionImpl.java:1114)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:79)
at
org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:66)
at
org.springframework.orm.jpa.JpaTemplate$10.doInJpa(JpaTemplate.java:333)
at
org.springframework.orm.jpa.JpaTemplate.execute(JpaTemplate.java:184)
... 23 more
On Tue, Oct 28, 2008 at 1:50 PM, Andrew
Bruno <[EMAIL PROTECTED]>
wrote:
Hello
all,
We are using DB persistance for TicketGrantingTIcket table, and have
managed to setup redundant load balanced servers successfully inc
Single Sign Out.
During load testing we noticed a few spikes every 83 minutes (5,000,000
msecs) or so.
It appears that this query is being executed
select ticketgran0_.ID as ID2_, ticketgran0_.NUMBER_OF_TIMES_USED as
NUMBER2_2_, ticketgran0_.CREATION_TIME as CREATION3_2_,
ticketgran0_.EXPIRATION_POLICY as EXPIRATION4_2_,
ticketgran0_.LAST_TIME_USED as LAST5_2_,
ticketgran0_.PREVIOUS_LAST_TIME_USED as PREVIOUS6_2_,
ticketgran0_.ticketGrantingTicket_ID as ticketG10_2_,
ticketgran0_.AUTHENTICATION as AUTHENTI7_2_, ticketgran0_.EXPIRED as
EXPIRED2_, ticketgran0_.SERVICES_GRANTED_ACCESS_TO as SERVICES9_2_ from
TICKETGRANTINGTICKET ticketgran0_
and there is no where clause.
Looking through the code, I believe the culprit is
https://www.ja-sig.org/svn/cas3/tags/cas-3-2-2-rc1/cas-server-core/src/main/java/org/jasig/cas/ticket/registry/support/DefaultTicketRegistryCleaner.java
i.e. the clean method:
log
.info("Starting cleaning of expired tickets from ticket
registry at ["
+ new Date() + "]");
--> GETS ALL TICKETS (returned 1500 rows in one of our tests)
ticketsInCache = this.ticketRegistry.getTickets();
for (final Ticket ticket : ticketsInCache) {
if (ticket.isExpired()) {
ticketsToRemove.add(ticket);
}
}
log.info(ticketsToRemove.size()
+ " found to be removed. Removing now.");
for (final Ticket ticket : ticketsToRemove) {
this.ticketRegistry.deleteTicket(ticket.getId());
}
log
.info("Finished cleaning of expired tickets from ticket
registry at ["
+ new Date() + "]");
Is there any reason why we need to get all the tickets, and the loop
through them?
If I was to write my own DB cleaner, how do I decide what the
expiration policy is?
Is there more to it that meets the eye?
Many thanks
Andrew
_______________________________________________
Yale CAS mailing list
[email protected]
http://tp.its.yale.edu/mailman/listinfo/cas
|
begin:vcard
fn:Adam Rybicki
n:Rybicki;Adam
org:Unicon, Inc.;Professional Services
adr:Suite 113;;3140 North Arizona Avenue;Chandler;AZ;85225;United States
email;internet:[EMAIL PROTECTED]
tel;work:+1-480-558-2400
tel;home:+1-310-265-8286
tel;cell:+1-310-980-2758
x-mozilla-html:FALSE
url:http://www.unicon.net/
version:2.1
end:vcard
smime.p7s
Description: S/MIME Cryptographic Signature
_______________________________________________
Yale CAS mailing list
[email protected]
http://tp.its.yale.edu/mailman/listinfo/cas
