Ehcache losing objects

Question

I'm using Ehcache to cache objects that are very expensive to load in my application. On start-up I cache all the needed objects and they get refreshed once a day by a separate process.

However, it appears that shortly after I add objects to the cache, they disappear. Nothing is being reported as being evicted, but the objects aren't lasting in the cache for some reason. When I run ObjectLoader.loadCache() this is the output I'm receiving:

2012-09-01 17:25:37,121 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:25:37,121 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 0
2012-09-01 17:25:37,121 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 501
2012-09-01 17:26:17,271 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:26:17,271 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:26:17,274 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 501
2012-09-01 17:26:17,274 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:26:17,274 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 1
2012-09-01 17:26:17,274 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 518
2012-09-01 17:26:35,894 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:26:35,895 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:26:35,895 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 518
2012-09-01 17:26:35,895 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:26:35,895 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 1
2012-09-01 17:26:35,895 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 516
2012-09-01 17:27:31,997 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:27:31,998 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:27:31,998 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 516
2012-09-01 17:27:31,998 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:27:31,998 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 1
2012-09-01 17:27:31,998 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 515
2012-09-01 17:28:20,343 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:28:20,343 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:28:20,344 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 515
2012-09-01 17:28:20,344 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:28:20,344 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 1
2012-09-01 17:28:20,344 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 525
2012-09-01 17:29:05,616 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:29:05,617 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:29:05,617 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 525
2012-09-01 17:29:05,617 [main] DEBUG ObjectLoader.getObject():65 - ************************************
2012-09-01 17:29:05,617 [main] DEBUG ObjectLoader.getObject():66 - Number of objects in cache: 1
2012-09-01 17:29:05,618 [main] DEBUG ObjectLoader.getObject():72 - Object not in cache | 512
2012-09-01 17:29:38,790 [main] DEBUG ObjectLoader.getObject():80 - Number of objects in cache: 1
2012-09-01 17:29:38,790 [main] DEBUG ObjectLoader.getObject():81 - Number of objects evicted from cache: 0
2012-09-01 17:29:38,790 [main] DEBUG ObjectLoader.getObject():83 - Object key found: 512

Do I have ehcache configured wrong or do I have a bug in my code? Any help would be appreciated. Thanks.

I'm using spring 3.1.0, ehcache-spring-annotations 1.1.2, and ehcache 2.4.2

ObjectCacheFacade.java

@Component()
public class ObjectCacheFacade {
    private static final String CACHE_KEY = "myObjectCache";

    @Resource
    private CacheManager cacheManager;
    private Cache cache;

    public ObjectCacheFacade() {
        cacheManager = CacheManager.getInstance();
        this.cache = cacheManager.getCache(CACHE_KEY);
    }

    public Object getObjectFromCache(String objectId) {
        Object result = null;
        Element element = cache.get(objectId);

        if (element != null && element.getValue() != null) {
            result = element.getObjectValue();
        } 

        return result;
    }

    public void putObjectIntoCache(String objectId, Object object) {
        Element element = new Element(objectId, object);
        cache.put(element);
    }

    public int getSize() {
        return cache.getSize();
    }

    public void removeObjectFromCache(String objectId) {
        cache.remove(objectId);
    }

    public void flushCache() {
        cache.removeAll();
    }

    public Cache getCache() {
        return cache;
    }
}

ObjectLoader.java

@Service
public class ObjectLoader {
    private static final Logger log = Logger.getLogger(ObjectLoader.class);

    @Resource
    protected ObjectDao objectDao;
    @Resource
    protected ObjectCacheFacade objectCache;

    public void loadCache() {
        List<String> objectIds = objectDao.getObjectIds();

        for (String objectId : objectIds) {
            loadObject(objectId);
        }
    }

    public Object getObject(String objectId) {
        log.debug("************************************");
        log.debug("Number of objects in cache: " + objectCache.getSize());

        Object object = objectCache.getObjectFromCache(objectId);

        if (object == null) {
            log.debug("Object not in cache | " + objectId);
            object = objectDao.getObject(objectId);

            if (object != null) {
                objectCache.putObjectIntoCache(objectId, object);

                log.debug("Number of objects in cache: " + objectCache.getSize());
                log.debug("Number of objects evicted from cache: " + objectCache.getCache().getCacheEventNotificationService().getElementsEvictedCounter());
                for (Object key : objectCache.getCache().getKeys()) {
                    log.debug("Object key found: " + key);
                }
            } 
        } 

        return object;
    }
}

ehcache.xml

<ehcache>
    <diskStore path="java.io.tmpdir"/>

    <defaultCache
        maxElementsInMemory="1000"
        eternal="false"
        timeToIdleSeconds="60"
        timeToLiveSeconds="300"
        overflowToDisk="false"
        memoryStoreEvictionPolicy="LRU"
       />

    <cache
        name="myObjectCache"
        maxElementsInMemory="1000"
        eternal="true"
        timeToIdleSeconds="0"
        timeToLiveSeconds="0"
        overflowToDisk="false"
        diskPersistent="true"
        memoryStoreEvictionPolicy="LRU"
       />

</ehcache>

applicationContext.xml

<bean id="cacheManager" class="org.springframework.cache.ehcache.EhCacheManagerFactoryBean" />

Answer 1

Since diskPersistent was set to true Ehcache was attempting to write the objects to disk after they were added to the cache. However, one of the nested objects inside the main cached object didn't implement Serializable, so it was throwing an exception on disk write and then evicting the object from the cache. This eviction wasn't showing up in the cache statistics since it wasn't evicted by the memoryStoreEvictionPolicy.

This should have been an very easy bug to find, but the project didn't include the slf4j-log4j12 library, so the exception was being swallowed instead of being written out to the logs. Once the logging was handled properly, it was instantly obvious what the problem was.

Oh well, live and learn I guess...