[jboss-jira] [JBoss JIRA] (WFLY-9631) "Failed to reinstate timer" warning is shown when creating large number of EJB timers

[Cheng Fang (Jira)]

    [ https://issues.jboss.org/browse/WFLY-9631?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13751089#comment-13751089 ] 

Cheng Fang commented on WFLY-9631:
----------------------------------

wrt timers.remove(..) call in DatabaseTimerPersistence, this is to remove any timers that are in the cache, but not in the timer data store.  For example, this can happen when a timer is cancelled from another server instance, and thus removed from timer db, and so the residual timer object needs to be cleared.

I think this could be a thread synchronization issue, e.g., DatabaseTimerPersistence.addTimer(...) method adds timer object to cache, and then save to db.  The 2 parts are not guarded as one single unit, and therefore some valid timers may be in cache, but not in db yet.  If in the middle the refresher task gets to run, it will try to remove the newly-added timers in cache, since they are not present in db. This removal may explain why certain timers never take effect.

Why the warning of duplicate timer ids?  My guess is that during new timer creation and start, the timer resource is already added to management model.  As explained above, some new timers are removed from DatabaseTimerPersistence cache, but the block that saves them to db eventually gets to run and they are persisted into db.  When it comes next timer refresh, they are deemed as timers that need to be added since they are present in db but not in cache.  Hence the duplicate timer resource warning.

If we set refresh interval to sufficiently long, the state of the cache and db are already consistent by the time the first refresh kicks in, and so there is no extra removal, or the additional adding.

> "Failed to reinstate timer" warning is shown when creating large number of EJB timers
> -------------------------------------------------------------------------------------
>
>                 Key: WFLY-9631
>                 URL: https://issues.jboss.org/browse/WFLY-9631
>             Project: WildFly
>          Issue Type: Bug
>          Components: EJB
>         Environment: EAP 7.0.8.GA
> Oracle 12 c
> [Configuration of datasources|https://github.com/MarianMacik/timers-testing/blob/c7dde64d27623949f3cafd0e11828bce8a93de21/jboss-eap-7.0/standalone/configuration/standalone-full.xml#L142-L205] - XA Datasource for jBPM - our application - and a separate XA Datasource for EJB Timers in a different schema.
>            Reporter: Marian Macik
>            Assignee: Cheng Fang
>            Priority: Major
>         Attachments: WFLY-9631-reproducer.zip
>
>
> Hi, [~manovotn],
> as we discussed before, I am creating a JIRA for an issue I experienced when testing EJB Timers with jBPM.
> What I did was that I started a large number of processes with jBPM, let's say 10 000 and more. Each process contains a timer which jBPM will create an EJB Timer for. Each timer was configured to fire at exactly the same time, e.g. 12:00 PM. During the test I got this warning displayed about 5 times for each 10 000 timers created:
> {code:java}
> WARN  [org.jboss.as.ejb3] (Timer-1) WFLYEJB0161: Failed to reinstate timer 'kie-server.kie-server.EJBTimerScheduler' (id=09afab21-6b0f-41b0-9338-403b4a12e507) from its persistent state: java.lang.IllegalStateException: WFLYCTL0075: Duplicate resource 09afab21-6b0f-41b0-9338-403b4a12e507
>     at org.jboss.as.controller.registry.AbstractModelResource$DefaultResourceProvider.register(AbstractModelResource.java:290)
>     at org.jboss.as.controller.registry.AbstractModelResource.registerChild(AbstractModelResource.java:169)
>     at org.jboss.as.ejb3.subsystem.deployment.TimerServiceResource.timerCreated(TimerServiceResource.java:193)
>     at org.jboss.as.ejb3.timerservice.TimerServiceImpl.registerTimerResource(TimerServiceImpl.java:1094)
>     at org.jboss.as.ejb3.timerservice.TimerServiceImpl.startTimer(TimerServiceImpl.java:767)
>     at org.jboss.as.ejb3.timerservice.TimerServiceImpl$TimerRefreshListener.timerAdded(TimerServiceImpl.java:1235)
>     at org.jboss.as.ejb3.timerservice.persistence.database.DatabaseTimerPersistence$RefreshTask.run(DatabaseTimerPersistence.java:820)
>     at java.util.TimerThread.mainLoop(Timer.java:555)
> at java.util.TimerThread.run(Timer.java:505)
> {code}
> The result of these warnings was that when I had only one EAP instance to fire these timers, it wouldn't fire exactly the timers with ids that were in those warnings, e.g. if it was id=09afab21-6b0f-41b0-9338-403b4a12e507 then this timer wouldn't fire. I had waited for minutes to be sure there is another tick of a refresh interval (configured to 1 min) but nothing happened. But when I started the second EAP instance, they were immediately picked up by that instance and fired. It seems that if there is this warning on a particular instance, the instance won't pick up the timer whatsoever. They will be picked up only by some other instances if there are any. With 2 EAP instances there were warnings too, but all timers fired since I guess affected timers were picked up each time by the other instance.
> Another interesting observation is that when I configured a refresh interval to be shorter, e.g. 5 seconds, these warnings were showing up almost every 5 seconds. When I set it to 30 minutes, I didn't get warnings at all, since all timers fired earlier than a refresh occurred.
> So I think it has something to do with refresh interval.
> Can you please have a look at it? For further configuration details, check the Environment field.
> Thank you very much!
> Marian Macik



--
This message was sent by Atlassian Jira
(v7.12.1#712002)