performance of executing openjpa query

Question

I have a rest web app with cxf 3.0.1 framework and openjpa 2.3.0. The web.xml:

<web-app xmlns="http://java.sun.com/xml/ns/javaee"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd">
    <display-name>Mobile app rest services</display-name>

    <context-param>
        <param-name>contextConfigLocation</param-name>
        <param-value>WEB-INF/cxf-servlet.xml</param-value>
    </context-param>

    <listener>
        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
    </listener>

    <servlet>
        <servlet-name>CXFServlet</servlet-name>
        <servlet-class>org.apache.cxf.transport.servlet.CXFServlet</servlet-class>
        <load-on-startup>1</load-on-startup>
    </servlet>

    <servlet-mapping>
        <servlet-name>CXFServlet</servlet-name>
        <url-pattern>/services/*</url-pattern>
    </servlet-mapping>
</web-app>

the persistence.xml:

<?xml version="1.0" encoding="UTF-8"?>
<persistence version="2.1" xmlns="http://xmlns.jcp.org/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_1.xsd">
    <persistence-unit name="thePU" transaction-type="RESOURCE_LOCAL">
        <provider>org.apache.openjpa.persistence.PersistenceProviderImpl</provider>
        <class>xz.Partner</class>
        <exclude-unlisted-classes>false</exclude-unlisted-classes>
        <properties>

            <property name="openjpa.DataCache" value="true(
                    Types=
                        /*selected classes*/
                    EvictionSchedule='0 0 * * *')"/>

            <property name="javax.persistence.jdbc.url" value="jdbc:mysql://some.remote.rds.amazonaws.com:3306/XZdb?zeroDateTimeBehavior=convertToNull"/>
            <property name="javax.persistence.jdbc.user" value="XXX"/>
            <property name="javax.persistence.jdbc.password" value="XXX"/>
            <property name="javax.persistence.jdbc.driver" value="com.mysql.jdbc.Driver"/>
            <property name="javax.persistence.validation.mode" value="NONE"/>
            <property name="openjpa.Log" value="DefaultLevel=WARN, Runtime=INFO, Tool=INFO, SQL=TRACE"/>
            <property name="openjpa.ConnectionFactoryProperties" 
                      value="PrettyPrint=true, PrintParameters=true"/>      
            <property name="openjpa.Compatibility" value="default(flushBeforeDetach=false)"/>
        </properties>
    </persistence-unit>
</persistence>

Then I have timed the execution of some queries with System.currentTimeMillis() before and after the execution process and it gives me pretty different results from openjpa trace log

2333  thePU  TRACE  [qtp1769466090-14] openjpa.jdbc.SQL - <t 2143135982, conn 1825478533> [164 ms] spent
2015-06-15[INFO]xz.orm.dao.impl.util.PerfMeasureUtil stop: :: exec query time: 824ms

[164 ms] spent vs exec query time: 824ms

It is a native query joining about 4 tables. I am managing the entityManager lifetime myself - creating at the start and closing at the end of request.

/**
 * Enables the derived classes to execute read only operation using the entityManager
 *
 * @param <T>
 * @param operation
 * @return
 */
protected <T> T executeNonTransactionOperation(SimpleOperation<T> operation) {
    try {
        EntityManager entityManager = PersistenceHelper.getEntityManager();

        T result = operation.execute(entityManager);

        return result;
    } catch (Exception e) {
        //TODO: throw our custom exception?
        throw e;
    } finally {
        PersistenceHelper.closeEntityManager();
    }
}

/**
 * Enables the derived classes to execute operation (inside transaction) using the entityManager
 *
 * @param <T>
 * @param operation
 * @return
 */
protected <T> T executeTransactionOperation(SimpleOperation<T> operation) {
    try {
        EntityManager entityManager = PersistenceHelper.getEntityManager();

        PersistenceHelper.beginTransaction();
        T result = operation.execute(entityManager);
        PersistenceHelper.commit();

        return result;
    } catch (Exception e) {
        PersistenceHelper.rollback();
        //TODO: throw our custom exception?
        throw e;
    } finally {
        PersistenceHelper.closeEntityManager();
    }
}

Why is there such difference if the openjpa states it is executed that fast?

Answer 1

The problem is that you are measuring two different things.164 ms is the time that the database spent executing the query. I suspect the 824 ms that you measured is query execution + instantiation of your Entity objects.