I apologize to everyone. I just found out that the performance problems
were caused by having set a log level to TRACE. When I changed that to
INFO, the response time for retrieving 5800 rows shrunk to less than 200 ms.
When running the query in my JUnit test I was already using a log level of
INFO which explains the big difference in performance.
/Bengt
2011/12/22 Bengt Rodehav <be...@rodehav.com>
> 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
>>
>
>
