Bonjour,

J'ai actuellement, un gros problème de performance au niveau du chargement de mon application.

Je fais plusieurs fois des récupérations de toutes les données d'une certaines classes et apparemment, rien n'est conservé dans le cache de premier niveau ni dans le second apparemment non plus (j'ai EhCache de configuré).

Voilà la trace qui apparait lors de la récupération de tous les acteurs (ActorImpl) :

18:36:38,187 DEBUG SessionImpl:247 - opened session at timestamp: 5075090629373952
18:36:38,188 TRACE QueryPlanCache:92 - unable to locate HQL query plan in cache; generating (select d from org.jtheque.films.persistence.od.ActorImpl d)
18:36:38,188 DEBUG QueryTranslatorImpl:269 - parse() - HQL: select d from org.jtheque.films.persistence.od.ActorImpl d
18:36:38,198 DEBUG AST:289 - --- HQL AST ---
\-[QUERY] 'query'
\-[SELECT_FROM] 'SELECT_FROM'
+-[FROM] 'from'
| \-[RANGE] 'RANGE'
| +-[DOT] '.'
| | +-[DOT] '.'
| | | +-[DOT] '.'
| | | | +-[DOT] '.'
| | | | | +-[DOT] '.'
| | | | | | +-[IDENT] 'org'
| | | | | | \-[IDENT] 'jtheque'
| | | | | \-[IDENT] 'films'
| | | | \-[IDENT] 'persistence'
| | | \-[IDENT] 'od'
| | \-[IDENT] 'ActorImpl'
| \-[ALIAS] 'd'
\-[SELECT] 'select'
\-[IDENT] 'd'

18:36:38,199 DEBUG ErrorCounter:91 - throwQueryException() : no errors
18:36:38,199 DEBUG HqlSqlBaseWalker:111 - select << begin [level=1, statement=select]
18:36:38,199 DEBUG FromElement:129 - FromClause{level=1} : org.jtheque.films.persistence.od.ActorImpl (d) -> actorimpl0_
18:36:38,200 DEBUG FromReferenceNode:74 - Resolved : d -> actorimpl0_.ID
18:36:38,200 DEBUG HqlSqlBaseWalker:117 - select : finishing up [level=1, statement=select]
18:36:38,201 DEBUG HqlSqlWalker:531 - processQuery() : ( SELECT ( {select clause} actorimpl0_.ID ) ( FromClause{level=1} OD_ACTOR actorimpl0_ ) )
18:36:38,201 DEBUG JoinProcessor:171 - Using FROM fragment [OD_ACTOR actorimpl0_]
18:36:38,201 DEBUG HqlSqlBaseWalker:123 - select >> end [level=1, statement=select]
18:36:38,202 DEBUG AST:255 - --- SQL AST ---
\-[SELECT] QueryNode: 'SELECT' querySpaces (OD_ACTOR)
+-[SELECT_CLAUSE] SelectClause: '{select clause}'
| +-[ALIAS_REF] IdentNode: 'actorimpl0_.ID as ID1_' {alias=d, className=org.jtheque.films.persistence.od.ActorImpl, tableAlias=actorimpl0_}
| \-[SQL_TOKEN] SqlFragment: 'actorimpl0_.VERSION as VERSION1_, actorimpl0_.FIRSTNAME as FIRSTNAME1_, actorimpl0_.NAME as NAME1_, actorimpl0_.THE_COUNTRY_FK as THE6_1_, actorimpl0_.NOTE as NOTE1_'
\-[FROM] FromClause: 'from' FromClause{level=1, fromElementCounter=1, fromElements=1, fromElementByClassAlias=[d], fromElementByTableAlias=[actorimpl0_], fromElementsByPath=[], collectionJoinFromElementsByPath=[], impliedElements=[]}
\-[FROM_FRAGMENT] FromElement: 'OD_ACTOR actorimpl0_' FromElement{explicit,not a collection join,not a fetch join,fetch non-lazy properties,classAlias=d,role=null,tableName=OD_ACTOR,tableAlias=actorimpl0_,origin=null,colums={,className=org.jtheque.films.persistence.od.ActorImpl}}

18:36:38,204 DEBUG ErrorCounter:91 - throwQueryException() : no errors
18:36:38,204 DEBUG QueryTranslatorImpl:239 - HQL: select d from org.jtheque.films.persistence.od.ActorImpl d
18:36:38,204 DEBUG QueryTranslatorImpl:240 - SQL: select actorimpl0_.ID as ID1_, actorimpl0_.VERSION as VERSION1_, actorimpl0_.FIRSTNAME as FIRSTNAME1_, actorimpl0_.NAME as NAME1_, actorimpl0_.THE_COUNTRY_FK as THE6_1_, actorimpl0_.NOTE as NOTE1_ from OD_ACTOR actorimpl0_
18:36:38,205 DEBUG ErrorCounter:91 - throwQueryException() : no errors
18:36:38,205 TRACE HQLQueryPlan:293 - HQL param location recognition took 0 mills (select d from org.jtheque.films.persistence.od.ActorImpl d)
18:36:38,205 TRACE QueryPlanCache:98 - located HQL query plan in cache (select d from org.jtheque.films.persistence.od.ActorImpl d)
18:36:38,206 TRACE HQLQueryPlan:174 - find: select d from org.jtheque.films.persistence.od.ActorImpl d
18:36:38,206 TRACE QueryParameters:300 - named parameters: {}
18:36:38,671 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
18:36:38,671 DEBUG ConnectionManager:444 - opening JDBC connection
18:36:38,671 TRACE DriverManagerConnectionProvider:116 - total checked-out connections: 0
18:36:38,672 TRACE DriverManagerConnectionProvider:122 - using pooled JDBC connection, pool size: 0
18:36:38,675 DEBUG SQL:111 -
select
actorimpl0_.ID as ID1_,
actorimpl0_.VERSION as VERSION1_,
actorimpl0_.FIRSTNAME as FIRSTNAME1_,
actorimpl0_.NAME as NAME1_,
actorimpl0_.THE_COUNTRY_FK as THE6_1_,
actorimpl0_.NOTE as NOTE1_
from
OD_ACTOR actorimpl0_
Hibernate:
select
actorimpl0_.ID as ID1_,
actorimpl0_.VERSION as VERSION1_,
actorimpl0_.FIRSTNAME as FIRSTNAME1_,
actorimpl0_.NAME as NAME1_,
actorimpl0_.THE_COUNTRY_FK as THE6_1_,
actorimpl0_.NOTE as NOTE1_
from
OD_ACTOR actorimpl0_
18:36:38,676 TRACE AbstractBatcher:513 - preparing statement
18:36:39,081 DEBUG AbstractBatcher:426 - about to open ResultSet (open ResultSets: 0, globally: 0)
18:36:39,082 TRACE Loader:717 - processing result set
18:36:39,083 DEBUG Loader:722 - result set row: 0
18:36:39,083 TRACE IntegerType:193 - returning '1' as column: ID1_
18:36:39,083 DEBUG Loader:1197 - result row: EntityKey[org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,084 TRACE Loader:1379 - Initializing object from ResultSet: [org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,084 TRACE AbstractEntityPersister:2059 - Hydrating entity: [org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,084 TRACE IntegerType:193 - returning '0' as column: VERSION1_
18:36:39,085 TRACE StringType:193 - returning 'Sean' as column: FIRSTNAME1_
18:36:39,086 TRACE StringType:193 - returning 'Connery' as column: NAME1_
18:36:39,086 TRACE IntegerType:193 - returning '1' as column: THE6_1_
18:36:39,086 TRACE TwoPhaseLoad:98 - Version: 0
18:36:39,086 DEBUG Loader:722 - result set row: 1
18:36:39,087 TRACE IntegerType:193 - returning '2' as column: ID1_
18:36:39,087 DEBUG Loader:1197 - result row: EntityKey[org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,088 TRACE Loader:1379 - Initializing object from ResultSet: [org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,088 TRACE AbstractEntityPersister:2059 - Hydrating entity: [org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,088 TRACE IntegerType:193 - returning '0' as column: VERSION1_
18:36:39,089 TRACE StringType:193 - returning 'Angelina' as column: FIRSTNAME1_
18:36:39,089 TRACE StringType:193 - returning 'Jolie' as column: NAME1_
18:36:39,090 TRACE IntegerType:193 - returning '1' as column: THE6_1_
18:36:39,090 TRACE TwoPhaseLoad:98 - Version: 0
18:36:39,090 TRACE Loader:744 - done processing result set (2 rows)
18:36:39,090 DEBUG AbstractBatcher:433 - about to close ResultSet (open ResultSets: 1, globally: 1)
18:36:39,091 DEBUG AbstractBatcher:418 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
18:36:39,091 TRACE AbstractBatcher:562 - closing statement
18:36:39,092 DEBUG ConnectionManager:427 - aggressively releasing JDBC connection
18:36:39,092 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
18:36:39,093 TRACE DriverManagerConnectionProvider:152 - returning connection to pool, pool size: 1
18:36:39,093 TRACE Loader:874 - total objects hydrated: 2
18:36:39,093 DEBUG TwoPhaseLoad:130 - resolving associations for [org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,094 TRACE DefaultLoadEventListener:199 - loading entity: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,094 TRACE DefaultLoadEventListener:372 - attempting to resolve: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,094 TRACE DefaultLoadEventListener:409 - object not resolved in any cache: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,095 TRACE AbstractEntityPersister:3065 - Fetching entity: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,096 DEBUG Loader:1873 - loading entity: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,096 DEBUG AbstractBatcher:410 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
18:36:39,097 DEBUG ConnectionManager:444 - opening JDBC connection
18:36:39,097 TRACE DriverManagerConnectionProvider:116 - total checked-out connections: 0
18:36:39,097 TRACE DriverManagerConnectionProvider:122 - using pooled JDBC connection, pool size: 0
18:36:39,099 DEBUG SQL:111 -
select
countryimp0_.ID as ID9_0_,
countryimp0_.VERSION as VERSION9_0_,
countryimp0_.NAME as NAME9_0_
from
OD_COUNTRY countryimp0_
where
countryimp0_.ID=?
Hibernate:
select
countryimp0_.ID as ID9_0_,
countryimp0_.VERSION as VERSION9_0_,
countryimp0_.NAME as NAME9_0_
from
OD_COUNTRY countryimp0_
where
countryimp0_.ID=?
18:36:39,099 TRACE AbstractBatcher:513 - preparing statement
18:36:39,107 TRACE IntegerType:151 - binding '1' to parameter: 1
18:36:39,107 DEBUG AbstractBatcher:426 - about to open ResultSet (open ResultSets: 0, globally: 0)
18:36:39,108 TRACE Loader:717 - processing result set
18:36:39,109 DEBUG Loader:722 - result set row: 0
18:36:39,109 DEBUG Loader:1197 - result row: EntityKey[org.jtheque.primary.od.CountryImpl#1]
18:36:39,109 TRACE Loader:1379 - Initializing object from ResultSet: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,110 TRACE AbstractEntityPersister:2059 - Hydrating entity: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,110 TRACE IntegerType:193 - returning '0' as column: VERSION9_0_
18:36:39,111 TRACE StringType:193 - returning 'USA' as column: NAME9_0_
18:36:39,111 TRACE TwoPhaseLoad:98 - Version: 0
18:36:39,111 TRACE Loader:744 - done processing result set (1 rows)
18:36:39,112 DEBUG AbstractBatcher:433 - about to close ResultSet (open ResultSets: 1, globally: 1)
18:36:39,112 DEBUG AbstractBatcher:418 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
18:36:39,113 TRACE AbstractBatcher:562 - closing statement
18:36:39,257 DEBUG ConnectionManager:427 - aggressively releasing JDBC connection
18:36:39,257 DEBUG ConnectionManager:464 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
18:36:39,258 TRACE DriverManagerConnectionProvider:152 - returning connection to pool, pool size: 1
18:36:39,259 TRACE Loader:874 - total objects hydrated: 1
18:36:39,259 DEBUG TwoPhaseLoad:130 - resolving associations for [org.jtheque.primary.od.CountryImpl#1]
18:36:39,260 DEBUG TwoPhaseLoad:226 - done materializing entity [org.jtheque.primary.od.CountryImpl#1]
18:36:39,260 DEBUG Loader:1904 - done entity load
18:36:39,261 DEBUG TwoPhaseLoad:158 - adding entity to second-level cache: [org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,261 TRACE ReadWriteCache:173 - Caching: org.jtheque.films.persistence.od.ActorImpl#1
18:36:39,261 DEBUG EhCache:74 - key: org.jtheque.films.persistence.od.ActorImpl#1
18:36:39,262 TRACE MemoryStore:138 - org.jtheque.films.persistence.od.ActorImplCache: org.jtheque.films.persistence.od.ActorImplMemoryStore miss for org.jtheque.films.persistence.od.ActorImpl#1
18:36:39,262 TRACE Cache:661 - org.jtheque.films.persistence.od.ActorImpl cache - Miss
18:36:39,263 DEBUG EhCache:83 - Element for org.jtheque.films.persistence.od.ActorImpl#1 is null
18:36:39,263 TRACE ReadWriteCache:185 - Cached: org.jtheque.films.persistence.od.ActorImpl#1
18:36:39,263 DEBUG TwoPhaseLoad:226 - done materializing entity [org.jtheque.films.persistence.od.ActorImpl#1]
18:36:39,264 DEBUG TwoPhaseLoad:130 - resolving associations for [org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,264 TRACE DefaultLoadEventListener:199 - loading entity: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,264 TRACE DefaultLoadEventListener:372 - attempting to resolve: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,265 TRACE DefaultLoadEventListener:389 - resolved object in session cache: [org.jtheque.primary.od.CountryImpl#1]
18:36:39,266 DEBUG TwoPhaseLoad:158 - adding entity to second-level cache: [org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,266 TRACE ReadWriteCache:173 - Caching: org.jtheque.films.persistence.od.ActorImpl#2
18:36:39,266 DEBUG EhCache:74 - key: org.jtheque.films.persistence.od.ActorImpl#2
18:36:39,266 TRACE MemoryStore:138 - org.jtheque.films.persistence.od.ActorImplCache: org.jtheque.films.persistence.od.ActorImplMemoryStore miss for org.jtheque.films.persistence.od.ActorImpl#2
18:36:39,740 TRACE Cache:661 - org.jtheque.films.persistence.od.ActorImpl cache - Miss
18:36:39,741 DEBUG EhCache:83 - Element for org.jtheque.films.persistence.od.ActorImpl#2 is null
18:36:39,742 TRACE ReadWriteCache:185 - Cached: org.jtheque.films.persistence.od.ActorImpl#2
18:36:39,742 DEBUG TwoPhaseLoad:226 - done materializing entity [org.jtheque.films.persistence.od.ActorImpl#2]
18:36:39,743 DEBUG StatefulPersistenceContext:860 - initializing non-lazy collections
18:36:39,743 TRACE JDBCContext:260 - after autocommit
18:36:39,743 DEBUG ConnectionManager:427 - aggressively releasing JDBC connection
18:36:39,744 TRACE SessionImpl:449 - after transaction completion
18:36:39,744 DEBUG PersistenceManager:64 - GetList for : org.jtheque.films.persistence.od.ActorImpl : 2 results.
A noter que la partie AST n'est repetée que la première fois.

On peut voir cette trace de nombreuses fois et il me semble que normalement, il ne devrait pas rééxécuter la requête SQL.

Au niveau de l'entityManager, je le crée pour chaque requête :

Code Java : Sélectionner tout - Visualiser dans une fenêtre à part
1
2
3
public EntityManager getEntityManager() {
     return emf.createEntityManager();
}

mais je ne le ferme pas, car j'avais des problèmes avec le lazy-loading lorsque je fermais l'entitymanager après avoir récupéré des entités qui sont liées à d'autres entités.

Je ne le ferme que dans le cas d'une requête de modification.

De plus, est-ce normal que toutes les connexions JDBC soient directement fermées ?

Voici mon fichier de persistence :

Code XML : Sélectionner tout - Visualiser dans une fenêtre à part
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
<?xml version="1.0" encoding="UTF-8"?>
<persistence version="1.0" xmlns="http://java.sun.com/xml/ns/persistence">
    <persistence-unit name="jtheque" transaction-type="RESOURCE_LOCAL">
        <!--  Provider -->
        <provider>org.hibernate.ejb.HibernatePersistence</provider>
 
        <properties>
            <!-- Commentaires SQL -->
            <property name="hibernate.show_sql" value="true"/>
            <property name="hibernate.format_sql" value="true"/>
            <property name="use_sql_comments" value="false"/>
 
            <!-- Auto détection -->
            <property name="hibernate.archive.autodetection" value="none"/>
 
            <!-- Dialect -->
            <property name="hibernate.dialect" value="org.hibernate.dialect.HSQLDialect"/>
 
            <!-- SQL Schema generator -->
            <property name="hibernate.hbm2ddl.auto" value="update"/>
 
            <!-- Cache de second niveau -->
            <property name="hibernate.cache.provider_class" value="org.hibernate.cache.EhCacheProvider" />
 
            <!-- Pool de connexion c3p0 -->
            <property name="hibernate.c3p0.min_size" value="5" />
            <property name="hibernate.c3p0.max_size" value="20" />
            <property name="hibernate.c3p0.timeout" value="300" />
            <property name="hibernate.c3p0.max_statements" value="50" />
            <property name="hibernate.c3p0.idle_test_period" value="3000" />
        </properties>
    </persistence-unit>
</persistence>

et voici une de mes entités :

Classe fille :

Code Java : Sélectionner tout - Visualiser dans une fenêtre à part
1
2
3
4
5
6
7
@Entity
@Table(
        name = "OD_ACTOR",
        uniqueConstraints =
        @UniqueConstraint(columnNames = {"NAME", "FIRSTNAME"}))
@Cache(usage = CacheConcurrencyStrategy.READ_WRITE)
public class ActorImpl extends Actor {...

Classe parente :

Code : Sélectionner tout - Visualiser dans une fenêtre à part
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
@MappedSuperclass
public abstract class Person extends Data {
    ...
 
    @Column(name = "NAME", length = 100, nullable = false)
    public String getName() {
        return name;
    }
 
    @Column(name = "FIRSTNAME", length = 100, nullable = false)
    public String getFirstName() {
        return firstName;
    }
 
    @ManyToOne(optional = true)
    @JoinColumn(
            name = "THE_COUNTRY_FK",
            unique = false,
            nullable = true
    )
    public CountryImpl getTheCountry() {
        return theCountry;
    }
Code : Sélectionner tout - Visualiser dans une fenêtre à part
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
@MappedSuperclass
public abstract class Entity implements Comparable<Entity> {
    ... 
 
    @Id
    @Column(name = "ID", nullable = false)
    @GeneratedValue(strategy = GenerationType.AUTO)
    public final int getId() {
        return id;
    }
 
    @Column(name = "VERSION", nullable = false)
    @Version
    public int getVersion() {
        return version;
    }
Est-ce qu'il y a quelque chose que je fais faux ? Est-ce que vous avez des trucs et astuces pour améliorer les performances ? N'hésitez pas à me faire part de toutes vos propositions.

Je pense que ça doit forcément venir de quelque chose que je fais vraiment faux car tous les retours que j'ai eu sur Hibernate/JPA sont très bon et font état de bonnes performances tandis que là, me semble que c'est plutôt lent.

Merci