Re: Help with duration of statement: EXECUTE <unnamed> [PREPARE: COMMIT]

Eric Comeau <ecomeau(at)signiant(dot)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