# Performance Problem mit Prepared Statement



## DreamArtist (5. Jan 2009)

Hallo,

ich habe massive Performance Probleme wenn ich mit Hibernate auf die DB Querys absetze.

Ich verwende Hibernate3
Die Datenbank hat ca. 22 Millionen Datensätze.

Setze ich die Querys als Nativ SQL ab brauchen 100 Abfragen ca.: 5 Sekunden.
Setze ich die selben mit Hql ab, brauchen Sie 155 Sekunden.

Folgendes habe ich konfiguriert:

persistence.xml


```
<persistence-unit name="testOnDb2Test" transaction-type="RESOURCE_LOCAL">
		<provider>org.hibernate.ejb.HibernatePersistence</provider>
		<properties>
			<property name="hibernate.dialect" value="org.hibernate.dialect.DB2Dialect" />

			<property name="connection.provider_class" value="org.hibernate.connection.C3P0ConnectionProvider"/>
			<property name="hibernate.connection.url" value="jdbc:db2://localhost:50000/ODB" />
			<property name="hibernate.connection.username" value="xxx" />
			<property name="hibernate.connection.password" value="xxx" />
			<property name="hibernate.default_schema" value="xxx" />
			<property name="hibernate.cache.use_query_cache" value="true" />

			<property name="hibernate.show_sql" value="false" />
			<property name="hibernate.format_sql" value="false" />
            <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.maxStatementsPerConnection" value="50"/>
            <property name="hibernate.c3p0.idle_test_period" value="300000"/>
            
             
            <!-- 
       		-->
		      <property name="hibernate.cache.use_second_level_cache" value="true"/> 
		      <property name="hibernate.cache.provider_class" value="org.hibernate.cache.EhCacheProvider"/> 
      
			<property name="hibernate.generate_statistics" value="false" />


		</properties>
	</persistence-unit>
```

Der Code:



```
StringBuffer queryString2 = new StringBuffer();
		queryString2
		.append("select model.id.mid from Table model where model.id.id = ?");
		queryString2.append(" and model.creatstamp < ? ");
		queryString2
		.append(" and  (model.businesstype=? or model.businesstype=? or model.businesstype=? or model.businesstype=?) ");
		queryString2.append(" and (model.state = ? or model.state = ?) ");
		
		for(int c = 0; c < 100; c++){
			
			Query query = this.entityManager.createQuery(queryString2.toString());		
			org.hibernate.ejb.QueryImpl q = (org.hibernate.ejb.QueryImpl)query;
			q.getHibernateQuery().setCacheable(true);
		    query.setParameter(1, new Long(116));
			query.setParameter(2, new Timestamp(new Date().getTime()));
			query.setParameter(3, "O");
			query.setParameter(4, "T");
			query.setParameter(5, "I");
			query.setParameter(6, "C");
			query.setParameter(7, "S");
			query.setParameter(8, "E");
			System.out.println("Before Execute the Query");
			List<Disposition> dispositionList =  query.getResultList();
			System.out.println("After Execute");
			int x = 1;
			for (Disposition disposition : dispositionList) {
				System.out.print("Nr:" + (x++));
				System.out.println(disposition.getId());
			}
		}
```

Hat wer einen Tipp?

Danke


----------



## SlaterB (5. Jan 2009)

warum erzeugst du auch ständig Query-Objekte?

einmal vor der Schleife und gut, wie ein PreparedStatement


----------



## DreamArtist (7. Jan 2009)

Hallo, danke für die Antwort.

Selbst wenn ich die Query vor der Schleife erzeuge dauert es ewig.

Der Code sieht nun so aus:



```
Query query = this.entityManager.createQuery(queryString2.toString());       
org.hibernate.ejb.QueryImpl q = (org.hibernate.ejb.QueryImpl)query; 
q.getHibernateQuery().setCacheable(true); 
for(int c = 0; c < 100; c++){ 
         query.setParameter(1, new Long(116)); 
         query.setParameter(2, new Timestamp(new Date().getTime())); 
         query.setParameter(3, "O"); 
         query.setParameter(4, "T"); 
         query.setParameter(5, "I"); 
         query.setParameter(6, "C"); 
         query.setParameter(7, "S"); 
         query.setParameter(8, "E"); 
         System.out.println("Before Execute the Query"); 
         List<Disposition> dispositionList =  query.getResultList(); 
         System.out.println("After Execute"); 
         int x = 1; 
         for (Disposition disposition : dispositionList) { 
            System.out.print("Nr:" + (x++)); 
            System.out.println(disposition.getId()); 
         } 
      }
```

Seltsam ist das immer wieder das Prepared Statement geschlossen wird.
Hier die Ausgabe der Konsole:



```
Before Execute the Query
08:00:45,791 DEBUG [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
08:00:45,791 DEBUG [QueryPlanCache] located HQL query plan in cache (select model.id.merchanttrnsid from Disposition model where model.id.merchantid = ?  and model.creatstamp < ?  and  (model.businesstype=? or model.businesstype=? or model.businesstype=? or model.businesstype=?)  and (model.state = ? or model.state = ?) )
08:00:45,791 DEBUG [HQLQueryPlan] find: select model.id.merchanttrnsid from Disposition model where model.id.merchantid = ?  and model.creatstamp < ?  and  (model.businesstype=? or model.businesstype=? or model.businesstype=? or model.businesstype=?)  and (model.state = ? or model.state = ?) 
08:00:45,791 DEBUG [QueryParameters] parameters: [116, 2009-01-07 08:00:45, O, T, I, C, S, E]
08:00:45,791 DEBUG [QueryParameters] named parameters: {}
08:00:45,791 DEBUG [StandardQueryCache] checking cached query results in region: org.hibernate.cache.StandardQueryCache
08:00:45,791 DEBUG [EhCache] key: sql: select dispositio0_.MERCHANTTRNSID as col_0_0_ from PSCAPPL.DISPOSITION dispositio0_ where dispositio0_.MERCHANTID=? and dispositio0_.CREATSTAMP<? and (dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=?) and (dispositio0_.STATE=? or dispositio0_.STATE=?); parameters: 116, 2009-01-07 08:00:45.791, O, T, I, C, S, E, ; named parameters: {}
08:00:45,791 DEBUG [MemoryStore] org.hibernate.cache.StandardQueryCacheCache: org.hibernate.cache.StandardQueryCacheMemoryStore miss for sql: select dispositio0_.MERCHANTTRNSID as col_0_0_ from PSCAPPL.DISPOSITION dispositio0_ where dispositio0_.MERCHANTID=? and dispositio0_.CREATSTAMP<? and (dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=?) and (dispositio0_.STATE=? or dispositio0_.STATE=?); parameters: 116, 2009-01-07 08:00:45.791, O, T, I, C, S, E, ; named parameters: {}
08:00:45,791 DEBUG [Cache] org.hibernate.cache.StandardQueryCache cache - Miss
08:00:45,791 DEBUG [EhCache] Element for sql: select dispositio0_.MERCHANTTRNSID as col_0_0_ from PSCAPPL.DISPOSITION dispositio0_ where dispositio0_.MERCHANTID=? and dispositio0_.CREATSTAMP<? and (dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=?) and (dispositio0_.STATE=? or dispositio0_.STATE=?); parameters: 116, 2009-01-07 08:00:45.791, O, T, I, C, S, E, ; named parameters: {} is null
08:00:45,791 DEBUG [StandardQueryCache] query results were not found in cache
08:00:45,791 DEBUG [AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[b]08:00:45,791 DEBUG [ConnectionManager] opening JDBC connection[/b]
08:00:45,791 DEBUG [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1079ff [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@9f3e95)
08:00:45,791 DEBUG [code=sql] select dispositio0_.MERCHANTTRNSID as col_0_0_ from PSCAPPL.DISPOSITION dispositio0_ where dispositio0_.MERCHANTID=? and dispositio0_.CREATSTAMP<? and (dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=? or dispositio0_.BUSINESSTYPE=?) and (dispositio0_.STATE=? or dispositio0_.STATE=?)


08:00:45,791 DEBUG [AbstractBatcher] preparing statement


08:00:45,791 DEBUG [GooGooStatementCache] com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache ----> CACHE HIT
08:00:45,791 DEBUG [GooGooStatementCache] checkoutStatement: com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 2; checked out: 1; num connections: 2; num keys: 2
08:00:45,791 DEBUG [LongType] binding '116' to parameter: 1
08:00:45,791 DEBUG [TimestampType] binding '2009-01-07 08:00:45' to parameter: 2
08:00:45,791 DEBUG [StringType] binding 'O' to parameter: 3
08:00:45,791 DEBUG [StringType] binding 'T' to parameter: 4
08:00:45,791 DEBUG [StringType] binding 'I' to parameter: 5
08:00:45,791 DEBUG [StringType] binding 'C' to parameter: 6
08:00:45,791 DEBUG [StringType] binding 'S' to parameter: 7
08:00:45,791 DEBUG [StringType] binding 'E' to parameter: 8
08:00:47,275 DEBUG [AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0)
08:00:47,275 DEBUG [Loader] processing result set
08:00:47,275 DEBUG [Loader] done processing result set (0 rows)
08:00:47,275 DEBUG [AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1)


08:00:47,275 DEBUG [AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1)


08:00:47,275 DEBUG [AbstractBatcher] closing statement
08:00:47,275 DEBUG [GooGooStatementCache] checkinStatement(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
08:00:47,275 DEBUG [ConnectionManager] aggressively releasing JDBC connection
08:00:47,275 DEBUG [ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
08:00:47,275 DEBUG [GooGooStatementCache] checkinAll(): com.mchange.v2.c3p0.stmt.DoubleMaxStatementCache stats -- total size: 2; checked out: 0; num connections: 2; num keys: 2
08:00:47,275 DEBUG [BasicResourcePool] trace com.mchange.v2.resourcepool.BasicResourcePool@1079ff [managed: 5, unused: 4, excluded: 0] (e.g. com.mchange.v2.c3p0.impl.NewPooledConnection@9f3e95)
08:00:47,275 DEBUG [StatefulPersistenceContext] initializing non-lazy collections
08:00:47,275 DEBUG [StandardQueryCache] caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=5043451737088000
08:00:47,275 DEBUG [JDBCContext] after autocommit
08:00:47,275 DEBUG [ConnectionManager] aggressively releasing JDBC connection
08:00:47,275 DEBUG [SessionImpl] after transaction completion
After Execute
```

Keine Ahnung warum Hibernate immer das Statement schließt, andererseits wird das 
"normale" Statement ja auch immer geschlossen und ist viel schneller als das Prepared Statement.

Verwendet wird im übrigen eine DB2.


----------



## DreamArtist (12. Jan 2009)

Habe das Problem mittlerweile lösen können.
Die DB2 kann das Prepared Statement nicht wieder verwenden wenn mann es als Parameter übergibt.
Alle Anderen Werte können Dynamisch sein, nur der Timestamp darf es nicht.

Was ich mich noch frage: "Warum schafft die DB2 das nicht?".

Weiß vielleicht jemand warum?


----------



## GilbertGrape (12. Jan 2009)

Es ist vielleicht nicht so sinnvoll, den Thread als erledigt zu markieren, wenn du noch eine Frage hast... (man kanns auch wieder rückgängig machen)

Gruß, GG


----------



## DreamArtist (13. Okt 2010)

Sorry das die Antwort fast 2 Jahre später folgt.

Ich bin das Problem nur umgangen.
Weiß jedoch noch immer nicht warum gerade ein Timestamp das Prepared Statement in die Knie zwingt.
Wäre cool wenn wer eine Antowrt wüsste....


----------



## madboy (13. Okt 2010)

Ich vermute mal, dass der Timestamp jedes Mal identisch ist wenn du die Query manuell absetzt?
Falls ja, wird vermutlich ein Statement/Resultcache auf der DB zuschlagen und dir die Ergebnisse sehr schnell liefern, ohne wirklich erneut nach Daten zu suchen. Ändert sich der Timestamp nun gelegentlich kann kein Cache greifen, da die Query anders aussieht. Ergebnis: längere Abfragezeit.


----------

