[JPA/Hibernate] Problème de performance

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) :

Citation:

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:

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:

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>org.hibernate.ejb.HibernatePersistence</provider> <properties>  <property name="hibernate.show_sql" value="true"/> <property name="hibernate.format_sql" value="true"/> <property name="use_sql_comments" value="false"/>  <property name="hibernate.archive.autodetection" value="none"/>  <property name="hibernate.dialect" value="org.hibernate.dialect.HSQLDialect"/>  <property name="hibernate.hbm2ddl.auto" value="update"/>  <property name="hibernate.cache.provider_class" value="org.hibernate.cache.EhCacheProvider" />  <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:

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:

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:

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 :)

Avant tout, la spécification du cache de 2ème niveau ne fait partie de JPA (du moins pour JPA 1.0, dans la v2, ça devrait être intégré).
Du point de vue Hibernate, le cache de 2ème niveau ne se limite pas qu'à définir le CacheProvider (ça serait trop facile :?)

Il faut définir la configuration du cache (fichier ehcache.xml) dans lequel tu peux préciser la capacité du cache, la péremption des données ... Chaque entrée dans ce fichier correspond à une région. L'intégration Hibernate /EhCache fonctionne de la manière suivante :

Un cache pour chaque entité mappée (nom du cache = nom complet de la classe)
Deux caches pour les requêtes (si utilisation du cache de requête) nommées org.hibernate.cache.StandardQueryCache et org.hibernate.cache.UpdateTimestampsCache

EhCache dispose d'une configuration par défaut (appelé default si je me souviens bien) qui s'applique pour chaque région mais, pour faire propre, il faut (re)définir ce paramétrage pour éviter d'avoir des caches peu performants.

D'autre part, il faut également distinguer :

cache de données (= annotation @Cache) : ce cache est utilisé lorsqu'on charge unitairement un élément (par son ID)
cache de requêtes applicable aux requêtes nommées (= annotation @NamedQueries) : ce cache est utilisé dès qu'on utilise une requête nommée (avec hibernate, il faut préciser setCacheable(true))

Attention je ne crois pas que le 1er cache soit utilisé lorsqu'on charge les données par une requête HQL (ou JPAQL) et je pense que c'est ce qui explique ce que tu constates.

Et en prime, voici quelques astuces concernant Hibernate

Merci pour ta réponse :)

Pour ce qui est du cache, j'ai effectivement créé un fichier ehcache.xml, mais pour le moment, je n'ai que le cache par défaut. Le problème c'est que je travaille avec une application modulable, les entités que j'utilise ou n'utilise pas dépendent des modules chargés, je ne peux pas donc pas écrire un fichier de config global. Est-il possible de faire des sous-fichiers de config ?

Merci pour le cache de requêtes :) J'en avais entendu parler, mais je ne l'avais pas encore mis en oeuvre, je vais essayer de modifier mon application pour l'utiliser et je vais voir ce que ça donne :)

Est-ce qu'il faut également le configurer au niveau de EhCache ou on n'a pas de changements à faire ?

Merci pour l'excellent article (très bon blog d'ailleurs que je ne connaissais pas :) ). Par contre, je ne vais pas pouvoir appliquer cette astuce, étant donné que la plupart du temps, je charge des collections d'objets et non pas des objets seulement.

Concernant le cache des requêtes, si tu ne les redéfinis pas au niveau de la configuration EhCache alors ça passera par la config 'défault'. Ceci est valable quelque soit la région. Je te conseille d'activer les statistiques d'Hibernate pour suivre l'activité du cache de 2ème niveau (hit ratio, nbre d'éléments ...) et ainsi valider l'intérêt de l'utiliser.

Pour tes collections d'objets, peut-être que tu pourrais envisager de les stocker toi-même en cache dans tes traitements (en utilisant directement l'API EhCache et sans passer par Hibernate) ? C'est moins élégant mais tu auras un meilleur contrôle sur le contenu de ce cache :roll:

Pourquoi recréer à chaque requête ton EntityManager alors que tu pourrai très bien avoir un CommonDAO dans lequel tu as un attribut EntityManager et là tu utilise l'injection de ta persistence-unit.

Chacun de tes DAOs hérite de celui ci et utilise le meme EntityManager !!

Au passage, sais-tu s'il existe un outil permettant de générer des Entity Bean respectant la spec EJB3 et les annotations JPA à partir d'un modèle XSD !!! please Help. EMF/Teneo a été utilisé pour le client mais ca respecte pas JPA car les annotations sont dans les commentaires

C'est ce que je fais maintenant. Je suis passé à Spring JPA/Spring Transaction et en gérant correctement mes caches, j'ai réussi à bien améliorer mes performances.

Maintenant j'ai des problèmes avec les transactions, mais c'est une autre histoire :P

En tout cas, merci à ceux qui ont répondu :)

Pour ce qui est de ton outil, non, je n'en ai pas connaissance, désolé.