Hi Alexey,
Thank you for your suggestion. We had to rewrite our constraints to be DEFERRABLE INITIALLY IMMEDIATE, but after we did that we saw a nice speedup in our clear-all-tables query.
Unfortunately I'm still seeing a very slow query which is affecting our tests. It's happening with roughly the same frequency as the previous error.
The query log is here: https://gist.github.com/kevinburkeshyp/f1a4f73f8933e027aebbc53283acced2
In the log, it looks like an INSERT on the users table takes about 23 seconds. This query is connecting from _javascript_ to a Postgres server on the same machine. After 18 seconds, the test performing the INSERT times out, we try to clear the database, and then the next test runs. The next test also attempts to INSERT a record, but is blocked on the first INSERT. After 5 more seconds, the first INSERT completes, and the second INSERT is allowed to run.
2016-04-14 00:46:54.649 UTC 2016-04-14 00:46:34 UTC [14308-570ee86a.37e4-42] 00000 ubuntu@circle_test LOG: process 14308 still waiting for ExclusiveLock on extension of relation 17215 of database 16387 after 1000.104 ms
2016-04-14 00:46:54.649 UTC 2016-04-14 00:46:34 UTC [14308-570ee86a.37e4-43] 00000 ubuntu@circle_test DETAIL: Process holding the lock: 14260. Wait queue: 14308.
2016-04-14 00:46:58.979 UTC 2016-04-14 00:46:34 UTC [14308-570ee86a.37e4-45] 00000 ubuntu@circle_test LOG: process 14308 acquired ExclusiveLock on extension of relation 17215 of database 16387 after 5330.117 ms
Between the last time I emailed and now, I also disabled autovacuum on the server; it seemed unnecessary if we are issuing ~10k queries tops, and generating ~100k records tops, in the course of a test run. However, I didn't see any other queries or log messages (e.g. "kicking off autovacuum") that would have indicated a problem.
Here's the schema on the table that generated the 23-second long INSERT: https://gist.github.com/kevinburkeshyp/5a40d372b6aa1e1426801d8195cb0b61
Any ideas why an INSERT on an empty table, to a low-load server running on the same machine, with no other queries being generated during that time, could take 23 seconds to complete? The server is running Postgres 9.4.6.
What other information do I/you need to figure out what's going on?
Thanks,
Kevin
On Thu, Apr 7, 2016 at 1:26 AM, Alexey Bashtanov <alexey@xxxxxxxxxxxxxx> wrote:
Hello Kevin,
On 06/04/16 23:22, Kevin Burke wrote:
I'd suggest one more method: SET CONSTRAINTS ALL DEFERRED and DELETE FROM all tables in arbitrary order (will require making constraints deferrable)Why mess around with DISABLE/ENABLE TRIGGER instead of TRUNCATE? We observed that TRUNCATE took about 200ms, but this method takes about 13ms. Over a our test suite TRUNCATE is going to more or less double the length of the suite.
We could resolve some kind of foreign key dependency tree, issue the DELETE FROM's in the right order, and skip DISABLE TRIGGER etc., but haven't invested the time to do this or figured out how to maintain it/update it as we add new tables.
this only indicates that 16936 does not allow ALTER TABLE to acquire AccessExclusiveLockSpecifically we kick off the ALTER TABLE ... DELETE, a second later (our deadlock_timeout) a log message appears that the ALTER TABLE is waiting for an AccessExclusiveLock held by process 16936... which is later revealed to be an autovacuum process of the "events" table.
this does not necessarily mean that 16936 has acquired AccessExclusiveLock, it means that 16936 has acquired some lock conflicting with AccessExclusiveLock you can use this table to determine what locks are conflicting one with another Regards, Alexey Bashtanov
kevin
