Re: How can I tell from debug output whether setting "batchLimit" made any difference?

Mon, 01 Feb 2010 22:08:08 -0800 

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























					Reply via email to