> -----Original Message----- > From: Patrick Linskey [mailto:plins...@gmail.com] > Sent: Monday, February 01, 2010 3:53 PM > To: users@openjpa.apache.org > Subject: Re: How can I tell from debug output whether setting > "batchLimit" made any difference? > > Hi, > > Can you post the SQL log for one of your transactions?
Here's two logs for a single transaction (with table names slightly altered for paranoia's sake), one when I didn't set "batchLimit", and the other with "batchLimit=25". without batchLimit setting: ------------- 1464622 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 82 SELECT t0.CREATION_DATE, t0.DISPLAY_NAME, t0.MIGRATION_STATUS, t1.CATALOG_ID, t2.CATEGORY_ID, t3.CATEGORY_ID, t3.DESCRIPTION, t3.DISPLAY_NAME, t3.SEO_LABEL, t2.CREATION_DATE, t2.DESCRIPTION, t2.DISPLAY_NAME FROM CATALOG t0, ROOT_CATS t1, CATEGORY t2, DCS_CATEGORY_ES t3 WHERE t0.CATALOG_ID = ? AND t0.CATALOG_ID = t1.CATALOG_ID(+) AND t1.ROOT_CAT_ID = t2.CATEGORY_ID(+) AND t2.CATEGORY_ID = t3.CATEGORY_ID(+) [params=(String) catalog1270009] 1464622 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464622 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 84 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat1530013] 1464622 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 86 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat170001] 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 88 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat170001] 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 90 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80001] 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464638 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 92 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80001] 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [15 ms] spent 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 94 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80008] 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 96 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80008] 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent 1464653 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 98 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80012] 1464669 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [16 ms] spent 1464669 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> executing prepstmnt 100 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80012] 1464669 dynamicContent TRACE [[ACTIVE] ExecuteThread: '9' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 1999815247, conn 81> [0 ms] spent ------------- with batchLimit=25: ------------- 60341 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 217 SELECT t0.CREATION_DATE, t0.DISPLAY_NAME, t0.MIGRATION_STATUS, t1.CATALOG_ID, t2.CATEGORY_ID, t3.CATEGORY_ID, t3.DESCRIPTION, t3.DISPLAY_NAME, t3.SEO_LABEL, t2.CREATION_DATE, t2.DESCRIPTION, t2.DISPLAY_NAME FROM CATALOG t0, ROOT_CATS t1, CATEGORY t2, DCS_CATEGORY_ES t3 WHERE t0.CATALOG_ID = ? AND t0.CATALOG_ID = t1.CATALOG_ID(+) AND t1.ROOT_CAT_ID = t2.CATEGORY_ID(+) AND t2.CATEGORY_ID = t3.CATEGORY_ID(+) [params=(String) catalog1270009] 60357 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60357 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 219 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat1530013] 60357 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60357 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 221 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat170001] 60372 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [15 ms] spent 60372 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 223 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat170001] 60372 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60372 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 225 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80001] 60372 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60388 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 227 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80001] 60388 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60388 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 229 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80008] 60388 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60404 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 231 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80008] 60404 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent 60404 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 233 SELECT t0.LONG_DESCRIPTION FROM DCS_CATEGORY_ES t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80012] 60419 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [15 ms] spent 60419 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> executing prepstmnt 235 SELECT t0.LONG_DESCRIPTION FROM CATEGORY t0 WHERE t0.CATEGORY_ID = ? [params=(String) cat80012] 60419 dynamicContent TRACE [[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'] openjpa.jdbc.SQL - <t 224212551, conn 216> [0 ms] spent --------- > > -Patrick > > On Feb 1, 2010, at 3:44 PM, KARR, DAVID (ATTCINW) wrote: > > > Normally, when I see a query generate the SQL, OpenJPA prints > > performance numbers after each query, like "[15 ms]". I see that on > > most of the queries, although some of them say "[0 ms]". > > > > I decided I wanted to try to turn on statement batching, as several > > operations at the transactional layer need to do several queries to > > get > > their results. I tried adding the following to my persistence.xml: > > > > <property name="openjpa.jdbc.DBDictionary" value="batchLimit=25"/> > > > > When I retested with this, it seemed to have zero effect. The SQL > > debug > > output seemed to be the same. Should I see something different if I > > set > > the "batchLimit"? > > -- > Patrick Linskey > 202 669 5907
