Slow queries (high duration) and their log entries appearing out-of-order

I'm trying to debug a jboss/hibernate application that uses PostgreSQL
as a backend, for which PostgreSQL is reporting a lot of queries as
taking around 4398046 ms (~73 minutes) plus or minus 10 ms to
complete. I have two questions about this.

First, when I look at the logs, the long queries appear interleaved
between log lines from earlier. For example, when I set
log_min_duration_statement to 0, with a log_destination of stderr and
log_line_prefix of '%t %c ', my log file has entries like this:
...
2011-07-08 19:12:01 WEST 4e174859.1f5b LOG:  duration: 0.000 ms
execute <unnamed>: select count(*) as num_sender from madserv_sender
where alias = $1
2011-07-08 19:12:01 WEST 4e174859.1f5b DETAIL:  parameters: $1 = '965990300'
2011-07-08 20:25:19 WEST 4e174859.1f5b LOG:  duration: 4398046.575 ms
bind S_4: INSERT INTO
madserv_user_sender(user_id,sender_id)values((select id from
madserv_admin_user where login = $1),(select id from madserv_sender
where alias = $2))
2011-07-08 20:25:19 WEST 4e174859.1f5b DETAIL:  parameters: $1 =
'3045530977U80019488', $2 = '965990300'
2011-07-08 20:25:19 WEST 4e174859.1f5b LOG:  duration: 0.322 ms
execute S_4: INSERT INTO
madserv_user_sender(user_id,sender_id)values((select id from
adserv_admin_user where login = $1),(select id from madserv_sender
where alias = $2))
2011-07-08 20:25:19 WEST 4e174859.1f5b DETAIL:  parameters: $1 =
'3045530977U80019488', $2 = '965990300'
2011-07-08 19:12:01 WEST 4e174859.1f5b LOG:  duration: 0.339 ms  parse
<unnamed>: select count(*) as num_user from madserv_admin_user where
login = '8842934'
...

Here the entries from 20:25:19 are bracketed by entries from 19:12:01.
I noticed that 20:25:19 -  4398046.575 ms is 19:12:01 - but this is
strange to me as I thought the log entries would appear in
chronological order. Or am I misunderstanding something here?

Secondly, I'm trying to understand why the queries are taking a long
time. The queries affected are varied, and I see the delays occurring
in the parse, bind and execute states. Is there a known issue which
would cause this? I've even seen the behaviour on the query "select
1", so I don't think it's a problem with the schema design or even
general performance:
2011-07-01 01:10:30 WEST LOG:  duration: 4398046.526 ms  bind
<unnamed>: select 1
2011-07-01 00:00:13 WEST LOG:  duration: 4398046.589 ms  parse
<unnamed>: select 1

I've put the output from explain analyze at
http://explain.depesz.com/s/RYR for the above query "INSERT INTO
madserv_user_sender". The madserv_user_sender table has 2 columns of
type integers, with ~2000 entries and foreign key constraints on the
other tables/columns in the query. The madserv_admin_user table has
~4500 rows and has a btree index on the login(int) column. The
madserv_sender table has ~300 entries and a btree index on the alias
(varchar(32)) column.

Between 19:11 and 19:12 there are ~100s of these inserts running per
second. The developers say that they haven't seen this before.

My version of PostgreSQL is:
PostgreSQL 8.3.5 on i686-redhat-linux-gnu, compiled by GCC gcc (GCC)
4.1.2 20071124 (Red Hat 4.1.2-42)

running on RHEL 5.4 i686. PostgreSQL was installed from RPMs which
came from http://www.postgresql.org/ftp/binary/

Jboss is 4.2.3-GA, running on the Sun JDK 1.6.0u12, with the
PostgreSQL JDBC JAR postgresql-8.3-603.jdbc4.jar.

I realise that I'm behind on the minor version for the PostgreSQL
server, and I'm going to recommend upgrading - but it'd be nice to
know if anyone else has seen this behaviour before.

Thanks for your help.
--
Jonathan Barber <jonathan.barber@gmail.com>