because it involves pagination ? 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..
2013/6/11 Bjørn-Willy Arntzen [via OpenJPA] <ml-node+s208410n7584110...@n2.nabble.com>: > 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:[hidden email]] > Sendt: 11. juni 2013 11:26 > Til: [hidden email] > 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 > > > > ________________________________ > If you reply to this email, your message will be added to the discussion > below: > http://openjpa.208410.n2.nabble.com/Why-is-OpenJPA-execting-select-count-for-a-simple-select-tp7584109p7584110.html > To start a new topic under OpenJPA Users, email > ml-node+s208410n208411...@n2.nabble.com > To unsubscribe from OpenJPA Users, click here. > NAML -- View this message in context: http://openjpa.208410.n2.nabble.com/Re-Why-is-OpenJPA-execting-select-count-for-a-simple-select-tp7584415.html Sent from the OpenJPA Users mailing list archive at Nabble.com.
