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@xxxxxxxxx> -- Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
