Hello,
I have collected a few more data, as suggested by Aristedes.
On 9/23/07, Giulio Cesare Solaroli <giulio.cesar..mail.com> wrote:
> On 9/23/07, Aristedes Maniatis <ar..aniatis.org> 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
This archive was generated by hypermail 2.0.0 : Sun Sep 23 2007 - 11:12:59 EDT