On Wed, Oct 28, 2009 at 12:29 AM, Alvaro Herrera <alvherre@xxxxxxxxxxxxxxxxx> wrote:
No, the transactions were not cancelled. All I saw in he pg_log is this (taken at the time le lock was lifted):
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 LOG: process 14866 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.271 ms
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 LOG: process 14048 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.409 ms
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:39:50 CET dbuser dbase 10.33.10.41 LOG: duration: 62103.487 ms statement: SELECT put_root_files_into_ag_scheduler_delete_files( 8 , 50 );
2009-10-27 05:39:57 CET dbuser dbase 10.33.10.133 LOG: process 14797 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.362 ms
2009-10-27 05:39:57 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.33 LOG: process 18964 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572619.123 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.33 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 LOG: process 24284 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572193.509 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 LOG: process 19497 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572005.173 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
The log_user table is the mother table with rules redirecting the inserts to the monthly partitions.
I was not monitoring the database at the time, all I saw is that pg_stat_user_tables dates the last_autovacuum at 2009-10-27 05:40:09.611129+01 this day on the partition.
We have no cronjobs running vacuum on these monthly partition.
No sign of canceled vacuums neither.
Regards,
JC Praud escribió:
This bit does not make much sense to me. A transaction waiting will not
> - Last night the database locked. pg_log full of messages about insert into
> the mother table waiting for a lock.
show up in the log. Were they cancelled? Can you paste an extract from
the log?
No, the transactions were not cancelled. All I saw in he pg_log is this (taken at the time le lock was lifted):
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 LOG: process 14866 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.271 ms
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 LOG: process 14048 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.409 ms
2009-10-27 05:39:19 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:39:50 CET dbuser dbase 10.33.10.41 LOG: duration: 62103.487 ms statement: SELECT put_root_files_into_ag_scheduler_delete_files( 8 , 50 );
2009-10-27 05:39:57 CET dbuser dbase 10.33.10.133 LOG: process 14797 still waiting for RowExclusiveLock on relation 26683 of database 23806 after 5000.362 ms
2009-10-27 05:39:57 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.33 LOG: process 18964 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572619.123 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.33 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 LOG: process 24284 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572193.509 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 LOG: process 19497 acquired RowExclusiveLock on relation 26683 of database 23806 after 3572005.173 ms
2009-10-27 05:40:09 CET dbuser dbase 10.33.10.133 STATEMENT: INSERT INTO log_user (id_user, action, comment, date, id_session, ip_addr) VALUES (...)
The log_user table is the mother table with rules redirecting the inserts to the monthly partitions.
Do you have a vacuum in cron or something like that? As Tom says, if it
> - After about 40min, the waiting queries acquired their locks and ran.
had been autovacuum, it should have been cancelled automatically (else
we've got a bug); but something invoking vacuum externally wouldn't
have, so what you describe is what we would expect.
I was not monitoring the database at the time, all I saw is that pg_stat_user_tables dates the last_autovacuum at 2009-10-27 05:40:09.611129+01 this day on the partition.
We have no cronjobs running vacuum on these monthly partition.
No sign of canceled vacuums neither.
Regards,
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
--
JC
Ph'nglui mglw'nafh Cthulhu n'gah Bill R'lyeh Wgah'nagl fhtagn!
