Path: csiph.com!eternal-september.org!feeder.eternal-september.org!mx02.eternal-september.org!.POSTED!not-for-mail
From: Cecil Westerhof <Cecil@decebal.nl>
Newsgroups: comp.lang.java.programmer
Subject: Re: Performance JPA
Date: Wed, 11 Nov 2015 23:11:42 +0100
Organization: Decebal Computing
Lines: 102
Message-ID: <8737wc425d.fsf@Equus.decebal.nl>
References: <87lhagkcsh.fsf@Equus.decebal.nl> <563763d9$0$23727$e4fe514c@news.xs4all.nl> <87d1vrk20x.fsf@Equus.decebal.nl> <n1a51v$4qh$1@dont-email.me> <87ziyvhs0r.fsf@Equus.decebal.nl> <n1b13k$rd7$1@dont-email.me> <87mvuui2ws.fsf@Equus.decebal.nl> <87si4e49ja.fsf@Equus.decebal.nl> <n1u3ne$hvk$1@speranza.aioe.org>
Mime-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Injection-Info: mx02.eternal-september.org; posting-host="528adfd6ad074c92fdc6a7f8fb9e23d8"; logging-data="23463"; mail-complaints-to="abuse@eternal-september.org";	posting-account="U2FsdGVkX19Qw7YvA8jO3US1Rmc7OAz+rmmItSLxF3A="
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.3 (gnu/linux)
Cancel-Lock: sha1:knUPit1OUumLhDe5wvTKZcL5EUE= sha1:cunax7jbb5GNUVGvvLpLHroheP8=
X-Homepage: http://www.decebal.nl/
Xref: csiph.com comp.lang.java.programmer:33108

On Wednesday 11 Nov 2015 01:56 CET, Arne Vajhøj wrote:

> On 11/10/2015 2:07 AM, Cecil Westerhof wrote:
>> On Wednesday  4 Nov 2015 09:28 CET, Cecil Westerhof wrote:
>>> No. Until now it where two completely different environments. I at
>>> last managed to get them to test on the same test database. I
>>> should soon get more trustworthy measurements.
>>
>> I got some progress. Last week the old and new version where run in
>> the same environment/database. The performance problem still stood.
>> So there is certainly a problem with the new program. Because
>> several things have changed I am not sure what would be the
>> problem, but the rest is convinced it is a JPA problem.
>
> It is very likely that performance problems in a database
> application relates to its usage of database, so it makes sense to
> focus troubleshooting on that.
>
>> In principal database logging is going to be enabled, but I am
>> waiting already a week for this.
>
> If you enable logging of the generated SQL then you can start moving
> on instead of waiting for somebody else.
>
>> Yesterday I was told that the queries themselves do not take a lot
>> of time.
>
> If that is true, which it may not be, then that points to not
> being database.
>
>> But I am told that JPA does a lot of things beside retrieving
>> things out of the database and that those other things JPA is doing
>> are the problem. Sounds far-fetched to me, but this is the first
>> time I am working with JPA. Could they be right? If so: how do we
>> pinpoint this?
>
> JPA does not do things randomly. It does what you tell it to do.

At last I have some useful metrics. It certainly looks like it that
JPA is the problem: JPA pauses 4.5 seconds before it starts executing
the datbase queries.

We use the following code:
    public T read(K id) {
        System.out.println("######################################## read enter");
        T entity = em.find(entityClass, id);
        System.out.println("######################################## read leave");
        return entity;
    }

and this results in:
    [11-11-15 15:13:53:590 CET] 000000ad SystemOut O ######################################## read enter
    [11-11-15 15:13:58:112 CET] 000000ad jdbc_SQL 3 openjpa.jdbc.SQL: Trace: <t 728215633, conn -1937712648> executing prepstmnt 212337536 SELECT …
    [11-11-15 15:13:58:118 CET] 000000ad jdbc_SQL 3 openjpa.jdbc.SQL: Trace: <t 728215633, conn -1937712648> [6 ms] spent
    [11-11-15 15:13:58:119 CET] 000000ad jdbc_JDBC 3 openjpa.jdbc.JDBC: Trace: <t 728215633, conn -1937712648> [0 ms] close
    [11-11-15 15:13:58:120 CET] 000000ad SystemOut O ######################################## read leave


Somewhere else we have:
    System.out.println("######################################## 6");

    List<BeconBericht> berichten = query.getResultList();
    System.out.println("######################################## leave");

and this results in:
    [11-11-15 15:13:58:160 CET] 000000ad SystemOut O ######################################## 6
    [11-11-15 15:13:58:161 CET] 000000ad Query 3 openjpa.Query: Trace: Executing query: [SELECT bb FROM …
    [11-11-15 15:14:02:670 CET] 000000ad jdbc_SQL 3 openjpa.jdbc.SQL: Trace: <t 728215633, conn 1696992183> executing prepstmnt -729574466 SELECT …
    [11-11-15 15:14:02:677 CET] 000000ad jdbc_SQL 3 openjpa.jdbc.SQL: Trace: <t 728215633, conn 1696992183> [6 ms] spent
    [11-11-15 15:14:02:720 CET] 000000ad jdbc_JDBC 3 openjpa.jdbc.JDBC: Trace: <t 728215633, conn 1696992183> [8 ms] close
    [11-11-15 15:14:02:720 CET] 000000ad SystemOut O ######################################## leave

It probably has to do with the database that is used. When using Derby
with Unit Tests we do not have this problem. The test where we have
this problem uses a DB2 database running on a mainframe. When Those
4.5 seconds would disappear we would have a comparable performance
with JPA as we have with JDBC I think.

It should not be a problem with the connection pool. We are using an
IBM wasserver 8.0 and this should take care of the connection pool.

The relevant parts of the persistence.xml:
    <properties>
    <property name="openjpa.Compatibility" value="QuotedNumbersInQueries=true" />
    <property name="openjpa.ConnectionDriverName" value="com.ibm.db2.jcc.DB2Driver" />
    <property name="openjpa.ConnectionFactoryProperties" value="PrintParameters=true" />
    <property name="openjpa.jdbc.DBDictionary" value="org.apache.openjpa.jdbc.sql.DB2Dictionary" />
    <property name="openjpa.Log" value="DefaultLevel=WARN, Runtime=INFO, Tool=INFO, SQL=TRACE" />
    <property name="openjpa.DataCache" value="true (EnableStatistics=false)"/>
    <property name="openjpa.RuntimeUnenhancedClasses" value="unsupported" />
    <property name="openjpa.RemoteCommitProvider" value="sjvm"/>
    <property name="openjpa.ReadLockLevel" value = "none" />
    </properties>

Anyone an idea what is happening here and what to do about it?

If any other information is needed: let me know.

-- 
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof