Here is an update reflecting my latest findings.
It seems I only get bad performance when running inside Karaf. E g
retrieving all rows in the table (5800) takes about 130 ms when I run the
query as a JUnit test. In this case I do not use a JTA. I use the entity
manager's transaction support.
When running the same query in the container it takes between 60 and 70
seconds (yes seconds - not milliseconds). Something very weird is going on
here...
I've been using SQL Server's Profiler to see the actual statements being
executed and how long they take. The actual SQL statements take the same
amount of time in both scenarios (inside and outside the container). But,
when I run inside the container I can see the following:
1. The SQL Select statement is being executed (using a prepared statement).
Takes about 50-60 ms.
2. Nothing happens on the SQL Server side for over one minute. During this
period my java.exe process is utilizing 25% of my CPU (which is 100% for
the active thread since I have 4 cores).
3. After about one minute the SQL Server executes an "sp_unprepare" which I
guess is being done after the query is finished. At this time I get the
result back to my java process.
The time spent on the java side seems to be proportional to the number of
rows retrieved. If I retrieve 5800 rows it takes over a minute. If I
retrieve 330 rows it takes a few seconds.
Has anyone experienced something like this? I assume it has something to do
with Aries JTA in combination with OpenJPA (and perhaps Karaf). I will also
cross post this on the Aries list.
I appreciate any help,
/Bengt
2011/12/21 Bengt Rodehav <be...@rodehav.com>
> I'm using OpenJPA 2.1.1 on Karaf 2.2.4. I also use the aries transaction
> support (0.3). I use SQL Server 2005.
>
> I'm getting very slow query responses. Retrieving 330 rows with 5 columns
> takes almost 4 seconds (about 100 bytes per row). Running the SQL Server
> profiler I can see that the actual database time is much less (around 20-30
> ms). It seems like the time is spent in Java. I'm not 100% sure of this but
> this is my impression.
>
> If I run the query direclty from within SQL Server Management studio, the
> query is very quick (much less than one second).
>
> Here is an excerpt from my code:
>
> * public List<Customer> findCustomers(CustomerSearchCriteria
> theCriteria) {*
> * long t0 = System.nanoTime();*
> * CriteriaBuilder builder = mEntityManager.getCriteriaBuilder();*
> * long t1 = System.nanoTime();*
> * CriteriaQuery<Customer> query = builder.createQuery(Customer.class);*
> * long t2 = System.nanoTime();*
> * Root<Customer> customer = query.from(Customer.class);*
> * long t3 = System.nanoTime();*
> * query.where(createCriteria(builder, customer, theCriteria));*
> * long t4 = System.nanoTime();*
> * query.orderBy(builder.asc(customer.get(Customer_.shortName)));*
> * long t5 = System.nanoTime();*
> *
> *
> * /**
> * * Fetch the entries*
> * */*
> * TypedQuery<Customer> typedQuery = mEntityManager.createQuery(query);*
> * long t6 = System.nanoTime();*
> * List<Customer> result = typedQuery.getResultList(); *
> * long t7 = System.nanoTime();*
> * *
> * System.out.println("t1: " + (t1-t0) / 1000000 + " ms");*
> * System.out.println("t2: " + (t2-t1) / 1000000 + " ms");*
> * System.out.println("t3: " + (t3-t2) / 1000000 + " ms");*
> * System.out.println("t4: " + (t4-t3) / 1000000 + " ms");*
> * System.out.println("t5: " + (t5-t4) / 1000000 + " ms");*
> * System.out.println("t6: " + (t6-t5) / 1000000 + " ms");*
> * System.out.println("t7: " + (t7-t6) / 1000000 + " ms");*
> * *
> * return result;*
> * }*
>
> As you can see, I did some measurements. All time is spent in between t6
> and t7. I guess that is to be expected since that is where the query is
> being executed.
>
> My persistence.xml looks like this:
>
> *<?xml version="1.0" encoding="UTF-8"?>*
> *<persistence xmlns="http://java.sun.com/xml/ns/persistence"; xmlns:xsi="
> http://www.w3.org/2001/XMLSchema-instance"*
> * xsi:schemaLocation="http://java.sun.com/xml/ns/persistence
> http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd"*
> * version="2.0">*
> * <persistence-unit name="skistPU" transaction-type="JTA">*
> *
> <provider>org.apache.openjpa.persistence.PersistenceProviderImpl</provider>
> *
> * <jta-data-source>osgi:service/javax.sql.DataSource/(
> osgi.jndi.service.name=jdbc/skistory)</jta-data-source>*
> * <class>se.digia.skistory.domain.Customer</class>*
> * <class>se.digia.skistory.domain.Statement</class>*
> * <class>se.digia.skistory.domain.Transaction</class>*
> * <exclude-unlisted-classes>true</exclude-unlisted-classes>*
> * <validation-mode>NONE</validation-mode>*
> * <properties>*
> * <property name="openjpa.ConnectionFactoryMode" value="managed" />*
> * <property name="openjpa.jdbc.SynchronizeMappings"
> value="buildSchema(ForeignKeys=true)" />*
> * <property name="openjpa.jdbc.SynchronizeMappings"
> value="buildSchema(ForeignKeys=true)" />*
> * <property name="openjpa.jdbc.DBDictionary"
> value="org.apache.openjpa.jdbc.sql.SQLServerDictionary" />*
> * <property name="openjpa.jdbc.UpdateManager"
> value="operation-order" />*
> * <property name="openjpa.Log" value="DefaultLevel=INFO, Tool=INFO"
> />*
> * </properties>*
> * </persistence-unit>*
> *</persistence>*
>
> And I instantiate my datasource using Aries blueprint as follows:
>
> *<?xml version="1.0" encoding="UTF-8"?>*
> *<blueprint xmlns="http://www.osgi.org/xmlns/blueprint/v1.0.0"; xmlns:xsi="
> http://www.w3.org/2001/XMLSchema-instance"*
> * xmlns:cm="http://aries.apache.org/blueprint/xmlns/blueprint-cm/v1.1.0";
> xmlns:ext="http://aries.apache.org/blueprint/xmlns/blueprint-ext/v1.0.0"*
> * xsi:schemaLocation="http://www.osgi.org/xmlns/blueprint/v1.0.0";
> default-activation="lazy">*
> *
> *
> * <cm:property-placeholder persistent-id="skist.datasource"
> update-strategy="reload">*
> * <cm:default-properties>*
> * <cm:property name="user" value="user" />*
> * <cm:property name="password" value="password" />*
> * <cm:property name="host" value="localhost" />*
> * <cm:property name="port" value="1433" />*
> * <cm:property name="databaseName" value="skistory" />*
> * </cm:default-properties>*
> * </cm:property-placeholder>*
> *
> *
> * <bean id="skistDataSource"
> class="org.apache.commons.dbcp.BasicDataSource">*
> * <property name="username" value="${user}" />*
> * <property name="password" value="${password}" />*
> * <property name="url"
> value="jdbc:sqlserver://${host}:${port};databaseName=${databaseName};SendStringParametersAsUnicode=false"
> />*
> * <property name="driverClassName"
> value="com.microsoft.sqlserver.jdbc.SQLServerDriver" />*
> * </bean>*
> *
> *
> * <service ref="skistDataSource" interface="javax.sql.DataSource">*
> * <service-properties>*
> * <entry key="osgi.jndi.service.name" value="jdbc/skistory" />*
> * </service-properties>*
> * </service>*
> *
> *
> *</blueprint>*
>
> I first used version 1.2 of Microsoft's JDBC driver but I have now
> upgraded to version 3.0. It doesn't make any difference - actually the
> newer version was a little slower.
>
> I haven't seen this problem on MySql although I haven't measured it. Does
> anyone know how to configure OpenJPA in order to get decent performance
> with SQL Server 2005?
>
> /Bengt
>
