Return-Path: Delivered-To: apmail-incubator-open-jpa-dev-archive@locus.apache.org Received: (qmail 24000 invoked from network); 17 Oct 2006 20:38:52 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199) by minotaur.apache.org with SMTP; 17 Oct 2006 20:38:52 -0000 Received: (qmail 78840 invoked by uid 500); 17 Oct 2006 20:38:51 -0000 Delivered-To: apmail-incubator-open-jpa-dev-archive@incubator.apache.org Received: (qmail 78813 invoked by uid 500); 17 Oct 2006 20:38:51 -0000 Mailing-List: contact open-jpa-dev-help@incubator.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: open-jpa-dev@incubator.apache.org Delivered-To: mailing list open-jpa-dev@incubator.apache.org Received: (qmail 78804 invoked by uid 99); 17 Oct 2006 20:38:51 -0000 Received: from asf.osuosl.org (HELO asf.osuosl.org) (140.211.166.49) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 17 Oct 2006 13:38:51 -0700 X-ASF-Spam-Status: No, hits=2.0 required=10.0 tests=HTML_MESSAGE X-Spam-Check-By: apache.org Received-SPF: pass (asf.osuosl.org: local policy) Received: from [66.160.117.11] (HELO ptint5.peacetech.com) (66.160.117.11) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 17 Oct 2006 13:38:43 -0700 X-MimeOLE: Produced By Microsoft Exchange V6.5 Content-class: urn:content-classes:message MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="----_=_NextPart_001_01C6F22C.27941508" Subject: RE: Why would Kodo refuse to batch inserts in certain tables? Big performance drop migrating to Kodo 4.1 Date: Tue, 17 Oct 2006 16:38:07 -0400 Message-ID: <49BF64BA795F6A498EC2F04F39BAA8D3D97EDE@ptint5.peacetech.com> X-MS-Has-Attach: X-MS-TNEF-Correlator: Thread-Topic: Why would Kodo refuse to batch inserts in certain tables? Big performance drop migrating to Kodo 4.1 Thread-Index: AcbyK7xjmQ1Qz1//TeqRwdVHoP/rtgAACoZg From: "Roytman, Alex" To: X-Virus-Checked: Checked by ClamAV on apache.org X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N ------_=_NextPart_001_01C6F22C.27941508 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Yes it will be wrapped by email though =20 15 WARN [main] openjpa.Runtime - The property named "kodo.jdbc.SequenceFactory" was not recognized and will be ignored, although the name closely matches a valid property called "kodo.jdbc.SchemaFactory". 15 WARN [main] openjpa.Runtime - The property named "kodo.jdbc.ClassIndicator" was not recognized and will be ignored, although the name closely matches a valid property called "kodo.jdbc.MappingFactory". 47 INFO [main] openjpa.Runtime - Starting BEA Kodo 4.1.0 with patches:=20 Kodo JDO Utilities vtip-revision 62 INFO [main] openjpa.jdbc.JDBC - Using dictionary class "org.apache.openjpa.jdbc.sql.OracleDictionary". 328 INFO [main] openjpa.jdbc.JDBC - oracle-batch-override 1578 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 21057622 SELECT t0.JDO_LOCK, t0.IS_ACTIVE, t0.DEFAULT_VALUE, t0.DESCRIPTION, t0.IS_LOOKUP, t0.LOOKUP_SORT_ORDER, t0.IS_MULTI_VALUE FROM DTS.PROPERTY_DEFINITION t0 WHERE t0.NAME =3D ? [params=3D(String) IC] 1578 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1593 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 21057622 SELECT t0.JDO_LOCK, t0.IS_ACTIVE, t0.DEFAULT_VALUE, t0.DESCRIPTION, t0.IS_LOOKUP, t0.LOOKUP_SORT_ORDER, t0.IS_MULTI_VALUE FROM DTS.PROPERTY_DEFINITION t0 WHERE t0.NAME =3D ? [params=3D(String) DocType] 1593 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1593 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 21057622 SELECT t0.JDO_LOCK, t0.IS_ACTIVE, t0.DEFAULT_VALUE, t0.DESCRIPTION, t0.IS_LOOKUP, t0.LOOKUP_SORT_ORDER, t0.IS_MULTI_VALUE FROM DTS.PROPERTY_DEFINITION t0 WHERE t0.NAME =3D ? [params=3D(String) GC] 1593 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1593 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 21057622 SELECT t0.JDO_LOCK, t0.IS_ACTIVE, t0.DEFAULT_VALUE, t0.DESCRIPTION, t0.IS_LOOKUP, t0.LOOKUP_SORT_ORDER, t0.IS_MULTI_VALUE FROM DTS.PROPERTY_DEFINITION t0 WHERE t0.NAME =3D ? [params=3D(String) ClauseId] 1593 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 15513215 INSERT INTO DTS.DOCUMENT (DOCUMENT_NODE_ID, DOCUMENT_NUMBER, TEMPLATE_ID, ORG_UNIT_ID, PREPARER, TITLE, IS_PUBLISHED, PUBLISH_DATE) VALUES (?, ?, ?, ?, ?, ?, ?, ?) [params=3D(long) 529800, (String) {529800}, (long) 9432, (long) 1, = (long) 1, (null) null, (int) 0, (null) null] 1625 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 12675864 INSERT INTO DTS.DOCUMENT_FIELD (DOCUMENT_NODE_ID, NAME, CONTENT_ID, VALUE, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?) [params=3D(long) 529802, (String) preferences, (long) 2117, (null) null, (int) 520, (int) 1] 1625 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 12675864 INSERT INTO DTS.DOCUMENT_FIELD (DOCUMENT_NODE_ID, NAME, CONTENT_ID, VALUE, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?) [params=3D(long) 529801, (String) preferences, (long) 2116, (null) null, (int) 520, (int) 1] 1625 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 12675864 INSERT INTO DTS.DOCUMENT_FIELD (DOCUMENT_NODE_ID, NAME, CONTENT_ID, VALUE, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?) [params=3D(long) 529802, (String) address, (long) = 2117, (null) null, (int) 510, (int) 1] 1625 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 12675864 INSERT INTO DTS.DOCUMENT_FIELD (DOCUMENT_NODE_ID, NAME, CONTENT_ID, VALUE, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?) [params=3D(long) 529801, (String) address, (long) = 2116, (null) null, (int) 510, (int) 1] 1625 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1625 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 12675864 INSERT INTO DTS.DOCUMENT_FIELD (DOCUMENT_NODE_ID, NAME, CONTENT_ID, VALUE, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?) [params=3D(long) 529801, (String) address, (long) = 2116, (null) null, (int) 510, (int) 1] 1640 TRACE [main] openjpa.jdbc.SQL - [15 ms] spent 1640 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 6169134 INSERT INTO DTS.DOCUMENT_NODE (DOCUMENT_NODE_ID, OWNER_DOCUMENT, LOCAL_ROOT, PARENT, NAME, CREATE_DATE, UPDATE_DATE, UPDATE_USER, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [params=3D(long) 529800, (long) 529800, = (long) 529800, (null) null, (String) d529800, (Date) 2006-10-16, (Date) 2006-10-16, (String) dts.test, (int) 440, (int) 1] 1640 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1640 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 1440568 INSERT INTO DTS.DOCUMENT_NODE (DOCUMENT_NODE_ID, OWNER_DOCUMENT, LOCAL_ROOT, PARENT, PARENT_SORT_ORDER, NAME, CONTENT_ID, ORIGINAL_CONTENT, REFERENCE_NUMBER, IS_GROUP, IS_SELECTED_BY_USER, IS_SELECTED_BY_RULE, CREATE_DATE, UPDATE_DATE, UPDATE_USER, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [params=3D(long) 529801, (long) 529800, (long) 529800, (long) 529800, (int) 0, (String) t1, (long) 2116, (null) null, (null) null, (int) 0, (null) null, (int) 0, (Date) 2006-10-16, (Date) 2006-10-16, (String) dts.test, (int) 430, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [16 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 1440568 INSERT INTO DTS.DOCUMENT_NODE (DOCUMENT_NODE_ID, OWNER_DOCUMENT, LOCAL_ROOT, PARENT, PARENT_SORT_ORDER, NAME, CONTENT_ID, ORIGINAL_CONTENT, REFERENCE_NUMBER, IS_GROUP, IS_SELECTED_BY_USER, IS_SELECTED_BY_RULE, CREATE_DATE, UPDATE_DATE, UPDATE_USER, JDO_CLASS, JDO_LOCK) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) [params=3D(long) 529802, (long) 529800, (long) 529800, (long) 529801, (int) 0, (String) t1.1, (long) 2117, (null) null, (null) null, (int) 0, (null) null, (int) 0, (Date) 2006-10-16, (Date) 2006-10-16, (String) dts.test, (int) 430, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529802, (String) IC, (String) IC1, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) ClauseId, (String) CRS, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529802, (String) GC, (String) CRS, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529800, (String) DocType, (String) RFP, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529802, (String) GC, (String) EDUC, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) GC, (String) CRS, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529802, (String) ClauseId, (String) CRS, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529800, (String) IC, (String) NHLBI, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529802, (String) IC, (String) IC2, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) GC, (String) EDUC, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529800, (String) IC, (String) NCI, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) IC, (String) IC1, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - batching prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) IC, (String) IC2, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent 1656 TRACE [main] openjpa.jdbc.SQL - executing prepstmnt 18895884 INSERT INTO DTS.DOCUMENT_NODE_PROPERTY (DOCUMENT_NODE_ID, NAME, VALUE, JDO_LOCK) VALUES (?, ?, ?, ?) [params=3D(long) 529801, (String) IC, (String) IC2, (int) 1] 1656 TRACE [main] openjpa.jdbc.SQL - [0 ms] spent =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 = =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 =20 -----Original Message----- From: Marc Prud'hommeaux [mailto:mprudhomapache@gmail.com] On Behalf Of Marc Prud'hommeaux Sent: Tuesday, October 17, 2006 4:34 PM To: open-jpa-dev@incubator.apache.org Subject: Re: Why would Kodo refuse to batch inserts in certain tables? Big performance drop migrating to Kodo 4.1 =20 Alex- =20 No attachment came through. =20 Can you just paste the SQL log into a mail? =20 =20 On Oct 16, 2006, at 6:04 PM, Roytman, Alex wrote: =20 > Marc, >=20 > Attached is JDBC trace and my mapping file. >=20 > You can see how everything but DOCUMENT_NODE is batched. >=20 > DOCUMENT_NODE is a super-class table. It has several sub-classes =20 > all but > one mapped on the same table. The one mapped vertically uses DOCUMENT > table. DOCUMENT_NODE have several bi- and uni-directional recursive > associations >=20 > The rest of the classes are related to DOCUMENT_NODE via mapped-by >=20 > Alex >=20 >=20 > -----Original Message----- > From: Marc Prud'hommeaux [mailto:mprudhomapache@gmail.com] On =20 > Behalf Of > Marc Prud'hommeaux > Sent: Monday, October 16, 2006 7:30 PM > To: open-jpa-dev@incubator.apache.org > Subject: Re: Why would Kodo refuse to batch inserts in certain tables? > Big performance drop migrating to Kodo 4.1 >=20 > Alex- >=20 > So you are saying that batching is working OK in general, just not > for a particular class? And that this particular class was batching > fine with previous versions? That is odd, although there are some > cases where we might refuse to batch a particular class (because of a > driver bug with batching certain column types, etc). >=20 > As a shot in the dark, we do work around a bug in the Oracle JDBC > driver's failure to batch date/time effectively. >=20 > Can you post the SQL log that shows the series of SQL statements that > should have been batched, but weren't? That might help shed light =20 > on it. >=20 > Also, database and JDBC driver type/version would be useful. >=20 >=20 >=20 > On Oct 15, 2006, at 7:30 PM, Roytman, Alex wrote: >=20 >> Hello, >>=20 >>=20 >>=20 >> While migrating to Kodo 4.1 I noticed significant drop in insert >> performance. I trace it down to some strange batching behavior. While >> most of the PC were committed with batched inserts one particular >> class >> refused to batch and would insert row by row resulting in 10 times >> performance drop. >>=20 >>=20 >>=20 >> There is nothing special about the class. Its hierarchy is mapped on >> base its table except for one of the lowest members which is mapped >> vertically. >>=20 >>=20 >>=20 >>=20 >>=20 >> Thank you very much >>=20 >>=20 >>=20 >> Alex Roytman >>=20 >> Peace Technology, Inc. >>=20 >> 301-206-9696x103 >>=20 >>=20 >>=20 >=20 =20 ------_=_NextPart_001_01C6F22C.27941508--