Ok, found one issue by my self... The 4 seconds delay is due to a non connection pooling datasource. It is quite fast after replacing it with org.springframework.jdbc.datasource.SingleConnectionDataSource.
Then only one issue is left : Why is OpenJPA executing select count(*) for a simple select ? Med vennlig hilsen / Regards from Bjørn-Willy Arntzen -----Opprinnelig melding----- Fra: Bjørn-Willy Arntzen [mailto:b...@klp.no] Sendt: 11. juni 2013 11:26 Til: users@openjpa.apache.org Emne: Why is OpenJPA execting select count(*) for a simple select ? I have this quite simple query with OpenJPA 2.0.1: @Query("SELECT y FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3") Page<Shadow> findByInsurerAndOrgNumberAndUnitNumber(String insurer, String orgNumber, String unitNumber, Pageable pageable); But is take very long time to execute. If I executes the generated SQL query in DBVizualizer is runs for just a couple of milliseconds. But is I run it in my Jetty environment it takes 10 seconds ... My log4j setting is trace all: <category name="openjpa" additivity="false"> <priority value="trace" /> <appender-ref ref="stdout" /> </category> Below is my trace : 1) Why is my JPA executing a select count(*) ? 2) Why is it taking over 4 seconds from the 11:09:24,395 DEBUG Query:73 to 11:09:29,034 DEBUG SQL:73 ? 3) And a another 4 seconds from 11:09:29,086 DEBUG SQLDiag:73 to 11:09:33,620 DEBUG SQL:73 ? 4) The actually DB2 executing seems to take less than 100 ms ... 11:09:24,226 DEBUG Runtime:73 - Found datasource1: datasource 140254981 from configuration. StoreContext: org.apache.openjpa.kernel.BrokerImpl@10a80b13 11:09:24,355 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:24,360 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:24,362 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:24,394 DEBUG Runtime:73 - Query "select count(y) FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" is cached." 11:09:24,395 DEBUG Query:73 - Executing query: [select count(y) FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3] with parameters: {1=1000, 2=00106, 3=001} 11:09:29,034 DEBUG SQL:73 - <t 831357506, conn 1183016620> executing prepstmnt 1880763659 SELECT COUNT(*) FROM T40008 t0 WHERE (t0.k_fgiv_refid = ? AND t0.org_nbr = ? AND t0.unt_nbr = ?) optimize for 1 row [params=?, ?, ?] 11:09:29,057 DEBUG SQL:73 - <t 831357506, conn 1183016620> [23 ms] spent 11:09:29,071 DEBUG JDBC:73 - <t 831357506, conn 1183016620> [11 ms] close 11:09:29,073 DEBUG Runtime:73 - Query "select count(y) FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" is removed from cache excluded permanently. Query "select count(y) FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" is not cached because it returns a single value rather than a list. A query that returns single value can not be cached. . 11:09:29,074 DEBUG Runtime:73 - Found datasource1: datasource 140254981 from configuration. StoreContext: org.apache.openjpa.kernel.BrokerImpl@21c98878 11:09:29,076 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:29,078 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:29,079 DEBUG MetaData:73 - Parsing class "java.lang.String". 11:09:29,080 DEBUG Runtime:73 - Query "SELECT y FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" is cached." 11:09:29,080 DEBUG Query:73 - Executing query: [SELECT y FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3] with parameters: {1=1000, 2=00106, 3=001} 11:09:29,086 DEBUG SQLDiag:73 - Eager relations: [no.klp.nettpensjon.bp.dao.entities.Shadow.nameAddress] 11:09:33,620 DEBUG SQL:73 - <t 831357506, conn 2125031061> executing prepstmnt 1103958842 SELECT t0.K_KATEGORI, t0.sos_sec_nbr, t0.org_nbr, t0.rsk_cmy_id, t0.L_SEKVENSNR, t0.unt_nbr, t0.agelimit, t0.b_hovedlonn, t0.PEN_SPM_SAL_AMT, t0.K_YTELSE, t0.BEST_ART, t0.K_KUND_ANSATTNR, t0.K_AVDELINGSNR, t0.eff_dt, t0.ocp_cd, t0.emp_pct, t0.k_fgiv_refid, t0.K_MEDL_ANSATTNR, t1.sos_sec_nbr, t1.adr_1, t1.fst_nm, t1.lst_nm, t1.post_cd, t0.K_FORS_TAKER, t0.sal_grd_cd, t0.status FROM T40008 t0 LEFT OUTER JOIN T40007 t1 ON t0.sos_sec_nbr = t1.sos_sec_nbr WHERE (t0.k_fgiv_refid = ? AND t0.org_nbr = ? AND t0.unt_nbr = ?) FETCH FIRST 50 ROWS ONLY [params=?, ?, ?] 11:09:33,677 DEBUG SQL:73 - <t 831357506, conn 2125031061> [57 ms] spent 11:09:33,753 DEBUG JDBC:73 - <t 831357506, conn 2125031061> [11 ms] close 11:09:33,755 DEBUG Runtime:73 - Query "SELECT y FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" is removed from cache excluded permanently. This query "SELECT y FROM Shadow y WHERE y.insurer = ?1 AND y.orgNumber = ?2 AND y.unitNumber = ?3" involves pagination and is not cached.. Any suggestions would be appreciated. Med vennlig hilsen / Regards from Bjørn-Willy Arntzen Seniorkonsulent IT Kommunal Landspensjonskasse gjensidig forsikringsselskap Dronning Eufemias gate 10, 0191 Oslo, Pb 400, Sentrum, 0103 Oslo Mob: +4797759007 www.klp.no<http://www.klp.no/> Vennligst tenk på miljøet før du skriver ut denne e-posten
