You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@openjpa.apache.org by Bengt Rodehav <be...@rodehav.com> on 2011/12/21 17:18:03 UTC
Slow query with SQL Server
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
Re: Slow query with SQL Server
Posted by Bengt Rodehav <be...@rodehav.com>.
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
>>
>
>
Re: Slow query with SQL Server
Posted by 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
>