Description

Context :

JDK 7, Linux 64
object being cached is a XJC-generated POJO which contains mutable ArrayLists
high GC pressure

When ehcache is trying to serialize it to disk, an error is being logged (stacktrace follows). The expected behaviour is to log at most at WARN level, and retry.

java.lang.NullPointerException at java.util.ArrayList.writeObject(ArrayList.java:706) at sun.reflect.GeneratedMethodAccessor86.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:975) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1493) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1493) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346) at java.util.ArrayList.writeObject(ArrayList.java:710) at sun.reflect.GeneratedMethodAccessor86.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:975) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1493) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1528) at java.io.ObjectOutputStream.defaultWriteObject(ObjectOutputStream.java:438) at net.sf.ehcache.Element.writeObject(Element.java:835) at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:975) at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1480) at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416) at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1174) at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:346) at net.sf.ehcache.util.MemoryEfficientByteArrayOutputStream.serialize(MemoryEfficientByteArrayOutputStream.java:97) at net.sf.ehcache.store.disk.DiskStorageFactory.serializeElement(DiskStorageFactory.java:405) at net.sf.ehcache.store.disk.DiskStorageFactory.write(DiskStorageFactory.java:384) at net.sf.ehcache.store.disk.DiskStorageFactory$DiskWriteTask.call(DiskStorageFactory.java:485) at net.sf.ehcache.store.disk.DiskStorageFactory$PersistentDiskWriteTask.call(DiskStorageFactory.java:1088) at net.sf.ehcache.store.disk.DiskStorageFactory$PersistentDiskWriteTask.call(DiskStorageFactory.java:1072)

Comments

James House 2013-06-14

Please evaluate

Chris Dennis 2013-06-14

When using on disk storage the key/value serialization and disk io is done asynchronously on a different thread. Concurrent to Ehcache trying to serialize the value it appears your code is mutating the ArrayList (in this case it appears to be a remove). Ehcache will not tolerate this happening. In order to fix this problem you need to either:

Not mutate things you put in the cache (preferred solution). This prevents the exception from being thrown, and also resolves any ambiguity about which state of the ArrayList will get written in to the disk store.

Use a thread safe data structure instead of array list (non-preferred solution). This prevents the exception from being thrown, but leaves it ambiguous as to which state gets written to the disk store.

Vincent PERICART 2013-08-16

Thank you for your answer. I would agree that is it “not a bug” and will simply disable logging for this class.

As you said, this exception definitely is caused by a race condition. However, I disagree with your analysis of the condition itself because :

the error line at the top of the stacktrace indicates that elementData was null. Calls to remove() or clear() don’t do this.
actually, my code is not doing any modification on those lists.

The only state modification I see on those POJOs is caused by the way XJC generates lazy getters : protected List x; public List getX() \{ if (x == null) \{ x = new ArrayList(); \} return this.x \}

But I still can’t explain why elementData gets nulled.

Vincent PERICART 2013-08-16

Just for the record… my take is that the writing thread sees the new ArrayList<> object before it is fully constructed. This behaviour could be fixed with a XJC plugin that declares List fields as volatile, or that uses a tmp variable like this: protected List x; public List getX() \{ if (x == null) \{ List x0 = new ArrayList(); x = x0;\} return this.x \}