From hmurphy@example.net Mon Oct 01 15:31:24 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 25115 invoked from network); 1 Oct 2007 15:31:24 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 1 Oct 2007 15:31:24 -0000 Received: (qmail 1533 invoked by uid 500); 1 Oct 2007 15:31:13 -0000 Delivered-To: hmurphy@example.net Received: (qmail 1521 invoked by uid 500); 1 Oct 2007 15:31:13 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 1512 invoked by uid 99); 1 Oct 2007 15:31:13 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 08:31:13 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO nf-out-0910.google.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 15:31:14 +0000 Received: by nf-out-0910.google.com with SMTP id 4so9756382nfv for <hmurphy@example.net>; Mon, 01 Oct 2007 08:30:53 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=beta; h=domainkey-signature:received:received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; bh=Gkcm78m5WmKFYOlK8hGnQihyQcT+EANy32OWywYLpBw=; b=IgAiNBtGKx3MmLCmkamb3pnQuROY2pBpBAvFYhyYcKX1HGjPwPzHQCYpa2HT4B918aHfuD9LCiG4S/ylCbOC6SjOGXPCrRT7uXKcvXVMd+2m9KWYFQAZ1TTaXIyxBUxBTRAL2taprj2/egh049FzszdcslnC5elFr1gXjpBkYe4= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=UcBzu4olnAC60Fz1H3ohami6hBXI3QBdgr90uZxpedTesOhojw9UMhth593PvC3IPfs2cseBhUJBMxqULarlQVwaYOkHdV5Bnjvt72F8jpxGVlOcZdDaNNzv/kxzsL0/E7YktHymIN+ez/IkNYXmRe9BD6m72UkZ+bRH7olWHpo= Received: by 83.161.120.155 with SMTP id w15mr3154323hud.1191252652380; Mon, 01 Oct 2007 08:30:52 -0700 (PDT) Received: by 83.161.120.155 with HTTP; Mon, 1 Oct 2007 08:30:51 -0700 (PDT) Message-ID: <hmurphy@example.net> Date: Mon, 1 Oct 2007 17:30:51 +0200 From: "Giulio Cesare Solaroli" <hmurphy@example.net> To: hmurphy@example.net Subject: Re: Optimize cascade deletes In-Reply-To: <hmurphy@example.net> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> X-Virus-Checked: Checked by ClamAV on apache.org Hello everybody, today I have being able to do some more tests and I have found out that the problem seems to be caused by a "fragmentation" of the data on the Postgresql table space. I have created a copy of the table where delete statements where very slow (using the "create table .... as select from ..." syntax) and matching the structure of the new copy to the original one (index and constraint wise); in this new table the performance of the delete statements where from 20 to 100 times faster that in the original table. :-( This rules out Cayenne as the culprit, but leave me wondering how to avoid this degradation of performances on Postgresql; but this is probably not the right place where to start. Thank you everybody for your attention and for the very useful suggestions or pointers that greatly helped me in understanding this problem. Best regards, Giulio Cesare On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > Hello, > > I have collected a few more data, as suggested by Aristedes. > > On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > On 9/23/07, Aristedes Maniatis <hmurphy@example.net> wrote: > > > > > > On 23/09/2007, at 5:38 PM, Giulio Cesare Solaroli wrote: > > > > > > > log4j.logger.org.apache.cayenne=ERROR > > > > log4j.logger.org.apache.cayenne.access.QueryLogger=DEBUG > > > > > > > > > > > > Is there anything going on on the Cayenne code between the last [batch > > > > bind:xxx] log and the "updated" log? > > > > > > Well, you could always try: > > > > > > log4j.logger.org.apache.cayenne=DEBUG > > > > Argh. I should have thought about this myself. :-( > > Even with full log enabled I got the same exact log, so it looks like > all the time is really spent on the DB. And the next logs confirm > this. > > > > > > Is all this time spent on the DB only? > > > > > > What does turning on log_min_duration_statement tell you? > > I have being able to run PostgreSQL with logging enabled only on my > Parallels instance, as I can not start/stop the db on the deployment > server; this will make the absolute times not that relevant, but I > hope we can understand something more anyway. > > First of all, there is a huge difference between the deletion time of > the "cascade" records in different tables. > > [...] > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > LOG: duration: 0.021 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > [...] > > To delete rows on the USRCNNRQS (aka UserConnectionRequest) table, it > averages at bout 0.020 ms. > > > For another table (USRCNN aka UserConnection) the times range from > 0.145 to 0.060, for later settling for 0.040 ms: > > [...] > LOG: duration: 0.090 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > LOG: duration: 0.071 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > LOG: duration: 0.067 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > [...] > > > It later took 43 seconds (!!) to parse and execute the deletion of a > single record, ... > [...] > LOG: statement: PREPARE S_5 AS DELETE FROM clipperz.RCR WHERE ID_RCR = $1 > LOG: statement: <BIND> > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > clipperz.RCR WHERE ID_RCR = $1] > LOG: duration: 42.998 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > LOG: statement: <BIND> > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > clipperz.RCR WHERE ID_RCR = $1] > [...] > > ...later spotting time as low as 0.042 for the execution of the same query: > [...] > LOG: duration: 0.042 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > LOG: statement: <BIND> > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > clipperz.RCR WHERE ID_RCR = $1] > [...] > > But as I may understand this different timing may be due to the > interaction of the Virtual machine with the real server, what is > puzzling me is that the deletion from the latest table had a > "constant" time of about 2 seconds each: > [...] > LOG: duration: 1929.043 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > LOG: duration: 1991.311 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > LOG: duration: 2078.249 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > LOG: duration: 2015.047 ms statement: EXECUTE <unnamed> [PREPARE: > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > [...] > > > If nobody as something else to suggest, I will try to get back the the > DB schema to see if there is some constraint/index that is slowing > down the deletion of these records. > > Thank you very much for your attention. > > Best regards, > > Giulio Cesare > From hmurphy@example.net Mon Oct 01 16:42:22 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 23418 invoked from network); 1 Oct 2007 16:42:22 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 1 Oct 2007 16:42:22 -0000 Received: (qmail 9779 invoked by uid 500); 1 Oct 2007 16:42:12 -0000 Delivered-To: hmurphy@example.net Received: (qmail 9534 invoked by uid 500); 1 Oct 2007 16:42:11 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 9525 invoked by uid 99); 1 Oct 2007 16:42:11 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 09:42:11 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO nz-out-0506.google.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 16:42:13 +0000 Received: by nz-out-0506.google.com with SMTP id f1so8811988nzc for <hmurphy@example.net>; Mon, 01 Oct 2007 09:41:52 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=beta; h=domainkey-signature:received:received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; bh=hxxiCUXznXJUVx1dvxD8l7TLhk99EJfy39sXVcukUjk=; b=a8fnyXEaJijel6JpiyEZahUV7SF3BLr50fix9d4yGH+ktpR8y9DW4LrhXuoq3kNr2s8RdKgDCfQA3yvbABVSQLv9k60Hc6RAPJUT67CrqlruUYT1coKG3Ld3Zsamd5wXnCwOe0m0GSiT9MULklpfPwv3Z36k3Mj1I2VBw7R1RrA= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=iWbkwfh4vuToUyWxrWeHeGoPPx0jsjjBhy5pzq1bR/vzoMMB37M4MaCLFT7OPufF/zh4EHyoL7HaxLMbwamG1NyMRJc7iA4Hju4uG0m/Obeahxwu5/BAZ/VprNAlYIC44PAV2sEUkhynzhbZwg86lED0p0DxsCiwbqfXj5MMnx0= Received: by 83.161.120.155 with SMTP id n6mr4145405waf.1191256907130; Mon, 01 Oct 2007 09:41:47 -0700 (PDT) Received: by 83.161.120.155 with HTTP; Mon, 1 Oct 2007 09:41:46 -0700 (PDT) Message-ID: <hmurphy@example.net> Date: Mon, 1 Oct 2007 12:41:46 -0400 From: "Michael Gentry" <hmurphy@example.net> To: hmurphy@example.net Subject: Re: Optimize cascade deletes In-Reply-To: <hmurphy@example.net> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> X-Virus-Checked: Checked by ClamAV on apache.org Have you vacuumed the original (slow) table? /dev/mrg On 10/1/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > Hello everybody, > > today I have being able to do some more tests and I have found out > that the problem seems to be caused by a "fragmentation" of the data > on the Postgresql table space. > > I have created a copy of the table where delete statements where very > slow (using the "create table .... as select from ..." syntax) and > matching the structure of the new copy to the original one (index and > constraint wise); in this new table the performance of the delete > statements where from 20 to 100 times faster that in the original > table. :-( > > This rules out Cayenne as the culprit, but leave me wondering how to > avoid this degradation of performances on Postgresql; but this is > probably not the right place where to start. > > Thank you everybody for your attention and for the very useful > suggestions or pointers that greatly helped me in understanding this > problem. > > Best regards, > > Giulio Cesare > > > > > > > > On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > Hello, > > > > I have collected a few more data, as suggested by Aristedes. > > > > On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > > On 9/23/07, Aristedes Maniatis <hmurphy@example.net> wrote: > > > > > > > > On 23/09/2007, at 5:38 PM, Giulio Cesare Solaroli wrote: > > > > > > > > > log4j.logger.org.apache.cayenne=ERROR > > > > > log4j.logger.org.apache.cayenne.access.QueryLogger=DEBUG > > > > > > > > > > > > > > > Is there anything going on on the Cayenne code between the last [batch > > > > > bind:xxx] log and the "updated" log? > > > > > > > > Well, you could always try: > > > > > > > > log4j.logger.org.apache.cayenne=DEBUG > > > > > > Argh. I should have thought about this myself. :-( > > > > Even with full log enabled I got the same exact log, so it looks like > > all the time is really spent on the DB. And the next logs confirm > > this. > > > > > > > > > Is all this time spent on the DB only? > > > > > > > > What does turning on log_min_duration_statement tell you? > > > > I have being able to run PostgreSQL with logging enabled only on my > > Parallels instance, as I can not start/stop the db on the deployment > > server; this will make the absolute times not that relevant, but I > > hope we can understand something more anyway. > > > > First of all, there is a huge difference between the deletion time of > > the "cascade" records in different tables. > > > > [...] > > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > LOG: duration: 0.021 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > [...] > > > > To delete rows on the USRCNNRQS (aka UserConnectionRequest) table, it > > averages at bout 0.020 ms. > > > > > > For another table (USRCNN aka UserConnection) the times range from > > 0.145 to 0.060, for later settling for 0.040 ms: > > > > [...] > > LOG: duration: 0.090 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > LOG: duration: 0.071 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > LOG: duration: 0.067 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > [...] > > > > > > It later took 43 seconds (!!) to parse and execute the deletion of a > > single record, ... > > [...] > > LOG: statement: PREPARE S_5 AS DELETE FROM clipperz.RCR WHERE ID_RCR = $1 > > LOG: statement: <BIND> > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > clipperz.RCR WHERE ID_RCR = $1] > > LOG: duration: 42.998 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > > LOG: statement: <BIND> > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > clipperz.RCR WHERE ID_RCR = $1] > > [...] > > > > ...later spotting time as low as 0.042 for the execution of the same query: > > [...] > > LOG: duration: 0.042 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > > LOG: statement: <BIND> > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > clipperz.RCR WHERE ID_RCR = $1] > > [...] > > > > But as I may understand this different timing may be due to the > > interaction of the Virtual machine with the real server, what is > > puzzling me is that the deletion from the latest table had a > > "constant" time of about 2 seconds each: > > [...] > > LOG: duration: 1929.043 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > LOG: duration: 1991.311 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > LOG: duration: 2078.249 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > LOG: duration: 2015.047 ms statement: EXECUTE <unnamed> [PREPARE: > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > [...] > > > > > > If nobody as something else to suggest, I will try to get back the the > > DB schema to see if there is some constraint/index that is slowing > > down the deletion of these records. > > > > Thank you very much for your attention. > > > > Best regards, > > > > Giulio Cesare > > > From hmurphy@example.net Mon Oct 01 17:05:44 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 64687 invoked from network); 1 Oct 2007 17:05:41 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 1 Oct 2007 17:05:41 -0000 Received: (qmail 54835 invoked by uid 500); 1 Oct 2007 17:05:30 -0000 Delivered-To: hmurphy@example.net Received: (qmail 54588 invoked by uid 500); 1 Oct 2007 17:05:30 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 54579 invoked by uid 99); 1 Oct 2007 17:05:30 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 10:05:30 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO wx-out-0506.google.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 17:05:32 +0000 Received: by wx-out-0506.google.com with SMTP id r21so2982957wxc for <hmurphy@example.net>; Mon, 01 Oct 2007 10:05:11 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=beta; h=domainkey-signature:received:received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; bh=5ivvcFMHYC2mDmbVMxMuqHzmPl5kBXhK2/fxdAogjB4=; b=NJU61ngrRObyLTxxF5uN0rLeWFUPj6H8xA1qycJT5HPtHg1USnFuDep0OyASISzsLTNyJSWVEvhR6yWILy7UD4XQ+u0vHgfjbtGVLHJLMJCJg+AxOMW4m1I5awB1/j3gSPqERDRTeCdaGqC3wKX8Hwgc9d1thylCFXZoLssSdp0= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=QiLYaeTlWf6AgcTBxrndNJl32tuVWJCdioBReytiI4J/cqzLzbxOn37l+fMtHgTtIE4ywaAaOYzDIW6/BgbqvuZ+fwbS+wn8V3OnPZwHiwo18JbTSvM0b1qFwX3kS4N60wjTYlJch0Q5im6V2zysPiZi0KdnW9Ui0gQs4y80MdM= Received: by 83.161.120.155 with SMTP id b9mr10167344wxb.1191258308492; Mon, 01 Oct 2007 10:05:08 -0700 (PDT) Received: by 83.161.120.155 with HTTP; Mon, 1 Oct 2007 10:05:08 -0700 (PDT) Message-ID: <hmurphy@example.net> Date: Mon, 1 Oct 2007 19:05:08 +0200 From: "Giulio Cesare Solaroli" <hmurphy@example.net> To: hmurphy@example.net Subject: Re: Optimize cascade deletes In-Reply-To: <hmurphy@example.net> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> X-Virus-Checked: Checked by ClamAV on apache.org Yes, I have vacuumed it and also rebuild the indexes to no avail. :-( I am not a PostgreSQL expert (and not even an expert DBA in general), so it is very possible that I am doing something very wrong. This is both a good news (the application should be fine, and I don't need to tune it much further) and bad news (I need to learn how to tune a PostgreSQL db, or find someone that could help). Best regards, Giulio Cesare On 10/1/07, Michael Gentry <hmurphy@example.net> wrote: > Have you vacuumed the original (slow) table? > > /dev/mrg > > On 10/1/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > Hello everybody, > > > > today I have being able to do some more tests and I have found out > > that the problem seems to be caused by a "fragmentation" of the data > > on the Postgresql table space. > > > > I have created a copy of the table where delete statements where very > > slow (using the "create table .... as select from ..." syntax) and > > matching the structure of the new copy to the original one (index and > > constraint wise); in this new table the performance of the delete > > statements where from 20 to 100 times faster that in the original > > table. :-( > > > > This rules out Cayenne as the culprit, but leave me wondering how to > > avoid this degradation of performances on Postgresql; but this is > > probably not the right place where to start. > > > > Thank you everybody for your attention and for the very useful > > suggestions or pointers that greatly helped me in understanding this > > problem. > > > > Best regards, > > > > Giulio Cesare > > > > > > > > > > > > > > > > On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > > Hello, > > > > > > I have collected a few more data, as suggested by Aristedes. > > > > > > On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > > > > On 9/23/07, Aristedes Maniatis <hmurphy@example.net> wrote: > > > > > > > > > > On 23/09/2007, at 5:38 PM, Giulio Cesare Solaroli wrote: > > > > > > > > > > > log4j.logger.org.apache.cayenne=ERROR > > > > > > log4j.logger.org.apache.cayenne.access.QueryLogger=DEBUG > > > > > > > > > > > > > > > > > > Is there anything going on on the Cayenne code between the last [batch > > > > > > bind:xxx] log and the "updated" log? > > > > > > > > > > Well, you could always try: > > > > > > > > > > log4j.logger.org.apache.cayenne=DEBUG > > > > > > > > Argh. I should have thought about this myself. :-( > > > > > > Even with full log enabled I got the same exact log, so it looks like > > > all the time is really spent on the DB. And the next logs confirm > > > this. > > > > > > > > > > > > Is all this time spent on the DB only? > > > > > > > > > > What does turning on log_min_duration_statement tell you? > > > > > > I have being able to run PostgreSQL with logging enabled only on my > > > Parallels instance, as I can not start/stop the db on the deployment > > > server; this will make the absolute times not that relevant, but I > > > hope we can understand something more anyway. > > > > > > First of all, there is a huge difference between the deletion time of > > > the "cascade" records in different tables. > > > > > > [...] > > > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > > LOG: duration: 0.021 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > > LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > > > [...] > > > > > > To delete rows on the USRCNNRQS (aka UserConnectionRequest) table, it > > > averages at bout 0.020 ms. > > > > > > > > > For another table (USRCNN aka UserConnection) the times range from > > > 0.145 to 0.060, for later settling for 0.040 ms: > > > > > > [...] > > > LOG: duration: 0.090 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > > LOG: duration: 0.071 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > > LOG: duration: 0.067 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > > > [...] > > > > > > > > > It later took 43 seconds (!!) to parse and execute the deletion of a > > > single record, ... > > > [...] > > > LOG: statement: PREPARE S_5 AS DELETE FROM clipperz.RCR WHERE ID_RCR = $1 > > > LOG: statement: <BIND> > > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > > clipperz.RCR WHERE ID_RCR = $1] > > > LOG: duration: 42.998 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > > > LOG: statement: <BIND> > > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > > clipperz.RCR WHERE ID_RCR = $1] > > > [...] > > > > > > ...later spotting time as low as 0.042 for the execution of the same query: > > > [...] > > > LOG: duration: 0.042 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > > > LOG: statement: <BIND> > > > LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > > > clipperz.RCR WHERE ID_RCR = $1] > > > [...] > > > > > > But as I may understand this different timing may be due to the > > > interaction of the Virtual machine with the real server, what is > > > puzzling me is that the deletion from the latest table had a > > > "constant" time of about 2 seconds each: > > > [...] > > > LOG: duration: 1929.043 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > > LOG: duration: 1991.311 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > > LOG: duration: 2078.249 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > > LOG: duration: 2015.047 ms statement: EXECUTE <unnamed> [PREPARE: > > > DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > > > [...] > > > > > > > > > If nobody as something else to suggest, I will try to get back the the > > > DB schema to see if there is some constraint/index that is slowing > > > down the deletion of these records. > > > > > > Thank you very much for your attention. > > > > > > Best regards, > > > > > > Giulio Cesare > > > > > > From hmurphy@example.net Tue Oct 02 05:42:27 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 14265 invoked from network); 2 Oct 2007 05:42:27 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 2 Oct 2007 05:42:27 -0000 Received: (qmail 63920 invoked by uid 500); 2 Oct 2007 05:42:16 -0000 Delivered-To: hmurphy@example.net Received: (qmail 63903 invoked by uid 500); 2 Oct 2007 05:42:16 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 63894 invoked by uid 99); 2 Oct 2007 05:42:16 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 01 Oct 2007 22:42:16 -0700 X-ASF-Spam-Status: No, hits=1.2 required=10.0 tests=SPF_NEUTRAL X-Spam-Check-By: apache.org Received-SPF: neutral (athena.apache.org: local policy) Received: from [83.161.120.155] (HELO eccproxy.ecc.as) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 05:42:17 +0000 Received: from eccmx.ecc.as ([83.161.120.155]) by eccproxy.ecc.as with InterScan Messaging Security Suite; Tue, 02 Oct 2007 07:41:30 +0200 Received: from [83.161.120.155] ([83.161.120.155]) by eccmx.ecc.as with Microsoft SMTPSVC(510)560-3543); Tue, 2 Oct 2007 07:41:29 +0200 Mime-Version: 1.0 (Apple Message framework v752.3) In-Reply-To: <hmurphy@example.net> References: <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> Content-Type: text/plain; charset=US-ASCII; delsp=yes; format=flowed Message-Id: <hmurphy@example.net> Content-Transfer-Encoding: 7bit From: Tore Halset <hmurphy@example.net> Subject: Re: Optimize cascade deletes Date: Tue, 2 Oct 2007 07:41:23 +0200 To: hmurphy@example.net X-Mailer: Apple Mail (2.752.3) X-OriginalArrivalTime: 02 Oct 2007 05:41:29.0703 (UTC) FILETIME=[E1B00F70:01C804B6] X-imss-version: 2.048 X-imss-result: Passed X-imss-scores: Clean:99.90000 C:2 M:3 S:5 R:5 X-imss-settings: Baseline:2 C:2 M:2 S:2 R:2 (0.1500 0.1500) X-Virus-Checked: Checked by ClamAV on apache.org Hello. This does not sound like a cayenne issue any more. Here is what I would do to get going. * Remove the extra OS layer if you are still using it. Was it Parallells? * Update to latest PostgreSQL and JDBC driver. * Use vacuum analyze and autovacuum * Find slow queries and use "explain <query>" * Make sure PostgreSQL are set up with enough memory. * Ask on hmurphy@example.net Regards, - Tore. On Oct 1, 2007, at 19:05 , Giulio Cesare Solaroli wrote: > Yes, > > I have vacuumed it and also rebuild the indexes to no avail. :-( > > I am not a PostgreSQL expert (and not even an expert DBA in general), > so it is very possible that I am doing something very wrong. > > This is both a good news (the application should be fine, and I don't > need to tune it much further) and bad news (I need to learn how to > tune a PostgreSQL db, or find someone that could help). > > Best regards, > > Giulio Cesare > > > > > On 10/1/07, Michael Gentry <hmurphy@example.net> wrote: >> Have you vacuumed the original (slow) table? >> >> /dev/mrg >> >> On 10/1/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: >>> Hello everybody, >>> >>> today I have being able to do some more tests and I have found out >>> that the problem seems to be caused by a "fragmentation" of the data >>> on the Postgresql table space. >>> >>> I have created a copy of the table where delete statements where >>> very >>> slow (using the "create table .... as select from ..." syntax) and >>> matching the structure of the new copy to the original one (index >>> and >>> constraint wise); in this new table the performance of the delete >>> statements where from 20 to 100 times faster that in the original >>> table. :-( >>> >>> This rules out Cayenne as the culprit, but leave me wondering how to >>> avoid this degradation of performances on Postgresql; but this is >>> probably not the right place where to start. >>> >>> Thank you everybody for your attention and for the very useful >>> suggestions or pointers that greatly helped me in understanding this >>> problem. >>> >>> Best regards, >>> >>> Giulio Cesare >>> >>> >>> >>> >>> >>> >>> >>> On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: >>>> Hello, >>>> >>>> I have collected a few more data, as suggested by Aristedes. >>>> >>>> On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: >>>>> On 9/23/07, Aristedes Maniatis <hmurphy@example.net> wrote: >>>>>> >>>>>> On 23/09/2007, at 5:38 PM, Giulio Cesare Solaroli wrote: >>>>>> >>>>>>> log4j.logger.org.apache.cayenne=ERROR >>>>>>> log4j.logger.org.apache.cayenne.access.QueryLogger=DEBUG >>>>>>> >>>>>>> >>>>>>> Is there anything going on on the Cayenne code between the >>>>>>> last [batch >>>>>>> bind:xxx] log and the "updated" log? >>>>>> >>>>>> Well, you could always try: >>>>>> >>>>>> log4j.logger.org.apache.cayenne=DEBUG >>>>> >>>>> Argh. I should have thought about this myself. :-( >>>> >>>> Even with full log enabled I got the same exact log, so it looks >>>> like >>>> all the time is really spent on the DB. And the next logs confirm >>>> this. >>>> >>>> >>>>>>> Is all this time spent on the DB only? >>>>>> >>>>>> What does turning on log_min_duration_statement tell you? >>>> >>>> I have being able to run PostgreSQL with logging enabled only on my >>>> Parallels instance, as I can not start/stop the db on the >>>> deployment >>>> server; this will make the absolute times not that relevant, but I >>>> hope we can understand something more anyway. >>>> >>>> First of all, there is a huge difference between the deletion >>>> time of >>>> the "cascade" records in different tables. >>>> >>>> [...] >>>> LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] >>>> LOG: duration: 0.021 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] >>>> LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] >>>> [...] >>>> >>>> To delete rows on the USRCNNRQS (aka UserConnectionRequest) >>>> table, it >>>> averages at bout 0.020 ms. >>>> >>>> >>>> For another table (USRCNN aka UserConnection) the times range from >>>> 0.145 to 0.060, for later settling for 0.040 ms: >>>> >>>> [...] >>>> LOG: duration: 0.090 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] >>>> LOG: duration: 0.071 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] >>>> LOG: duration: 0.067 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] >>>> [...] >>>> >>>> >>>> It later took 43 seconds (!!) to parse and execute the deletion >>>> of a >>>> single record, ... >>>> [...] >>>> LOG: statement: PREPARE S_5 AS DELETE FROM clipperz.RCR WHERE >>>> ID_RCR = $1 >>>> LOG: statement: <BIND> >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM >>>> clipperz.RCR WHERE ID_RCR = $1] >>>> LOG: duration: 42.998 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM clipperz.RCR WHERE ID_RCR = $1] >>>> LOG: statement: <BIND> >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM >>>> clipperz.RCR WHERE ID_RCR = $1] >>>> [...] >>>> >>>> ...later spotting time as low as 0.042 for the execution of the >>>> same query: >>>> [...] >>>> LOG: duration: 0.042 ms statement: EXECUTE <unnamed> [PREPARE: >>>> DELETE FROM clipperz.RCR WHERE ID_RCR = $1] >>>> LOG: statement: <BIND> >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM >>>> clipperz.RCR WHERE ID_RCR = $1] >>>> [...] >>>> >>>> But as I may understand this different timing may be due to the >>>> interaction of the Virtual machine with the real server, what is >>>> puzzling me is that the deletion from the latest table had a >>>> "constant" time of about 2 seconds each: >>>> [...] >>>> LOG: duration: 1929.043 ms statement: EXECUTE <unnamed> >>>> [PREPARE: >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] >>>> LOG: duration: 1991.311 ms statement: EXECUTE <unnamed> >>>> [PREPARE: >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] >>>> LOG: duration: 2078.249 ms statement: EXECUTE <unnamed> >>>> [PREPARE: >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] >>>> LOG: duration: 2015.047 ms statement: EXECUTE <unnamed> >>>> [PREPARE: >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] >>>> [...] >>>> >>>> >>>> If nobody as something else to suggest, I will try to get back >>>> the the >>>> DB schema to see if there is some constraint/index that is slowing >>>> down the deletion of these records. >>>> >>>> Thank you very much for your attention. >>>> >>>> Best regards, >>>> >>>> Giulio Cesare >>>> >>> >> > From hmurphy@example.net Tue Oct 02 07:03:25 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 36630 invoked from network); 2 Oct 2007 07:03:25 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 2 Oct 2007 07:03:25 -0000 Received: (qmail 10063 invoked by uid 500); 2 Oct 2007 07:03:14 -0000 Delivered-To: hmurphy@example.net Received: (qmail 10044 invoked by uid 500); 2 Oct 2007 07:03:14 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 10035 invoked by uid 99); 2 Oct 2007 07:03:14 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 00:03:14 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO wx-out-0506.google.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 07:03:16 +0000 Received: by wx-out-0506.google.com with SMTP id r21so3162356wxc for <hmurphy@example.net>; Tue, 02 Oct 2007 00:02:55 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=beta; h=domainkey-signature:received:received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; bh=I3ATzzAbBVtmF5u9bUOitCK48nbR7shQTCpqFCwuZrQ=; b=joweE2yzipBh3RoHPQchKtMLELBlhsKhxhlx6PxMe60LeaLQF7hEXt9/4fu01lmhAfFf03zVMHleQG3A3hfdXjhUSV2NuNAQ1hFLgtXTPuUKoOhnTFpfBkjHsgG0NM07zutn0eWwD3UyzC6PNVGpAqlltqlWuutSxtvsuHwKAQ4= DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:in-reply-to:mime-version:content-type:content-transfer-encoding:content-disposition:references; b=Xoz2u0pOqA7VB7NDhB6TrIWc8OTVvw4epCTLQQlQaVDQ0pETsapvz2+Po8HTETKuoyB2cbYfn+vZq3tThbqEIhKlUbNKXjjg87l29OcQWTdwiMmJpShZEf+LbVoWPleMr0BebCKGelVexxJD5BxA023dPlAx0ZMGaM5hnN0oypU= Received: by 83.161.120.155 with SMTP id l5mr11472697wxc.1191308575251; Tue, 02 Oct 2007 00:02:55 -0700 (PDT) Received: by 83.161.120.155 with HTTP; Tue, 2 Oct 2007 00:02:55 -0700 (PDT) Message-ID: <hmurphy@example.net> Date: Tue, 2 Oct 2007 09:02:55 +0200 From: "Giulio Cesare Solaroli" <hmurphy@example.net> To: hmurphy@example.net Subject: Re: Optimize cascade deletes In-Reply-To: <hmurphy@example.net> MIME-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Content-Disposition: inline References: <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> <hmurphy@example.net> X-Virus-Checked: Checked by ClamAV on apache.org Hello Tore, On 10/2/07, Tore Halset <hmurphy@example.net> wrote: > Hello. > > This does not sound like a cayenne issue any more. Definitely. > Here is what I would do to get going. > > * Remove the extra OS layer if you are still using it. Was it > Parallells? Parallels could alter the absolute values of the operation timing; but I have see an consistent difference between 20 and 100 times faster on the newly created table; this make me think that it is not a problem bound to the usage of a virtual machine. > * Update to latest PostgreSQL and JDBC driver. I may try to update to the latest PostgreSQL version, but it is not a JDBC issue as I got the same problem issuing the query right from psql. > * Use vacuum analyze and autovacuum I have already tried this. > * Find slow queries and use "explain <query>" The slow query is a simple delete on a table accessed using the primary key. The explain plan reports an index scan, as expected. > * Make sure PostgreSQL are set up with enough memory. The current instance i probably running with a very low memory footprint, but if a copy of the same table on the same PostgreSQL instance is running the same query 20 to 100 times faster, there is something else to fix before tuning the memory. > * Ask on hmurphy@example.net Great pointer. Thanks!!!! :-) Best regards, Giulio Cesare > On Oct 1, 2007, at 19:05 , Giulio Cesare Solaroli wrote: > > > Yes, > > > > I have vacuumed it and also rebuild the indexes to no avail. :-( > > > > I am not a PostgreSQL expert (and not even an expert DBA in general), > > so it is very possible that I am doing something very wrong. > > > > This is both a good news (the application should be fine, and I don't > > need to tune it much further) and bad news (I need to learn how to > > tune a PostgreSQL db, or find someone that could help). > > > > Best regards, > > > > Giulio Cesare > > > > > > > > > > On 10/1/07, Michael Gentry <hmurphy@example.net> wrote: > >> Have you vacuumed the original (slow) table? > >> > >> /dev/mrg > >> > >> On 10/1/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > >>> Hello everybody, > >>> > >>> today I have being able to do some more tests and I have found out > >>> that the problem seems to be caused by a "fragmentation" of the data > >>> on the Postgresql table space. > >>> > >>> I have created a copy of the table where delete statements where > >>> very > >>> slow (using the "create table .... as select from ..." syntax) and > >>> matching the structure of the new copy to the original one (index > >>> and > >>> constraint wise); in this new table the performance of the delete > >>> statements where from 20 to 100 times faster that in the original > >>> table. :-( > >>> > >>> This rules out Cayenne as the culprit, but leave me wondering how to > >>> avoid this degradation of performances on Postgresql; but this is > >>> probably not the right place where to start. > >>> > >>> Thank you everybody for your attention and for the very useful > >>> suggestions or pointers that greatly helped me in understanding this > >>> problem. > >>> > >>> Best regards, > >>> > >>> Giulio Cesare > >>> > >>> > >>> > >>> > >>> > >>> > >>> > >>> On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > >>>> Hello, > >>>> > >>>> I have collected a few more data, as suggested by Aristedes. > >>>> > >>>> On 9/23/07, Giulio Cesare Solaroli <hmurphy@example.net> wrote: > >>>>> On 9/23/07, Aristedes Maniatis <hmurphy@example.net> wrote: > >>>>>> > >>>>>> On 23/09/2007, at 5:38 PM, Giulio Cesare Solaroli wrote: > >>>>>> > >>>>>>> log4j.logger.org.apache.cayenne=ERROR > >>>>>>> log4j.logger.org.apache.cayenne.access.QueryLogger=DEBUG > >>>>>>> > >>>>>>> > >>>>>>> Is there anything going on on the Cayenne code between the > >>>>>>> last [batch > >>>>>>> bind:xxx] log and the "updated" log? > >>>>>> > >>>>>> Well, you could always try: > >>>>>> > >>>>>> log4j.logger.org.apache.cayenne=DEBUG > >>>>> > >>>>> Argh. I should have thought about this myself. :-( > >>>> > >>>> Even with full log enabled I got the same exact log, so it looks > >>>> like > >>>> all the time is really spent on the DB. And the next logs confirm > >>>> this. > >>>> > >>>> > >>>>>>> Is all this time spent on the DB only? > >>>>>> > >>>>>> What does turning on log_min_duration_statement tell you? > >>>> > >>>> I have being able to run PostgreSQL with logging enabled only on my > >>>> Parallels instance, as I can not start/stop the db on the > >>>> deployment > >>>> server; this will make the absolute times not that relevant, but I > >>>> hope we can understand something more anyway. > >>>> > >>>> First of all, there is a huge difference between the deletion > >>>> time of > >>>> the "cascade" records in different tables. > >>>> > >>>> [...] > >>>> LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > >>>> LOG: duration: 0.021 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > >>>> LOG: duration: 0.020 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNNRQS WHERE ID_USRCNNRQS = $1] > >>>> [...] > >>>> > >>>> To delete rows on the USRCNNRQS (aka UserConnectionRequest) > >>>> table, it > >>>> averages at bout 0.020 ms. > >>>> > >>>> > >>>> For another table (USRCNN aka UserConnection) the times range from > >>>> 0.145 to 0.060, for later settling for 0.040 ms: > >>>> > >>>> [...] > >>>> LOG: duration: 0.090 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > >>>> LOG: duration: 0.071 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > >>>> LOG: duration: 0.067 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1] > >>>> [...] > >>>> > >>>> > >>>> It later took 43 seconds (!!) to parse and execute the deletion > >>>> of a > >>>> single record, ... > >>>> [...] > >>>> LOG: statement: PREPARE S_5 AS DELETE FROM clipperz.RCR WHERE > >>>> ID_RCR = $1 > >>>> LOG: statement: <BIND> > >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > >>>> clipperz.RCR WHERE ID_RCR = $1] > >>>> LOG: duration: 42.998 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > >>>> LOG: statement: <BIND> > >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > >>>> clipperz.RCR WHERE ID_RCR = $1] > >>>> [...] > >>>> > >>>> ...later spotting time as low as 0.042 for the execution of the > >>>> same query: > >>>> [...] > >>>> LOG: duration: 0.042 ms statement: EXECUTE <unnamed> [PREPARE: > >>>> DELETE FROM clipperz.RCR WHERE ID_RCR = $1] > >>>> LOG: statement: <BIND> > >>>> LOG: statement: EXECUTE <unnamed> [PREPARE: DELETE FROM > >>>> clipperz.RCR WHERE ID_RCR = $1] > >>>> [...] > >>>> > >>>> But as I may understand this different timing may be due to the > >>>> interaction of the Virtual machine with the real server, what is > >>>> puzzling me is that the deletion from the latest table had a > >>>> "constant" time of about 2 seconds each: > >>>> [...] > >>>> LOG: duration: 1929.043 ms statement: EXECUTE <unnamed> > >>>> [PREPARE: > >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > >>>> LOG: duration: 1991.311 ms statement: EXECUTE <unnamed> > >>>> [PREPARE: > >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > >>>> LOG: duration: 2078.249 ms statement: EXECUTE <unnamed> > >>>> [PREPARE: > >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > >>>> LOG: duration: 2015.047 ms statement: EXECUTE <unnamed> > >>>> [PREPARE: > >>>> DELETE FROM clipperz.RCRVRS WHERE ID_RCRVRS = $1] > >>>> [...] > >>>> > >>>> > >>>> If nobody as something else to suggest, I will try to get back > >>>> the the > >>>> DB schema to see if there is some constraint/index that is slowing > >>>> down the deletion of these records. > >>>> > >>>> Thank you very much for your attention. > >>>> > >>>> Best regards, > >>>> > >>>> Giulio Cesare > >>>> > >>> > >> > > > > From hmurphy@example.net Tue Oct 02 21:33:14 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 29641 invoked from network); 2 Oct 2007 21:33:14 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 2 Oct 2007 21:33:14 -0000 Received: (qmail 78788 invoked by uid 500); 2 Oct 2007 21:33:03 -0000 Delivered-To: hmurphy@example.net Received: (qmail 78771 invoked by uid 500); 2 Oct 2007 21:33:03 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 78762 invoked by uid 99); 2 Oct 2007 21:33:03 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 14:33:03 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO kuber.nabble.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 21:33:03 +0000 Received: from isper.nabble.com ([83.161.120.155]) by kuber.nabble.com with esmtp (Exim 4.63) (envelope-from <hmurphy@example.net>) id 1IcpMB-0004vF-92 for hmurphy@example.net; Tue, 02 Oct 2007 14:32:43 -0700 Message-ID: <hmurphy@example.net> Date: Tue, 2 Oct 2007 14:32:43 -0700 (PDT) From: pinkybum_nabble <hmurphy@example.net> To: hmurphy@example.net Subject: To dep PK MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Nabble-From: hmurphy@example.net X-Virus-Checked: Checked by ClamAV on apache.org I have only been looking into this tool for a couple of days now and I am finding it great to work with and easy to use. However, I have been having an issue which may be my ignorance of database relationships. I have defined dbEntities and relationships much like: MasterEntity DependentEntity The relationship is One-to-many (one Master to Many Dependents) I have created the analogous object entities. When I manipulate these objects in java using code like: Master mas = null; Dependent dep1 = null; Dependent dep2 = null; mas = (Master)context.newObject( Master.class ); mas.setNumber( Integer.valueOf( 100 )); dep1 = (Dependents)context.newObject( Dependents.class ); dep1.setName( "DependentNumber A"); mas.addToDependents( dep1 ); dep2 = (Dependents)context.newObject( Dependents.class ); dep2.setName( "DependentNumber B"); mas.addToDependents( dep2 ); context.commitChanges(); I get an exception which indicates that the database tried to create a Dependent entry with a duplicate primary key. The only configuration which alleviates this problem and creates unique Dependent keys is checking the "To dep PK" checkbox on the dependent side of the relationship. Reading the documentation it seems to suggest that the checkbox should be checked on the master side of the relationship. Did I just read wrongly, can't I just leave the checkbox blank or is there some other configuration I am missing when I create my schemas? I would like to get this issue resolved before adding full database support to the project via Cayenne and deploying the production database. Many Thankls Neil Pinkerton -- View this message in context: http://www.nabble.com/To-dep-PK-tf4558289.html#a13008451 Sent from the Cayenne - User mailing list hmurphy@example.net. From hmurphy@example.net Tue Oct 02 22:50:14 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 61182 invoked from network); 2 Oct 2007 22:50:14 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 2 Oct 2007 22:50:14 -0000 Received: (qmail 2837 invoked by uid 500); 2 Oct 2007 22:50:02 -0000 Delivered-To: hmurphy@example.net Received: (qmail 2828 invoked by uid 500); 2 Oct 2007 22:50:02 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 2819 invoked by uid 99); 2 Oct 2007 22:50:02 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 15:50:02 -0700 X-ASF-Spam-Status: No, hits=1.2 required=10.0 tests=SPF_NEUTRAL X-Spam-Check-By: apache.org Received-SPF: neutral (athena.apache.org: local policy) Received: from [83.161.120.155] (HELO fish.ish.com.au) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 22:50:04 +0000 Received: from [83.161.120.155] (helo=[83.161.120.155]) by fish.ish.com.au with esmtpa (Exim 4.43) id 1IcqWh-00050l-VW for hmurphy@example.net; Wed, 03 Oct 2007 08:47:42 +1000 Mime-Version: 1.0 (Apple Message framework v752.2) In-Reply-To: <hmurphy@example.net> References: <hmurphy@example.net> Content-Type: multipart/signed; protocol="application/pgp-signature"; micalg=pgp-sha1; boundary="Apple-Mail-34-457295881" Message-Id: <hmurphy@example.net> Content-Transfer-Encoding: 7bit From: Aristedes Maniatis <hmurphy@example.net> Subject: Re: To dep PK Date: Wed, 3 Oct 2007 08:49:36 +1000 To: hmurphy@example.net X-Pgp-Agent: GPGMail 1.1.2 (Tiger) X-Mailer: Apple Mail (2.752.2) X-Spam-Score: -1.4 (-) X-Spam-Report: -1.4 ALL_TRUSTED Passed through trusted hosts only via SMTP X-Virus-Checked: Checked by ClamAV on apache.org --Apple-Mail-34-457295881 Content-Transfer-Encoding: 7bit Content-Type: text/plain; charset=US-ASCII; delsp=yes; format=flowed On 03/10/2007, at 7:32 AM, pinkybum_nabble wrote: > I get an exception which indicates that the database tried to create a > Dependent entry with a duplicate primary key. The only > configuration which > alleviates this problem and creates unique Dependent keys is > checking the > "To dep PK" checkbox on the dependent side of the relationship. This should not be ticked in ordinary use. It is for special cases such as a one-to-one relationship model. http://cayenne.apache.org/doc/to-dep-pk-checkbox.html I'd be looking at your primary key generation strategy. Are you using the default? What key is being created in the database once you add and commit one record? Ari Maniatis --------------------------> Aristedes Maniatis phone (510)560-3543 PGP fingerprint 08 57 20 4B 80 69 59 E2 A9 BF 2D 48 C2 20 0C C8 --Apple-Mail-34-457295881 content-type: application/pgp-signature; x-mac-type=70674453; name=PGP.sig content-description: This is a digitally signed message part content-disposition: inline; filename=PGP.sig content-transfer-encoding: 7bit -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.3 (Darwin) iEYEARECAAYFAkcCywEACgkQ72p9Lj5JECpnaQCfdXs8KgZOyumf6PTcfxnMDgjS JGsAnjPETbdF2VLiyXQIFuRQn/r2XidG =FPOp -----END PGP SIGNATURE----- --Apple-Mail-34-457295881-- From hmurphy@example.net Tue Oct 02 23:25:53 2007 Return-Path: <hmurphy@example.net> Delivered-To: hmurphy@example.net Received: (qmail 76733 invoked from network); 2 Oct 2007 23:25:53 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (83.161.120.155) by minotaur.apache.org with SMTP; 2 Oct 2007 23:25:53 -0000 Received: (qmail 34514 invoked by uid 500); 2 Oct 2007 23:25:41 -0000 Delivered-To: hmurphy@example.net Received: (qmail 34481 invoked by uid 500); 2 Oct 2007 23:25:41 -0000 Mailing-List: contact hmurphy@example.net; run by ezmlm Precedence: bulk List-Help: <mailto:hmurphy@example.net> List-Unsubscribe: <mailto:hmurphy@example.net> List-Post: <mailto:hmurphy@example.net> List-Id: <user.cayenne.apache.org> Reply-To: hmurphy@example.net Delivered-To: mailing list hmurphy@example.net Received: (qmail 34464 invoked by uid 99); 2 Oct 2007 23:25:41 -0000 Received: from athena.apache.org (HELO athena.apache.org) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 16:25:41 -0700 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of hmurphy@example.net designates 83.161.120.155 as permitted sender) Received: from [83.161.120.155] (HELO kuber.nabble.com) (83.161.120.155) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 02 Oct 2007 23:25:42 +0000 Received: from isper.nabble.com ([83.161.120.155]) by kuber.nabble.com with esmtp (Exim 4.63) (envelope-from <hmurphy@example.net>) id 1Icr7B-00085N-89 for hmurphy@example.net; Tue, 02 Oct 2007 16:25:21 -0700 Message-ID: <hmurphy@example.net> Date: Tue, 2 Oct 2007 16:25:21 -0700 (PDT) From: pinkybum_nabble <hmurphy@example.net> To: hmurphy@example.net Subject: Re: To dep
{'source': 'Apache Software Foundation Public Mail Archives'}