• New Feature
  • Status: Resolved
  • 2 Major
  • Resolution: Won't Fix
  • ehcache
  • serverteam
  • Reporter: bountico
  • February 07, 2013
  • 0
  • Watchers: 5
  • December 11, 2013
  • December 11, 2013

Description

Overview:

From various bits of evidence I’ve observed, in 2.6.0 (at least) it looks like a shutdown hook is being registered automatically and that EhCache is shutting itself down independently of whatever else the application might be trying to do. From the documentation, this behaviour has changed from 2.4, where the hook could be enabled but was off by default:

http://www.ehcache.org/documentation/2.4/user-guide/shutdown#the-shutdown-hook

Iin my testing, setting net.sf.ehcache.enableShutdownHook=false had no (obvious) effect (in 2.6.0).

To support environments where the application is using a hook to shut itself and its resources down gracefully (either directly or indirectly via a container), it seems that EhCache should provide a switch/option (such as it did in earlier releases) to disable automated cleanup. Then disabled, EhCache would on rely on the application to indicate (by calling the shutdown method on the CacheManagers) that is it through using the caches.

Background:

I noticed the following messages appearing in the log regarding EhCache resources being shutdown, regardless of whether the CacheManager.shutdown was being call explicitly or not:

20:17:54.894 [Thread-2] DEBUG o.t.modules.ehcache.LocalVMResources - Unregistering Cache with name: local-shadow-cache-for-TestCache-uuid-mwright-Precision-M4700/127.0.1.1-8b2e1497-a1a5-4004-91a2-d55a5ff753cc 20:17:54.894 [Thread-21] INFO o.t.m.e.s.s.EhcacheSMLocalStore - Ignoring getOffHeapSize as inner cache is not alive. 20:17:54.899 [Thread-21] INFO EhCacheTest - Cache statistics: Total [ 14496], In memory [ 0], evictions [0] 2013-02-06 20:17:55,789 INFO - Channel ChannelID=[19] closed. 20:17:55.894 [Out of band notifier - 0] INFO n.s.e.terracotta.TerracottaClient - Thread [Out of band notifier - 0] [cacheManager: ‘EhCacheTest’]: ClusterNode [id=ClientID[19]] went offline (currentNode=ClientID[19]) 20:17:55.895 [Out of band notifier - 1] INFO n.s.e.terracotta.TerracottaClient - Thread [Out of band notifier - 1] [cacheManager: ‘EhCacheTest’]: ClusterNode [id=ClientID[19]] left the cluster (currentNode=ClientID[19])

I discovered, quite accidentally, that indeed a shutdown hook was being registered by EhCache, when my test harness exited during start up, causing this stack trace to be generated:

java.lang.IllegalStateException: Shutdown in progress at java.lang.ApplicationShutdownHooks.add(ApplicationShutdownHooks.java:39) at java.lang.Runtime.addShutdownHook(Runtime.java:192) at com.tc.util.CommonShutDownHook.addShutdownHook(CommonShutDownHook.java:49) at com.tc.object.DistributedObjectClient.setLoggerOnExit(DistributedObjectClient.java:1089) at com.tc.object.DistributedObjectClient.start(DistributedObjectClient.java:839) at com.tc.object.bytecode.ManagerImpl$2.execute(ManagerImpl.java:284) at com.tc.lang.StartupHelper.startUp(StartupHelper.java:39) at com.tc.object.bytecode.ManagerImpl.startClient(ManagerImpl.java:302) at com.tc.object.bytecode.ManagerImpl.init(ManagerImpl.java:212) at com.tc.object.bytecode.ManagerImpl.init(ManagerImpl.java:194) at com.tc.object.bytecode.hook.impl.DSOContextImpl.createStandaloneContext(DSOContextImpl.java:186) at com.terracotta.express.StandaloneL1Boot.call(StandaloneL1Boot.java:211) at com.terracotta.express.ClientImpl.(ClientImpl.java:369) at com.terracotta.express.ClientFactoryImpl.newClient(ClientFactoryImpl.java:286) at com.terracotta.express.ClientFactoryImpl.createClient(ClientFactoryImpl.java:279) at com.terracotta.express.ClientFactoryImpl.createDedicatedRejoinClient(ClientFactoryImpl.java:170) at org.terracotta.express.ClientFactoryExtras.createDedicatedRejoinClient(ClientFactoryExtras.java:40) at net.sf.ehcache.terracotta.StandaloneTerracottaClusteredInstanceFactory.(StandaloneTerracottaClusteredInstanceFactory.java:35) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) at java.lang.reflect.Constructor.newInstance(Constructor.java:513) at net.sf.ehcache.util.ClassLoaderUtil.createNewInstance(ClassLoaderUtil.java:92) at net.sf.ehcache.terracotta.TerracottaClusteredInstanceHelper.newClusteredInstanceFactory(TerracottaClusteredInstanceHelper.java:176) at net.sf.ehcache.terracotta.TerracottaClient.createNewClusteredInstanceFactory(TerracottaClient.java:186) at net.sf.ehcache.terracotta.TerracottaClient.access$1500(TerracottaClient.java:52) at net.sf.ehcache.terracotta.TerracottaClient$RejoinWorker.doRejoin(TerracottaClient.java:430) at net.sf.ehcache.terracotta.TerracottaClient$RejoinWorker.run(TerracottaClient.java:338) at java.lang.Thread.run(Thread.java:662)

Comments

Fiona OShea 2013-02-11

Can you evaluate whether this is an option? thanks

Chris Dennis 2013-04-10

The “net.sf.ehcache.enableShutdownHook” property in Ehcache does work in 2.6.x. The shutdown hook seen here isn’t an Ehcache shutdown hook - it’s a shutdown hook registered by the Terracotta client. Whether the presence of this shutdown hook has any impact on the Ehcache shutdown behavior (with or without it’s own shutdown hook registered) I don’t know. I’m assigning this to platform team to get their input on the status of the TC client shutdown hook.

Mitch Wright 2013-04-10

I re-ran my test this morning and, based on the output I am seeing in the log, I do not believe the property is working:

java -Dnet.sf.ehcache.enableShutdownHook=false EhCacheTest … 2013-04-10 09:04:25,494 (main) DEBUG [n.sf.ehcache.config.ConfigurationFactory] Configuring ehcache from InputStream 2013-04-10 09:04:25,534 (main) DEBUG [net.sf.ehcache.config.BeanHandler] Ignoring ehcache attribute xmlns:xsi 2013-04-10 09:04:25,535 (main) DEBUG [net.sf.ehcache.config.BeanHandler] Ignoring ehcache attribute xsi:noNamespaceSchemaLocation 2013-04-10 09:04:25,604 (main) DEBUG [net.sf.ehcache.CacheManager] Creating new CacheManager with InputStream 2013-04-10 09:04:25,611 (main) DEBUG [net.sf.ehcache.util.PropertyUtil] propertiesString is null. 2013-04-10 09:04:25,649 (main) INFO [n.sf.ehcache.terracotta.TerracottaClient] Thread [main] [cacheManager: ‘EhCacheTest’]: Creating new ClusteredInstanceFactory 2013-04-10 09:04:25,665 (Rejoin Worker Thread [cacheManager: EhCacheTest]) INFO [n.sf.ehcache.terracotta.TerracottaClient] Thread [Rejoin Worker Thread [cacheManager: EhCacheTest]] [cacheManager: ‘EhCacheTest’]: Rejoin worker waiting until rejoin requested (PS Perm Gen : 8M / 82M)… 2013-04-10 09:04:27,209 INFO - Terracotta 3.7.0, as of 20120717-133013 (Revision unknown-20453 by [email protected] from 3.7.0) 2013-04-10 09:04:28,141 INFO - Successfully loaded base configuration from server at ‘tcserver01.local-paymo.net:9510’. 2013-04-10 09:04:28,403 INFO - Successfully loaded base configuration from file at ‘/tmp/tc-config5829493315782367761.xml’. 2013-04-10 09:04:28,478 INFO - Log file: ‘/home/xxx/paymo/EhCacheTest/target/state/logs/terracotta-client.log’. 2013-04-10 09:04:31,398 INFO - Connection successfully established to server at 192.168.56.10:9510 2013-04-10 09:04:31,891 (main) INFO [n.sf.ehcache.terracotta.TerracottaClient] Thread [main] [cacheManager: ‘EhCacheTest’]: Registered interest for rejoin, current node: ClientID[14] 2013-04-10 09:04:31,897 (WorkerThread(cluster_events_stage, 0)) INFO [n.sf.ehcache.terracotta.TerracottaClient] Thread [WorkerThread(cluster_events_stage, 0)] [cacheManager: ‘EhCacheTest’]: ClusterNode [id=ClientID[14]] joined the cluster (currentNode=ClientID[14]) 2013-04-10 09:04:31,897 (WorkerThread(cluster_events_stage, 0)) INFO [n.sf.ehcache.terracotta.TerracottaClient] Thread [WorkerThread(cluster_events_stage, 0)] [cacheManager: ‘EhCacheTest’]: ClusterNode [id=ClientID[14]] became online (currentNode=ClientID[14]) 2013-04-10 09:04:31,906 (main) DEBUG [n.sf.ehcache.config.ConfigurationHelper] No CacheManagerEventListenerFactory class specified. Skipping… 2013-04-10 09:04:31,959 (main) DEBUG [net.sf.ehcache.Cache] No BootstrapCacheLoaderFactory class specified. Skipping… 2013-04-10 09:04:31,961 (main) DEBUG [net.sf.ehcache.Cache] CacheWriter factory not configured. Skipping… 2013-04-10 09:04:31,966 (main) DEBUG [n.sf.ehcache.config.ConfigurationHelper] No CacheExceptionHandlerFactory class specified. Skipping… 2013-04-10 09:04:31,967 (main) DEBUG [net.sf.ehcache.Cache] No BootstrapCacheLoaderFactory class specified. Skipping… 2013-04-10 09:04:31,967 (main) DEBUG [net.sf.ehcache.Cache] CacheWriter factory not configured. Skipping… 2013-04-10 09:04:31,967 (main) DEBUG [n.sf.ehcache.config.ConfigurationHelper] No CacheExceptionHandlerFactory class specified. Skipping… 2013-04-10 09:04:32,029 (NonStopCache [EhCacheTest] Executor Thread-1 for ‘main’) DEBUG [o.t.modules.ehcache.LocalVMResources] Registering CacheManager with uuid: EhCacheTest, cacheManager: EhCacheTest … 2013-04-10 08:50:11,743 (Thread-20) INFO [EhCacheTest] 04-10_08:50:11.743: Key [Thread-20 504], Pre-get [ true: 16893 us], Put [ 12703 us], Post-get [ true: 1179 us], Total [ 6000], In memory [ 172], evictions [0] 2013-04-10 08:50:11,753 (Thread-19) INFO [EhCacheTest] 04-10_08:50:11.752: Key [Thread-19 1768], Pre-get [ true: 22328 us], Put [ 13867 us], Post-get [ true: 1105 us], Total [ 6000], In memory [ 172], evictions [0] 2013-04-10 08:50:11,758 (Thread-21) INFO [EhCacheTest] 04-10_08:50:11.758: Key [Thread-21 1670], Pre-get [ true: 23039 us], Put [ 17201 us], Post-get [ true: 1108 us], Total [ 6000], In memory [ 172], evictions [0] 2013-04-10 08:50:11,759 (Thread-20) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-20 1790 2013-04-10 08:50:11,770 (Thread-20) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-20 1790 2013-04-10 08:50:11,773 (Thread-19) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-19 1581 2013-04-10 08:50:11,776 (Thread-21) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-21 145 2013-04-10 08:50:11,794 (Thread-21) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-21 145 2013-04-10 08:50:11,795 (Thread-19) DEBUG [net.sf.ehcache.Cache] Cache: TestCache store hit for Thread-19 1581 ^C2013-04-10 08:50:11,842 (Thread-2) DEBUG [o.t.modules.ehcache.LocalVMResources] Unregistering Cache with name: local-shadow-cache-for-TestCache-uuid-xxx-M4700/127.0.1.1-528e3001-7215-4b0f-b2f9-3add1e81df2f 2013-04-10 08:50:11,844 (Thread-2) DEBUG [o.t.modules.ehcache.LocalVMResources] Unregistering Cache with name: local-shadow-cache-for-LockCache-uuid-xxx-M4700/127.0.1.1-b3217c4a-140d-4aca-b21a-398169f46b64 2013-04-10 08:50:11,867 (WorkerThread(local_cache_transaction_complete_stage, 7, 0)) INFO [o.t.m.e.s.servermap.EhcacheSMLocalStore] Ignoring put for key: ObjectID=[1471175], value: Thread-19 1581 as inner cache is not alive. …

Note that in my code I an not doing anything explicit to shut down the cache.

Mitch Wright 2013-12-11

On further reflection, I think this behavior is OK. If the application is going to explicitly shut down the cache manager, it would probably do so either in response to receiving a signal (QUIT, for instance) or through some other trigger.

Please close this ticket.

Mitch Wright 2013-12-11

My previous comment should have read …in response to receiving a signal (SIGINT or SIGTERM, presumably)…

I did a little more research on this. If the Terracotta client hooks have any impact on the EhCache shut down behavior, there should be an option to disable them so as not to negatively impact the application’s shut down process.

Tim Wu 2013-12-11

As Chris mentioned, that shutdown hook is registered by TSA client. Shutdown hooks all pretty much run simultaneously so doing anything in a shutdown hook races with the TSA client one.

As you said, the way to do this would be for the app to do its cleanup before exiting.