Received: from maia.hub.org (maia-5.hub.org [200.46.204.29])
	by mail.postgresql.org (Postfix) with ESMTP id AA6821335B36
	for <pgsql-performance-postgresql.org@mail.postgresql.org>;
	Mon, 18 Oct 2010 11:14:01 -0300 (ADT)
Received: from mail.postgresql.org ([200.46.204.86])
	by maia.hub.org (mx1.hub.org [200.46.204.29]) (amavisd-maia, port 10024)
	with ESMTP id 57462-09
	for <pgsql-performance-postgresql.org@mail.postgresql.org>;
	Mon, 18 Oct 2010 14:13:55 +0000 (UTC)
X-Greylist: from auto-whitelisted by SQLgrey-1.7.6
Received: from sss.pgh.pa.us (sss.pgh.pa.us [66.207.139.130])
	by mail.postgresql.org (Postfix) with ESMTP id 54CDF1337B92
	for <pgsql-performance@postgresql.org>;
	Mon, 18 Oct 2010 11:13:53 -0300 (ADT)
Received: from sss2.sss.pgh.pa.us (tgl@localhost [127.0.0.1])
	by sss.pgh.pa.us (8.14.2/8.14.2) with ESMTP id o9IEDrYo018891;
	Mon, 18 Oct 2010 10:13:53 -0400 (EDT)
To: Eric Comeau <ecomeau@signiant.com>
cc: pgsql-performance@postgresql.org
Subject: Re: Help with duration of statement: EXECUTE <unnamed> [PREPARE:
	COMMIT]
In-reply-to: <i9c60b$ifv$1@news.hub.org> 
References: <i9c60b$ifv$1@news.hub.org>
Comments: In-reply-to Eric Comeau <ecomeau@signiant.com>
	message dated "Sat, 16 Oct 2010 08:32:11 -0400"
Date: Mon, 18 Oct 2010 10:13:53 -0400
Message-ID: <18890.1287411233@sss.pgh.pa.us>
From: Tom Lane <tgl@sss.pgh.pa.us>
X-Virus-Scanned: Maia Mailguard 1.0.1
X-Spam-Status: No, hits=-1.91 tagged_above=-10 required=5 tests=BAYES_00=-1.9,
	T_RP_MATCHES_RCVD=-0.01
X-Spam-Level: 
X-Archive-Number: 201010/288
X-Sequence-Number: 40706

Eric Comeau <ecomeau@signiant.com> writes:
> 2010-10-16 05:55:52 EDT [6334]: [1-1] LOG:  duration: 5572.517 ms 
> statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
> 2010-10-16 06:06:24 EDT [26856]: [1-1] LOG:  duration: 5617.866 ms 
> statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
> 2010-10-16 06:06:24 EDT [20740]: [13-1] LOG:  duration: 5210.190 ms 
> statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]
> 2010-10-16 08:24:06 EDT [8743]: [1-1] LOG:  duration: 6487.346 ms 
> statement: EXECUTE <unnamed>  [PREPARE:  COMMIT]

> Questions;

> 1) What do these statements mean?

They appear to be COMMIT commands.  (It's pretty stupid to be using the
PREPARE/EXECUTE machinery to execute a COMMIT, but that's evidently what
your client-side code is doing.)

> 2) How do I dig deeper to determine why they are taking longer than 5 secs.

My guess would be overstressed disk subsystem.  A COMMIT doesn't require
much except fsync'ing the commit WAL record down to disk ... but if the
disk is too busy to process that request quickly, you might have to
wait.  It also seems possible that the filesystem is interlocking the
fsync on the WAL file with previous writes to other files.  Anyway,
watching things with vmstat or iostat to see if there's an activity
spike when this is happening would confirm or refute that idea.

[ thinks for a bit ... ]  Actually, it's possible that the COMMIT
command is doing nontrivial work before it can really commit.  Perhaps
you have deferred foreign keys to check?

			regards, tom lane