Another thing to be aware of is that statement batching is turned on by default for only DB2 and Oracle databases. Both of these have the batch limit set to 100 by default. The other database dictionaries are set to 0 by default. This is mainly a testing statement. If other databases are shown and proven to also support statement batching then those defaults could be modified.
Kevin On Tue, Feb 2, 2010 at 12:07 AM, Patrick Linskey <[email protected]> wrote: > Hi, > > Statement batching is really only useful in OpenJPA for transactions that > do a lot of inserts, updates or deletes; it looks like your workload is > entirely select statements. > > Also, FYI, if you turn on JDBC logging (vs. SQL logging, which you already > have on), you'll see log messages when a statement is batched. > > -Patrick > > > On Feb 1, 2010, at 4:14 PM, KARR, DAVID (ATTCINW) wrote: > > -----Original Message----- >>> From: Patrick Linskey [mailto:[email protected]] >>> Sent: Monday, February 01, 2010 3:53 PM >>> To: [email protected] >>> 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 >>> >> >> > -- > Patrick Linskey > 202 669 5907 > >
