Re: Deadlock between VACUUM and ALTER TABLE commands

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(at)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(at)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(at)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(at)brandwatch(dot)com>
wrote:

> Hello Kevin,
>
> On 06/04/16 23:22, Kevin Burke wrote:
>
> *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.
>
> I'd suggest one more method: SET CONSTRAINTS ALL DEFERRED and DELETE FROM
> all tables in arbitrary order (will require making constraints deferrable)
>
> Specifically 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 only indicates that 16936 does not allow ALTER TABLE to acquire
> AccessExclusiveLock
> 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
> <http://www.postgresql.org/docs/9.4/static/explicit-locking.html#TABLE-LOCK-COMPATIBILITY>
> to determine what locks are conflicting one with another Regards, Alexey
> Bashtanov
>

--
kevin