Performance du cache de 2eme niveau

**youkoun** · 14/01/2009, 11h03

Bonjour,

Je fais des tests pour essayer d'améliorer les performances d'une application java qui utilise hibernate.

Du coup j'ai écrit un petit programme qui utilise le mapping de l'application et j'ai commencé à mettre un cache de 2ème niveau. Malheureusement lorsque j'active le cache des collections, l'application met plus de temps que sans cache.

Voila ce que j'ai mit :

Le fichier hibernate.cfg.xml :

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
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
 
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC "-//Hibernate/Hibernate Configuration DTD 3.0//EN" "http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
    <session-factory>
...
    <!-- <property name="connection.pool_size">1</property> -->
    <!-- C3P0 connection pool -->
        <property name="hibernate.c3p0.min_size">5</property>
        <property name="hibernate.c3p0.max_size">20</property>
        <property name="hibernate.c3p0.timeout">30000</property>
        <property name="hibernate.c3p0.max_statements">0</property>
    <!-- SQL dialect -->
    <!--
			<property name="dialect">
			org.hibernate.dialect.SQLServerDialect
			</property>
		//-->
    <!-- Enable Hibernate's automatic session context management -->
        <property name="current_session_context_class">thread</property>
    <!-- Enable the second-level cache -->
        <property name="cache.provider_class">org.hibernate.cache.EhCacheProvider</property>
        <property name="hibernate.cache.use_second_level_cache">true</property>
    <!-- Echo all executed SQL to stdout -->
        <property name="show_sql">false</property>
    <!-- Drop and re-create the database schema on startup -->
    <!-- <property name="hbm2ddl.auto">create</property> -->
        <property name="hibernate.cache.use_second_level_cache">true</property>
        <mapping resource="com/kayentis/faspharma/apidb/main/mapping/Form.hbm.xml"/>
        <mapping resource="com/kayentis/faspharma/apidb/main/mapping/Study.hbm.xml"/>
        <mapping resource="com/kayentis/faspharma/apidb/main/mapping/FieldStruct.hbm.xml"/>
        <mapping resource="com/kayentis/faspharma/apidb/main/mapping/User.hbm.xml"/>
...
 
        <class-cache class="com.kayentis.faspharma.apidb.main.FieldStruct" usage="read-only" include="all" />
        <class-cache class="com.kayentis.faspharma.apidb.main.Form" usage="read-only" include="all" />
        <collection-cache collection="com.kayentis.faspharma.apidb.main.Form.fieldsStruct" usage="read-write" />
    </session-factory>
</hibernate-configuration>

Le fichier ehcache.xml

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
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
<ehcache>
    <diskStore path="java.io.tmpdir"/>
    <defaultCache
        maxElementsInMemory="10000"
        eternal="false"
        timeToIdleSeconds="120"
        timeToLiveSeconds="120"
        overflowToDisk="true"
        diskPersistent="false"
        diskExpiryThreadIntervalSeconds="120"
        />
    <cache name="com.kayentis.faspharma.apidb.main.FieldStruct"
        maxElementsInMemory="3000"
        eternal="true"
        overflowToDisk="false"
        />
    <cache name="com.kayentis.faspharma.apidb.main.Form"
        maxElementsInMemory="300"
        eternal="false"
        overflowToDisk="false"
        timeToIdleSeconds="300"
        timeToLiveSeconds="600"
        />
    <cache name="com.kayentis.faspharma.apidb.main.User"
        maxElementsInMemory="300"
        eternal="false"
        overflowToDisk="false"
        timeToIdleSeconds="300"
        timeToLiveSeconds="600"
        />
    <cache name="com.kayentis.faspharma.apidb.main.Study"
        maxElementsInMemory="300"
        eternal="false"
        overflowToDisk="false"
        timeToIdleSeconds="300"
        timeToLiveSeconds="600"
        />
</ehcache>

Mes classes :

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
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
 
public class Main {
 
    private static final Logger LOG = Logger.getLogger(Main.class);
 
  public Main() throws InterruptedException {
        LOG.info("Main");
        int nb = 50;
        LOG.info("Close current Session");
        List listThread = new ArrayList(nb);
        for (int i = 0; i < nb; i++) {
            listThread.add(new Thread1());
        }
        for (int i = 0; i < nb; i++) {
            Thread thread = (Thread) listThread.get(i);
            thread.start();
            thread.join();
 
        }
    }
}
 
public class Thread1 extends Thread {
 
    private final Logger LOG;
 
    public Thread1() {
        LOG = Logger.getLogger(this.getName());
        LOG.debug("affectation");
    }
 
    public void run() {
        LOG.debug("start");
        Session session = UserDAO.getInstance().getSession();
        session.getSessionFactory().getStatistics().setStatisticsEnabled(true);
        LOG.debug("session : " + session.hashCode());
        LOG.debug("sessionFactory : " + session.getSessionFactory().hashCode());
        Transaction transaction = session.beginTransaction();
        User user = UserDAO.getInstance().getUserFromLogin("test", session);
        Set studies = user.getStudies();
        LOG.debug("NB study : " + studies.size());
        for (Iterator it = studies.iterator(); it.hasNext();) {
            Study study = (Study) it.next();
            Set forms = study.getForms();
            LOG.debug("NB forms : " + forms.size());
            for (Iterator itt = forms.iterator(); itt.hasNext();) {
                Form form = (Form) itt.next();
                Set fieldsStruct = form.getFieldsStruct();
                LOG.debug("NB fieldsStruct : " + fieldsStruct.size());
            }
        }
 
        transaction.commit();
        LOG.debug("User : " + user.getIdUser());
        Statistics tStats = session.getSessionFactory().getStatistics();
        LOG.debug("stat SF EntityLoadCount : " + tStats.getEntityLoadCount());
        LOG.debug("stat SF QueryCacheHitCount : " + tStats.getQueryCacheHitCount());
        LOG.debug("stat SF EntityFetchCount : " + tStats.getEntityFetchCount());
        LOG.debug("stat SF QueryExecutionCount : " + tStats.getQueryExecutionCount());
        LOG.debug("stat SF PrepareStatementCount : " + tStats.getPrepareStatementCount());
        session.close();
        LOG.debug("end");
    }
}

On voit bien avec les stat d'hiberante que les objest lus diminuent fortement quand le cache est activé. Mais le temps d'execution augmente énormément.

Vous avez une idée du pourquoi?

Youkoun

**mOuLi** · 14/01/2009, 13h54

Vu ton algo de traitement (utilisant des itérations), il serait peut-être judicieux d'intégrer d'autres caches au niveau des associations par collection. Et donc à moins qu'elles ne soient présentes dans ton fichier hibernate.cfg.xml, tu pourrais utiliser le collection-cache pour :

com.kayentis.faspharma.apidb.main.User.studies
com.kayentis.faspharma.apidb.main.Study.forms

Evidemment il faut rajouter les régions correspondantes dans ton fichier ehcache.xml.

D'autre part, il pourrait être intéressant de récupérer les stats d'activité EhCache (classe Statistics) pour qualifier ton cache (dimensionnement, hit ratio ...)

**youkoun** · 14/01/2009, 14h35

Je les avais mis mais cela ne changeait rien sur les perf. Idem pour la conf ehcache...

Je vais regarder pour les stat d'ehcache...

Youkoun

**youkoun** · 14/01/2009, 14h56

Voila les stats :
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF EntityLoadCount : 557
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF QueryCacheHitCount : 0
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF EntityFetchCount : 49
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF QueryExecutionCount : 50
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF PrepareStatementCount : 451
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF SecondLevelCachePutCount : 466
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF SecondLevelCacheHitCount : 22834
Thread-49 2009-01-14 14:54:59,796 [DEBUG] - stat SF SecondLevelCacheMissCount : 9

Ca prouve que le cache marche bien... Plus qu'a trouver pourquoi il ralentit l'application...

Youkoun