In Star Trek there is a test named the Kobayashi Maru given to all Starfleet Academy cadets. In this test the civilian vessel Kobayashi Maru is disabled and trapped in the Klingon Neutral Zone, and the cadet must choose whether to leave the ship to certain destruction or to attempt a rescue but risk the lives of their own ship and crew and possibly provoke the Klingons into an all-out war. If the cadet chooses to attempt a rescue the simulation inevitably ends in battle and complete destruction of the cadet's ship. The test is designed as a no-win situation to test the cadet's character.

How is this relevant to OpenJPA and EP you ask? In our case the Kobayashi Maru is your e-commerce store - stuck in the neutral zone between development and go live, disabled due to performance issues caused by a large object graph. The cadet is you, the developers. The Klingons represent the project stakeholders who will fight you to meet deadlines whilst requiring quality maintainable and functional code. What makes it a no-win situation is there is no simple way to tell OpenJPA to load just specific parts of the object graph. You have the following options:

• Try to use the EP load tuners to flag which parts of the object graph you are not interested in.
  • For example, the ProductLoadTuner lets you specify setLoadingCategories(false) to avoid loading all of the categories that a product belongs to. Seems sound, right? The only problem is it doesn't work! For legacy reasons there are many service methods and queries that load a product (either directly or as part of another object graph) and expect the categories - so a long time ago the JPA annotations on ProductImpl.getProductCategories() was set to FetchType.EAGER. This means JPA will always load the categories. If you change the annotation to use FetchType.LAZY then you would need to find everywhere in the system that loads a product expecting to see categories and change it to use the appropriate load tuner. You don't have that much time, and so you are defeated by the Klingons.
• Create a new OpenJPA FetchGroup which is a way of defining exactly which fields to load.
  • This is the strategy that has already been used in parts of the code - for example when building the product index. The drawbacks of this approach is that a fetch group will only load the specified fields, and you can only define a fetch group through annotations in the same classes that the fields are defined in. If you are trying to use Binary Based Development then this option is already disqualified. If you are happy to make core changes, then you need to edit every class in the object graph to define the fields that should be loaded as part of your fetch group. A quick search shows the PRODUCT_INDEX fetch group is defined across 20 classes! Miss one field in one class and you get an unexpected NullPointerException. You don't have time to do all the testing required to ensure you have all the necessary fields, and so you are either defeated by the Klingons or your ship implodes later due to a null pointer in the warp core.
• Change the OpenJPAFetchPlanHelperImpl to remove the default fetch group.
  • This is a special fetch group created by OpenJPA (FetchGroup.NAME_DEFAULT) which includes all basic fields, *ToOne fields, and other fields marked with FetchType.EAGER. Remove this and you then need to add back all the fields that you want to load. So you are most likely in the same situation as above. Even if you try to do something clever like having a spring injected list of fields to include, this will need to be maintained in the future when new fields are added to any of the classes involved, and you still need to do exhaustive testing to ensure no essential field was missed. So the Klingons win again.

I am now going to play the role of Captain James Kirk. Kirk stated "I don't believe in the no-win scenario", and his response to the Kobayashi Maru test was to subtely reprogram the simulator to make it possible to rescue the vessel. I'm going to reprogram our simulator using some of the OpenJPA API.

We can use the OpenJPA metadata API to recreate the "default" fetch plan in such a way as to allow ad-hoc addition and removal from this plan. Here's a code snippet that does this:

protected Set<String> getDefaultFetchFields(final Class< ? > persistenceClass, final EntityManager entityManager, final Set<Class<?>> configuredObjects) {
     Set<String> fetchFields = new HashSet<String>();
 
     if (configuredObjects == null) {
          configuredObjects = new HashSet<Class<?>>();
     } else if (configuredObjects.contains(persistenceClass)) {
          return fetchFields;
     }
     configuredObjects.add(persistenceClass);
 
     ClassMetaData classMetaData = JPAFacadeHelper.getMetaData(entityManager, persistenceClass);
     FieldMetaData[] fields = classMetaData.getFields();
     for (FieldMetaData field : fields) {
          if (field.isInDefaultFetchGroup()) {
               fetchFields.add(field.getFullName(false));
               if (field.isTypePC()) {
                    fetchFields.addAll(getDefaultFetchFields(field.getType(), entityManager, configuredObjects));
               } else if (field.getElement() != null && field.getElement().isTypePC()) {
                    getDefaultFetchFields(field.getElement().getType(), entityManager, configuredObjects);
               }
          }
     }
 
     return fetchFields;
}

The first block keeps track of any classes we have already processed since there can be self-references or bi-directional relationships in an object graph. We then use OpenJPA's JPAFacadeHelper class to get the metadata for the given class. This provides a collection of persistence fields - both in the current class and any of its superclasses. We loop through these fields and examine each one in turn. The field metadata will tell us if the field is in the default fetch group, and if so we add it to the list of fields to include. Next, we check if the field is itself a PersistenceCapable class, in which case we recurse down into the fields of that class, and so on. For a *ToMany relationship the field will have an element which may be PersistenceCapable so we recurse into that similarly.

The results of all this is a list of (fully qualified) field names that are in the default fetch group for the entire object graph of the given class. We can then tweak this list, removing any fields we don't want loaded and adding other (non-default) fields we specifically want to load. We can then tell OpenJPA to remove the default fetch group, and give it our list as the definitive list of fields to load. For example:

Set<String> productFetchFields = getDefaultFetchFields(beanFactory.getBeanImplClass(ContextIdNames.PRODUCT), entityManager, null);
fetchPlan.removeFetchGroup(FetchGroup.NAME_DEFAULT);
fetchPlan.addFields(productFetchFields);
fetchPlan.removeField(ProductImpl.class, "productCategories"); 

We now have a fetch plan that tells OpenJPA to load a product without the categories!

Using this technique you can easily define to a fine degree exactly what gets loaded in your object graph and thus rescue the civilian vessel without arousing the wrath of the Klingons.

In my next mission as captain of this starship I will refactor the OpenJPAFetchPlanHelperImpl to use this technique which will enable the load tuners flags to actually work as expected!  I'll also add methods to that class (and interface) to allow easy removal of fields and also a method for removal of all fields (except the uidPk) of a class. Sometimes having that object "reference" on the object graph is sufficient without requiring any of the other fields, and it would be tiresome to remove the fields from the plan individually. For an encore I will replace all the hard-coded @FetchGroup annotations with a spring-injectable plan which is more extension-friendly (whilst still preserving current behaviour).

Feeback welcome, in the meantime Live Long and Prosper!

Every order in Elastic Path Commerce must have a unique number. Out of the box, we use an auto-incrementing value stored in the TORDERNUMBERGENERATOR table. Here is the OpenJPA annotation for the orderNumber property in OrderImpl.java:

      @Basic
      @Column(name = "ORDER_NUMBER", length = GUID_LENGTH, nullable = false, unique = true)
      @GeneratedValue(strategy = GenerationType.TABLE, generator = NEXT_ORDER_NUMBER)
      @TableGenerator(name = NEXT_ORDER_NUMBER, table = "TORDERNUMBERGENERATOR", pkColumnName = "UIDPK",
                 valueColumnName = NEXT_ORDER_NUMBER, pkColumnValue = "1", allocationSize = 1)
      public String getOrderNumber() {
            return this.orderNumber;
      }

The first annotation declares orderNumber as a basic property. The second annotation declares ORDER_NUMBER as the column to save/load the property. The third annotation declares this as an auto-generated value, so no need to explicitly assign a value when the order is created in our code. The fourth annotation says that we are using the table generator. The next available order number is retrieved from the NEXT_ORDER_NUMBER column in TORDERNUMBERGENERATOR.

You may need to customize the number generation. For example, one of our customers has multiple data centers and each data center is running its own separate production deployment of Elastic Path Commerce. Order data from the different data centers is sent to a centralized financial application. The financial application needs to have unique order numbers, but each Elastic Path deployment uses the same order number generator algorithm, so there will be duplicate order numbers across the different data centers.

Having a centralized order number generator was not an option. The solution was to add a prefix to every order number on all data centers. The prefix would identify the data center where the order was created and ensure that order numbers would be unique across all data centers. To implement this, we would need to do the following:

• Create a CUSTOMIZEDORDERNUMBERGENERATOR database table with columns (UIDPK number, PREPEND varchar 3, NEXT_ORDER_NUMBER varchar 100). Each data center would store a different prefix in the PREPEND column.
  
• Create a CustomizedOrderNumberGenerator, which would read the PREPEND column and prepend it to  the NEXT_ORDER_NUMBER.
  
• Override the annotations for OrderImpl.getOrderNumber to use the new custom generator.

OpenJPA represents all generators internally with the org.apache.openjpa.kernel.Seq interface. This interface supplies all the context we need to create  our own custom generators, including the current persistence  environment, the JDBC DataSource,  and other essentials. The org.apache.openjpa.jdbc.kernel.AbstractJDBCSeq helps us create custom JDBC-based sequences. There are many  implementations in OpenJPA to generate different values as well, like AbstractJDBCSeq, ClassTableJDBCSeq, DelegatingSeq, NativeJDBCSeq, TableJDBCSeq, TimeSeededSeq, UUIDHexSeq, UUIDStringSeq, UUIDType4HexSeq, UUIDType4StringSeq, ValueTableJDBCSeq. Here is our CustomizedOrderNumberGenerator:

public class CustomizedOrderNumberGenerator extends ValueTableJDBCSeq {
 
    private static final String TABLE_NAME = "CUSTOMIZEDORDERNUMBERGENERATOR";
    private static final String PRIMARY_KEY_COLUMN = "UIDPK";
    private static final String PRIMARY_KEY_VALUE = "1";
    private static final String SEQUENCE_COLUMN = "NEXT_ORDER_NUMBER";
    private static final String PREFIX_COLUMN = "PREPEND";
 
    protected Object currentInternal(final JDBCStore store, final ClassMapping mapping) throws Exception {        
        return getPrefix(store, mapping) + super.currentInternal(store, mapping);    
    }
    
    protected Object nextInternal(final JDBCStore store, final ClassMapping mapping) throws Exception {
        return getPrefix(store, mapping) + super.nextInternal(store, mapping);    
    }
    
    protected String getPrefix(final JDBCStore store, final ClassMapping mapping) throws EpSystemException, SQLException {    
        if (prefix == null) {
            // Load from db
            Object primaryKey = getPrimaryKey(mapping);
    
            if (primaryKey == null) {    
                LOG.error(ERROR_CANNOT_GET_ORDER_PREFIX);
                throw new EpSystemException(ERROR_CANNOT_GET_ORDER_PREFIX);            
            }
            
            Connection conn = getConnection(store);            
            try {            
                prefix = getPrefix(conn);            
            } finally {            
                closeConnection(conn);            
            }         
        }            
        return prefix;            
    }
        
    
    private String getPrefix(final Connection conn) throws EpSystemException, SQLException {
        // Prepare the statement
        DBDictionary dict = getConfiguration().getDBDictionaryInstance();
        SQLBuffer sel = new SQLBuffer(dict).append(PREFIX_COLUMN);
        SQLBuffer where = new SQLBuffer(dict).append(PRIMARY_KEY_COLUMN).append(" = ").append(PRIMARY_KEY_VALUE);
        SQLBuffer tables = new SQLBuffer(dict).append(TABLE_NAME);
        
        SQLBuffer select = dict.toSelect(sel, null, tables, where, null, null,
                null, false, false, 0, Long.MAX_VALUE, false, true);
 
        PreparedStatement stmnt = select.prepareStatement(conn);
        
        ResultSet resultSet = null;
        
        try {
            //Do query
            resultSet = stmnt.executeQuery();
 
            if (!resultSet.next()) {
                LOG.error(ERROR_CANNOT_GET_ORDER_PREFIX);
                throw new EpSystemException(ERROR_CANNOT_GET_ORDER_PREFIX);
            }
            return dict.getString(resultSet, 1);
    
        } finally {        
            ...        
        }   
    }
}

The last step is to overwrite  the generator in order-orm.xml:

    <entity class="OrderImpl">
        <sequence-generator name="NEXT_ORDER_NUMBER" sequence-name="com.customize.CustomizedOrderNumberGenerator()" allocation-size="1" />
       ...
   </entity>

For more information on table generators, see the following links:

http://openjpa.apache.org/builds/1.2.0/apache-openjpa-1.2.0/docs/manual/jpa_overview_mapping_sequence.html#jpa_overview_mapping_sequence_tablegen

http://openjpa.apache.org/builds/1.0.2/apache-openjpa-1.0.2/docs/manual/jpa_overview_mapping_sequence.html

http://openjpa.apache.org/builds/1.0.2/apache-openjpa-1.0.2/docs/manual/ref_guide_sequence.html

If some of the recent performance-related posts by our much cherished Get Elastic blogger extraordinaire Linda are starting to worry you, fear not! With the newly released Elastic Path 6.2, the Product Development and Performance teams at Elastic Path have done a fantastic job ramping up the standard performance of the product. I'll let them brag about the numbers at a later date, but today's post is to dig into the guts of the caching introduced into the system, and how you can start tweaking some of the configuration settings to squeek out every millisecond for page responses.

Within Elastic Path, there are now two caches that are available to be tweaked:

• Application-level: Sitting between the view layer and the data access layer
• Persistence-level: A Level-2 cache, within the OpenJPA ORM framework
  

Application Level Cache

All products loaded within the Storefront application via the StoreProductService will be from an Ehcache-backed cache by default. Each application is responsible for loading products via a ProductRetrieveStrategy. You'll notice storefront has two new configurations to facilitate using Ehcache:

Cache.xml:

     <bean id="productCache" class="org.springframework.cache.ehcache.EhCacheFactoryBean">
          <property name="timeToLive" value="600"/>
          <property name="timeToIdle" value="600"/>
     </bean>

     <bean id="cachingProductRetrieveStrategy" class="com.elasticpath.sfweb.service.impl.EhCacheProductRetrieveStrategyImpl">
          <property name="productService" ref="productService" />
          <property name="cache" ref="productCache" />
     </bean>

ServiceSF.xml:

    <alias name="cachedSettingsReader" alias="settingsReader"/>
    <alias name="cachingProductRetrieveStrategy" alias="productRetrieveStrategy"/>

You'll note that the storefront is now using aliases in the Spring configuration to override the same bean definitions in the default core service.xml. This allows the storefront to setup caching-specific classes. For tweaking purposes, the productCache bean definition should be updated to optimize the Ehcache settings. By default, Spring's EhCacheFactoryBean will initialize the cache to allow overflow to disk, use LRU eviction and limit the in-memory size to 10k objects. For catalogs with a larger product mix, these settings should be optimized and potentially moved to an distributed cache via Terracotta to keep the JVM heap size to a reasonable level.

You can choose to add new properties here to tweak these values, or add an ehcache.xml configuration file to the classpath and define a specific cache name as part of the productCache definition to use. A quick tip on monitoring the cache statistics for tweaking the settings during load test is to setup JMX monitoring for the storefront cache. This can be done via two steps:

Running the appserver with remote JMX enabled (no authentication for a non-production environment):

-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=6969 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false

Configuring the JMX beans for Ehcache in cache.xml. Note in this case we are explicitly setting up a cache manager, which we can also use to specify a custom Ehcache configuration file instead of the default ehcache.xml:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd ">

    <bean id="productCache" class="org.springframework.cache.ehcache.EhCacheFactoryBean">
        <property name="timeToLive" value="600"/>
        <property name="timeToIdle" value="600"/>
        <property name="cacheManager" ref="cacheManager" />
    </bean>

    <bean id="cachingProductRetrieveStrategy" class="com.elasticpath.sfweb.service.impl.EhCacheProductRetrieveStrategyImpl">
        <property name="productService" ref="productService" />
        <property name="cache" ref="productCache" />
    </bean>

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

    <!-- Spring initialization of ehCache's mbeans -->
    <bean id="ehCacheMBeanRegistration"
        class="org.springframework.beans.factory.config.MethodInvokingFactoryBean">
        <property name="staticMethod"
            value="net.sf.ehcache.management.ManagementService.registerMBeans" />
        <property name="arguments">
            <list>
                <ref bean="cacheManager" />
                <ref bean="mbeanServer" />
                <value>true</value>
                <value>true</value>
                <value>true</value>
                <value>true</value>
            </list>
        </property>
    </bean>

    <bean id="mbeanServer" class="org.springframework.jmx.support.MBeanServerFactoryBean">
        <property name="locateExistingServerIfPossible" value="true" />
    </bean>

</beans>

Connecting up with jConsole lets us check the cache settings are properly configured, and to check the statistics, as per the below image. We should see updates to statistics as you browse the storefront and load more products:

Persistence Level Cache

As part of the Elastic Path 6.2 release, the included OpenJPA library has been upgraded to a 1.2.1 version, which overcomes some data cache issues in the previous 1.0.1 version. Please see the OpenJPA 1.2.1 documentation for all details on the native OpenJPA datacache. We'll go over some of the changes that enable the data cache using the native implementation.

Annotations:

All transactional persistent entities (anything submitted or updated regularly as an online transaction such as orders, payments and customers) have a new data cache annotation so that they are non-cacheable. By default, entities are enabled in the data cache unless this annotation is present and explicitly disabled the caching. All relatively static data, such as catalog entities should be part of the cache and thus will be missing this new annotation.

@DataCache(enabled = false)

Persistence.xml Configuration:

As part of the persistence unit configuration, three new properties are configured by default:

            <property name="openjpa.DataCache" value="true"/>
            <property name="openjpa.RemoteCommitProvider" value="sjvm"/>
            <property name="openjpa.DataCacheTimeout" value="1000"/>

These values are used for:

• openjpa.DataCache - enabling the cache, and specifying the cache properties. We recommend tweaking this value to accomodate the cache size according to the size of the underlying data: (true(CacheSize=25000, SoftReferenceSize=0))
• openjpa.RemoteCommitProvider - specifying the commit provider. For a clustered setup, evictions should be handled via configuring this setting to use JMS or TCP-based evictions.
• openjpa.DataCacheTimeout - maximum time to live for entities in the cache

Also suggested is to tune the query cache, which is enabled with default values when the DataCache property is set to true:

<property name="openjpa.DataCache" value="true(CacheSize=25000, SoftReferenceSize=0)"/>
<property name="openjpa.RemoteCommitProvider" value="sjvm"/>
<property name="openjpa.QueryCache" value="CacheSize=25000, SoftReferenceSize=0"/>

Tip: Catching Cache Hits and Misses

If caching is enabled and you're still seeing a large amount of database queries from the storefront server, you can enable data cache Log4j tracing and grep out the hits and misses logged to track down which entities and queries are mistakingly hitting the database. Most of the times, these can be tracked down to accidental evictions or entities within the inheritance hierachy being disabled from cache.

log4j.category.openjpa.DataCache=TRACE

This spits out some logs similar to below that's easily greppable to count and track which entities are creating problems:

DEBUG 2009-09-10 12:56:33,918 org.apache.renamed.openjpa.lib.log.CommonsLogFactory$LogAdapter.trace(CommonsLogFactory.java:76) - Cache hit while looking up key "com.elasticpath.domain.attribute.impl.ProductTypeProductAttributeImpl-1".
DEBUG 2009-09-10 12:56:33,926 org.apache.renamed.openjpa.lib.log.CommonsLogFactory$LogAdapter.trace(CommonsLogFactory.java:76) - Cache miss while looking up key "org.apache.renamed.openjpa.datacache.QueryKey@b7ee9cab[query:[SELECT ps.skuCodeInternal FROM ProductSkuImpl ps

OpenJPA Cache Plugins

The native data cache within OpenJPA is architected to be swappable via plugin configuration. This allows the ability to swap in alternative caching technologies like Ehcache or Oracle Coherence to support extensive scalability requirements, as both Ehcache/Terracotta and Oracle Coherence support distributed caching setups. We've tested Ehcache and Coherence plugins internally with favourable results.

An Ehcache plugin is provided by the Ehcache group, however this version must be repackaged to match the custom package names of the Elastic Path specific org.apache.renamed.openjpa jar. Once a repackaged instance of the Ehcache-OpenJPA jar is in the classpath, the configuration changes to:

<property name="openjpa.DataCacheManager" value="ehcache"/>

Similarily enough, OpenJPA commiter Pinaki has posted the initial workings of an Oracle Coherence plugin on his blog, along with some additional JPA caching insights. Elastic Path with OpenJPA and Oracle Coherence is probably worth an entire blog entry in itself (coming soon!), but the same configuration settings apply, along with the need to repackage the code to point at the Elastic Path OpenJPA jar:

<property name="openjpa.DataCacheManager" value="coherence"/>

So there it is, two new caching mechanisms to tweak and fine-tune as part of load tests that should favourably reflect storefront page load times, and hopefully conversion rates and green dollar signs. Feel free to ask away about some of our load testing and tuning war stories. We'd be happy to talk about our hands on experience with the recent caching work.

Our use of the OpenJPA APIs has typically been limited to the methods of the JPA EntityManager, which we wrap with our persistence engine class, JpaPersistenceEngineImpl.

We also make limited use of the OpenJPAQuery, EntityTransaction and FetchPlan classes.

However, OpenJPA provides some other very useful APIs, which can be used to inspect and/or control the way we load and persist our objects. Classes of particular interest include:

In this post, we'll see first-hand the usefulness of these APIs by building an enhanced version of the persistence engine - one that logs JPA loads and saves.

Determining the dirty state of an object

The OpenJPA entity manager can be used to determine the dirtiness of an object as follows:

protected void logDirtyState(final Persistence object) {
  OpenJPAEntityManager openjpaEM = OpenJPAPersistence.cast(getEntityManager());
  if (openjpaEM.isDirty(object)) {
    LOG.info(object.getClass().getName() + " (" + object.getUidPk() + ") is dirty");
  }
}

Note that this only works for PersistenceCapable objects, i.e. classes that have been enhanced by OpenJPA. So it can't be used to determine the dirty status of every object that may be involved in a save or merge. For example, if an object has a String field that has been changed, calling isDirty on that field will return false because String is not an enhanced class.

However, you can find out exactly which fields of a PersistenceCapable object are dirty as follows:

protected void logDirtyFields(final PersistenceCapable pcObject) {
  OpenJPAStateManager manager = (OpenJPAStateManager) pcObject.pcGetStateManager();
  ClassMetaData metaData = JPAFacadeHelper.getMetaData(getEntityManager(), pcObject.getClass());
  BitSet dirtySet = manager.getDirty();
  for (int dirtyIndex = dirtySet.nextSetBit(0); dirtyIndex >= 0; dirtyIndex = dirtySet.nextSetBit(dirtyIndex + 1)) {
    FieldMetaData fieldMetaData = metaData.getField(dirtyIndex);
    LOG.info(pcObject.getClass().getName() + " has a dirty field: " + fieldMetaData.getName());
  }
}

The state manager's getDirty() method will give us a BitSet indicating the indexes of the fields that are marked as dirty. We use the JPAFacadeHelper to get the metadata for the class, and then we can get the metadata for each of the dirty fields.

Examining the dirty state of an entire object graph

The above demonstrated how to determine whether an object is dirty, and how to find out which fields of that object are dirty. But what if some of those fields are themselves PersistenceCapable objects or collections of objects?

Well, OpenJPA makes it relatively easy to traverse the object graph. Let's change the above code to do a bit more with the dirty fields:

for (int dirtyIndex = dirtySet.nextSetBit(0); dirtyIndex >= 0; dirtyIndex = dirtySet.nextSetBit(dirtyIndex + 1)) {
  FieldMetaData fieldMetaData = metaData.getField(dirtyIndex);
  Method method = Reflection.findGetter(pcObject.getClass(), fieldMetaData.getName(), true);
  logDirtyField(fieldMetaData.getName(), Reflection.get(pcObject, method), (Persistence) pcObject);
}

The Reflection class gives us access to the getter for the given field and thus we can traverse further into that field's object, as follows:

protected void logDirtyField(final String fieldName, final Object object, final Persistence parent) {
  if (object instanceof Collection) {
    for (Object member : (Collection<Object>) object) {
      logDirtyField(fieldName + " (member)", member, parent);
    }
    return;
  }
  if (object instanceof Map) {
    for (Map.Entry<Object, Object> entry : ((Map<Object, Object>) object).entrySet()) {
      logDirtyField(fieldName + " (" + entry.getKey().toString() + ")", entry.getValue(), parent);
    }
    return;
  } 
  if (object instanceof PersistenceCapable) {
    logDirtyFields((PersistenceCapable) object);
  } else {
    LOG.info(parent.getClass().getName() + " (" + parent.getUidPk() + ") has dirty field " + fieldName 
                         + " with value " + object.toString());
}

As you can see, if we call this on a field that is a collection or map, it will just iterate through the members and pass each resultant member object into the logging method. If the field (or member) is itself a PersistenceCapable object, we call the original method to examine that object's dirty fields. Finally, when the field (or member) is not a collection, map, or PersistenceCapable object, we just log the fact it was found to be dirty.

To demonstrate this behaviour, if we edit a product and make some changes to its fields and attributes, we get a log similar to the below:

Examining the object graph loaded by JPA

When we ask JPA to load an object, we often get more than we bargained for. What gets loaded depends on the relationships the object has to other objects, the annotated FetchType, and any load tuners or fetch groups defined. More often than not we get a sizeable object graph.

OpenJPA provides a convenient way to examine what gets loaded without having to use something like reflection to manually traverse the object graph. Instead, you can use define a LoadListener - just one of the many listeners for lifecycle-related events that JPA allows you to add.

We define our logging load listener as follows:

public class LoggingLoadListener implements LoadListener {
 
  public void afterLoad(final LifecycleEvent event) {
    Persistence sourceObject = (Persistence) event.getSource();
    LOG.log(logLevel, "Loaded " + sourceObject.getClass().getName() + " with UIDPK " + sourceObject.getUidPk());
  }
 
  public void afterRefresh(final LifecycleEvent event) {
    // Do nothing - we don't care about refresh events.
  }
 
}

The lifecycle methods get called with a LifecycleEvent object which provides the event's source object.

Note: If you want to listen to multiple kinds of JPA events, you consider subclassing OpenJPA's AbstractLifecycleListener which implements all the lifecycle listeners and delegates them to a single method eventOccurred(LifecycleEvent event).

To tell OpenJPA to call this listener whenever it loads, we use the JPAFacadeHelper to get a hold of the underlying Broker as follows:

private void addLoadListener() {
    OpenJPAEntityManager openjpaEM = OpenJPAPersistence.cast(getEntityManager());
    Broker broker = JPAFacadeHelper.toBroker(openjpaEM);
    broker.addLifecycleListener(new LoggingLoadListener(), null);
}

A logging persistence engine

Now we know how to get this information, how do we seamlessly integrate it into our Elastic Path application? The easiest way is to create a subclass of the main Elastic Path JPA persistence engine, JpaPersistenceEngineImpl. We then override the persistence methods to call our logging functions.

For example:

public class LoggingPersistenceEngineImpl extends JpaPersistenceEngineImpl {
 
  @Override
  public <T extends Persistence> T merge(final T object) throws EpPersistenceException {
    logDirtyState(object);
    return super.merge(object);
  }
 
  @Override
  public void save(final Persistence object) throws EpPersistenceException {
    logDirtyState(object);
    super.save(object);
  }
 
  @Override
  public <T extends Persistence> T get(final Class<T> persistenceClass, final long uidPk) throws EpPersistenceException {
    addLoadListener();
    return super.get(persistenceClass, uidPk);
  }

...and similarly for the other methods (retrieve, retrieveByNamedQuery, etc.).

Then we just change the Spring wiring to use our new logging persistence engine as follows (found in conf/spring/dataaccess/openjpa/openjpa.xml)

<bean id="persistenceEngineTarget"
      class="com.elasticpath.persistence.impl.LoggingPersistenceEngineImpl">
  <property name="entityManager" ref="sharedEntityManager"/>
  <property name="sessionFactory" ref="sessionFactory"/>
</bean>

Enhancement - limiting the list of classes to be logged

There may be classes you want to exclude from the logging - such as search index related classes that may result in too much log noise. One easy way of being able to configure the set of classes you want logged is just to define the list through Spring. For example, we add the following property to the persistence engine bean definition:

<property name="loggingClasses">
  <set>
    <value>com.elasticpath.domain.attribute.impl.AbstractAttributeValueImpl</value>
    <value>com.elasticpath.domain.attribute.impl.AttributeGroupAttributeImpl</value>
    <value>com.elasticpath.domain.attribute.impl.AttributeImpl</value>
    <value>com.elasticpath.domain.attribute.impl.ProductAttributeValueImpl</value>
    <value>com.elasticpath.domain.attribute.impl.ProductTypeProductAttributeImpl</value>
    <value>com.elasticpath.domain.catalog.impl.AbstractPriceImpl</value>
    <value>com.elasticpath.domain.catalog.impl.AbstractPriceTierImpl</value>
    <value>com.elasticpath.domain.catalog.impl.CatalogProductPriceImpl</value>
    <value>com.elasticpath.domain.catalog.impl.AbstractLocaleDependantFieldsImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductAssociationImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductLocaleDependantFieldsImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductPriceImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductPriceTierImpl</value>
    <value>com.elasticpath.domain.catalog.impl.ProductTypeImpl</value>
  </set>
</property>

Then we add the relevant property, getter and setter to our class:

private Collection<String> loggingClasses;
 
public Collection<String> getLoggingClasses() {
  return loggingClasses;
}
 
public void setLoggingClasses(final Collection<String> loggingClasses) {
  this.loggingClasses = loggingClasses;
}

Finally, we add the following to our logDirtyState and afterLoad methods:

if (!getLoggingClasses().contains(object.getClass().getName())) {
  return;
}

Enhancement - configurable log level

Suppose we want to allow the log level used by our logging persistence engine to be configurable through spring. We can just add a getter and setter as follows:

private Level logLevel;
 
  public String getLogLevel() {
    return logLevel.toString();
  }
 
  public void setLogLevel(final String logLevel) {
    this.logLevel = Level.toLevel(logLevel);
  }

Then we just use the log4j log(Priority priority, Object message) method whenever we log. Make sure to set this in spring by adding the property to your bean definition:

<property name="logLevel" value="INFO"/>