DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta;
	h=received:message-id:date:from:to:subject:mime-version:content-type:content-transfer-encoding:content-disposition;
	b=BjAdWhiADHLmLBDTbirvtAUpEpeOsUoTpKeynDtk4GwDwuW+KwcB82Wsu4Qck/zDyVuZe8oKa91u544MVPWzEbWc0XYKP1BnmJl5GvXvFDKJKYg5+B4a2FMAXE4TsK8VjmwWstEbCHTsGVvOxdretomBYhK/RBap/NSlaclWSxU=
Message-ID: <ff737ac30710240344v4391d2eeq957e91dca6c2f9e0@mail.gmail.com>
Date: Wed, 24 Oct 2007 12:44:35 +0200
From: "Giulio Cesare Solaroli" <giulio.cesare@gmail.com>
To: pgsql-performance@postgresql.org
Subject: Finalizing commit taking very long
MIME-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit
Content-Disposition: inline

Hello,

I am having a strange latency problem on my instance of Postgres that
I don't know how to investigate.

I am accessing the db instance using a Java application and the
Cayenne mapping framework. Everything works fine, except when it is
time to delete a user account (that is a user of the application, not
of Postgres).

Deleting an account trigger a (sort-of) cascade delete to remove also
all the dependent records stored on the db. The cascade constraints
are managed by the Cayenne library, and the db receives a list of
delete statements for all the rows of the different tables that should
be deleted; this is probably not optimal from a db point of view, but
is extremely convenient from an application point of view.

Anyway, the deletion of all the records is executed without much
problems (I had a huge slowdown here a few weeks ago, but I was
missing an index on a constraint).

Obviously, all the delete statements are grouped into a single
transaction; and when it is time to commit this transaction, the db
instance takes "forever".

Here are some logs taken from the db server:

[ lot of delete statements skipped]
2007-10-24 12:13:17 CEST LOG:  statement: EXECUTE <unnamed>  [PREPARE:
 DELETE FROM connection.USRCNN WHERE ID_USRCNN = $1]
2007-10-24 12:13:17 CEST LOG:  duration: 0.206 ms
2007-10-24 12:13:17 CEST LOG:  duration: 0.206 ms  statement: EXECUTE
<unnamed>  [PREPARE:  DELETE FROM connection.USRCNN WHERE ID_USRCNN =
$1]
2007-10-24 12:13:17 CEST LOG:  statement: PREPARE <unnamed> AS DELETE
FROM clipperz.USR WHERE ID_USR = $1
2007-10-24 12:13:17 CEST LOG:  statement: <BIND>
2007-10-24 12:13:17 CEST LOG:  statement: EXECUTE <unnamed>  [PREPARE:
 DELETE FROM clipperz.USR WHERE ID_USR = $1]
2007-10-24 12:13:17 CEST LOG:  duration: 0.761 ms
2007-10-24 12:13:17 CEST LOG:  duration: 0.761 ms  statement: EXECUTE
<unnamed>  [PREPARE:  DELETE FROM clipperz.USR WHERE ID_USR = $1]
2007-10-24 12:13:17 CEST LOG:  statement: <BIND>
2007-10-24 12:13:17 CEST LOG:  statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
2007-10-24 12:13:51 CEST LOG:  autovacuum: processing database "clipperz_beta"
2007-10-24 12:14:51 CEST LOG:  autovacuum: processing database "clipperz_beta"
2007-10-24 12:15:10 CEST LOG:  duration: 113300.147 ms
2007-10-24 12:15:10 CEST LOG:  duration: 113300.147 ms  statement:
EXECUTE <unnamed>  [PREPARE:  COMMIT]


As you may notice, the commit phase takes almost 2 full minutes. :-(

How can I understand what is going on on that timeframe in order to
try to fix it?

Thanks for your attention.

Best regards,

Giulio Cesare

PS: I run my development machine on a MacOS, with Postgres running on
a Parallels virtual machine. I don't think this really matters for the
above problem, but in case ...