Как может возникнуть тупик, если не заданы блокировки строк или таблиц? (вызвано рельсами ActiveRecord#touch)
Я широко использую функции кэширования шаблонов в Rails 4. Много вложенных шаблонов и touch: true
на многих моделях. В целом это оказалось комплексным решением, о котором легко рассуждать.
Недавно я реализовал функцию, в которой создаются несколько фоновых заданий, которые перебирают сотни объектов и создают другие объекты по отношению к ним. Когда создается каждый из этих объектов, затрагивается один и тот же пользователь.
Итак, эти две работы выполняются параллельно:
- задание A: последовательно создает сотни объектов, каждый раз касаясь пользователя 123
- задание B: последовательно создает сотни объектов, каждый раз касаясь пользователя 123
После развертывания этой функции я обнаружил, что иногда postgres обнаруживает тупик и отменяет два запроса, которые ожидают друг друга. Запрос, показанный в ошибке, всегда является сенсорным запросом (обновите значение параметра update_at для пользователя 123 с текущим временем).
pid: 33541 tid: 0 vtid: LOG: database system was shut down at 2014-03-27 19:57:11 EDT
pid: 33545 tid: 0 vtid: LOG: autovacuum launcher started
pid: 33539 tid: 0 vtid: LOG: database system is ready to accept connections
pid: 33626 tid: 0 vtid: 2/5 LOG: statement: set client_encoding to 'UTF8'
pid: 33626 tid: 0 vtid: 2/6 LOG: statement: set client_encoding to 'unicode'
pid: 33626 tid: 0 vtid: 2/7 LOG: statement: SET client_min_messages TO 'warning'
pid: 33626 tid: 0 vtid: 2/8 LOG: statement: SHOW client_min_messages
pid: 33626 tid: 0 vtid: 2/9 LOG: statement: SET client_min_messages TO 'panic'
pid: 33626 tid: 0 vtid: 2/10 LOG: statement: SET standard_conforming_strings = on
pid: 33626 tid: 0 vtid: 2/11 LOG: statement: SET client_min_messages TO 'warning'
pid: 33626 tid: 0 vtid: 2/12 LOG: statement: SET time zone 'UTC'
pid: 33626 tid: 0 vtid: 2/13 LOG: statement: SELECT oid, typname, typelem, typdelim, typinput FROM pg_type
pid: 33626 tid: 0 vtid: 2/14 LOG: statement: SHOW TIME ZONE
pid: 33626 tid: 0 vtid: 2/15 LOG: statement: SELECT 1
pid: 33626 tid: 0 vtid: 2/16 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'users'
AND n.nspname = ANY (current_schemas(false))
pid: 33626 tid: 0 vtid: 2/17 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"users"'::regclass
pid: 33626 tid: 0 vtid: 2/18 LOG: statement: SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT 1
pid: 33626 tid: 0 vtid: 2/19 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/2 LOG: statement: set client_encoding to 'UTF8'
pid: 33627 tid: 0 vtid: 3/3 LOG: statement: set client_encoding to 'unicode'
pid: 33627 tid: 0 vtid: 3/4 LOG: statement: SET client_min_messages TO 'warning'
pid: 33627 tid: 0 vtid: 3/5 LOG: statement: SHOW client_min_messages
pid: 33627 tid: 0 vtid: 3/6 LOG: statement: SET client_min_messages TO 'panic'
pid: 33627 tid: 0 vtid: 3/7 LOG: statement: SET standard_conforming_strings = on
pid: 33627 tid: 0 vtid: 3/8 LOG: statement: SET client_min_messages TO 'warning'
pid: 33627 tid: 0 vtid: 3/9 LOG: statement: SET time zone 'UTC'
pid: 33627 tid: 0 vtid: 3/10 LOG: statement: SELECT oid, typname, typelem, typdelim, typinput FROM pg_type
pid: 33627 tid: 0 vtid: 3/11 LOG: statement: SHOW TIME ZONE
pid: 33627 tid: 0 vtid: 3/12 LOG: statement: SELECT 1
pid: 33627 tid: 0 vtid: 3/13 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/14 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'users'
AND n.nspname = ANY (current_schemas(false))
pid: 33627 tid: 0 vtid: 3/15 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"users"'::regclass
pid: 33627 tid: 0 vtid: 3/16 LOG: statement: SELECT id FROM "users" WHERE (bared_at IS NOT NULL) ORDER BY "users"."id" ASC LIMIT 1000
pid: 33628 tid: 0 vtid: 4/2 LOG: statement: set client_encoding to 'UTF8'
pid: 33628 tid: 0 vtid: 4/3 LOG: statement: set client_encoding to 'unicode'
pid: 33628 tid: 0 vtid: 4/4 LOG: statement: SET client_min_messages TO 'warning'
pid: 33628 tid: 0 vtid: 4/5 LOG: statement: SHOW client_min_messages
pid: 33628 tid: 0 vtid: 4/6 LOG: statement: SET client_min_messages TO 'panic'
pid: 33628 tid: 0 vtid: 4/7 LOG: statement: SET standard_conforming_strings = on
pid: 33628 tid: 0 vtid: 4/8 LOG: statement: SET client_min_messages TO 'warning'
pid: 33628 tid: 0 vtid: 4/9 LOG: statement: SET time zone 'UTC'
pid: 33628 tid: 0 vtid: 4/10 LOG: statement: SELECT oid, typname, typelem, typdelim, typinput FROM pg_type
pid: 33628 tid: 0 vtid: 4/11 LOG: statement: SHOW TIME ZONE
pid: 33628 tid: 0 vtid: 4/12 LOG: statement: SELECT 1
pid: 33628 tid: 0 vtid: 4/13 LOG: statement: SELECT id FROM "users" WHERE (bared_at IS NOT NULL) ORDER BY "users"."id" ASC LIMIT 1000
pid: 33627 tid: 0 vtid: 3/17 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'monkeys'
AND n.nspname = ANY (current_schemas(false))
pid: 33628 tid: 0 vtid: 4/14 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'monkeys'
AND n.nspname = ANY (current_schemas(false))
pid: 33627 tid: 0 vtid: 3/18 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"monkeys"'::regclass
pid: 33628 tid: 0 vtid: 4/15 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"monkeys"'::regclass
pid: 33627 tid: 0 vtid: 3/19 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users_monkeys"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33628 tid: 0 vtid: 4/16 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users_monkeys"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/20 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"monkeys"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33628 tid: 0 vtid: 4/17 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"monkeys"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/21 LOG: statement: SHOW search_path
pid: 33628 tid: 0 vtid: 4/18 LOG: statement: SHOW search_path
pid: 33627 tid: 0 vtid: 3/23 LOG: execute a1: SELECT COUNT(*) FROM "monkeys" INNER JOIN "users_monkeys" ON "monkeys"."id" = "users_monkeys"."monkey_id" WHERE "users_monkeys"."user_id" = $1 AND (((monkeys.name = 'recruiter') AND (monkeys.resource_type IS NULL) AND (monkeys.resource_id IS NULL)))
pid: 33627 tid: 0 vtid: 3/23 DETAIL: parameters: $1 = '2'
pid: 33628 tid: 0 vtid: 4/20 LOG: execute a1: SELECT COUNT(*) FROM "monkeys" INNER JOIN "users_monkeys" ON "monkeys"."id" = "users_monkeys"."monkey_id" WHERE "users_monkeys"."user_id" = $1 AND (((monkeys.name = 'recruiter') AND (monkeys.resource_type IS NULL) AND (monkeys.resource_id IS NULL)))
pid: 33628 tid: 0 vtid: 4/20 DETAIL: parameters: $1 = '2'
pid: 33627 tid: 0 vtid: 3/24 LOG: statement: SELECT "foos".* FROM "foos" WHERE "foos"."user_id" = 2 AND "foos"."fooer_id" = 1 LIMIT 1
pid: 33628 tid: 0 vtid: 4/21 LOG: statement: SELECT "foos".* FROM "foos" WHERE "foos"."user_id" = 1 AND "foos"."fooer_id" = 2 LIMIT 1
pid: 33628 tid: 0 vtid: 4/22 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"foos"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/25 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"foos"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33628 tid: 0 vtid: 4/23 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'foos'
AND n.nspname = ANY (current_schemas(false))
pid: 33627 tid: 0 vtid: 3/26 LOG: statement: SELECT COUNT(*)
FROM pg_class c
LEFT JOIN pg_namespace n ON n.oid = c.relnamespace
WHERE c.relkind in ('v','r')
AND c.relname = 'foos'
AND n.nspname = ANY (current_schemas(false))
pid: 33628 tid: 0 vtid: 4/24 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"foos"'::regclass
pid: 33627 tid: 0 vtid: 3/27 LOG: statement: SELECT attr.attname
FROM pg_attribute attr
INNER JOIN pg_constraint cons ON attr.attrelid = cons.conrelid AND attr.attnum = cons.conkey[1]
WHERE cons.contype = 'p'
AND cons.conrelid = '"foos"'::regclass
pid: 33628 tid: 0 vtid: 4/25 LOG: statement: BEGIN
pid: 33627 tid: 0 vtid: 3/28 LOG: statement: BEGIN
pid: 33628 tid: 0 vtid: 4/25 LOG: statement: SELECT 1 AS one FROM "foos" WHERE ("foos"."user_id" = 1 AND "foos"."id" != 4 AND "foos"."fooer_id" = 2) LIMIT 1
pid: 33627 tid: 0 vtid: 3/28 LOG: statement: SELECT 1 AS one FROM "foos" WHERE ("foos"."user_id" = 2 AND "foos"."id" != 3 AND "foos"."fooer_id" = 1) LIMIT 1
pid: 33628 tid: 0 vtid: 4/25 LOG: statement: SELECT a.attname, format_type(a.atttypid, a.atttypmod),
pg_get_expr(d.adbin, d.adrelid), a.attnotnull, a.atttypid, a.atttypmod
FROM pg_attribute a LEFT JOIN pg_attrdef d
ON a.attrelid = d.adrelid AND a.attnum = d.adnum
WHERE a.attrelid = '"users"'::regclass
AND a.attnum > 0 AND NOT a.attisdropped
ORDER BY a.attnum
pid: 33627 tid: 0 vtid: 3/28 LOG: execute a2: SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1
pid: 33627 tid: 0 vtid: 3/28 DETAIL: parameters: $1 = '2'
pid: 33627 tid: 0 vtid: 3/28 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.619282' WHERE "users"."id" = 2
pid: 33628 tid: 0 vtid: 4/25 LOG: execute a2: SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1
pid: 33628 tid: 0 vtid: 4/25 DETAIL: parameters: $1 = '1'
pid: 33627 tid: 6723 vtid: 3/28 LOG: execute a2: SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1
pid: 33627 tid: 6723 vtid: 3/28 DETAIL: parameters: $1 = '1'
pid: 33628 tid: 0 vtid: 4/25 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.627175' WHERE "users"."id" = 1
pid: 33627 tid: 6723 vtid: 3/28 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.628983' WHERE "users"."id" = 1
pid: 33628 tid: 6724 vtid: 4/25 LOG: execute a2: SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT 1
pid: 33628 tid: 6724 vtid: 4/25 DETAIL: parameters: $1 = '2'
pid: 33628 tid: 6724 vtid: 4/25 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.632111' WHERE "users"."id" = 2
pid: 33627 tid: 6723 vtid: 3/28 ERROR: deadlock detected
pid: 33627 tid: 6723 vtid: 3/28 DETAIL: Process 33627 waits for ShareLock on transaction 6724; blocked by process 33628.
Process 33628 waits for ShareLock on transaction 6723; blocked by process 33627.
Process 33627: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.628983' WHERE "users"."id" = 1
Process 33628: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.632111' WHERE "users"."id" = 2
Я удивлен, что этот тупик возникает, потому что ни строка, ни таблица не блокируются. Разве вторая транзакция не должна просто ждать завершения первой?
обновление: минимальное sql-only воспроизведение ошибки здесь: https://gist.github.com/jjb/9823023
1 ответ
Ваш оригинальный журнал был неполным, потому что первый UPDATE
У них не было идентификатора транзакции, поэтому они не были включены в исходный журнал.
Теперь, когда есть журнал с виртуальными txids, вы можете видеть, что PostgreSQL ведет себя точно так, как задумано.
Соответствующие строки:
pid: 33627 tid: 0 vtid: 3/28 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.619282' WHERE "users"."id" = 2
pid: 33628 tid: 0 vtid: 4/25 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.627175' WHERE "users"."id" = 1
pid: 33627 tid: 6723 vtid: 3/28 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.628983' WHERE "users"."id" = 1
pid: 33628 tid: 6724 vtid: 4/25 LOG: statement: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.632111' WHERE "users"."id" = 2
pid: 33627 tid: 6723 vtid: 3/28 ERROR: deadlock detected
pid: 33627 tid: 6723 vtid: 3/28 DETAIL: Process 33627 waits for ShareLock on transaction 6724; blocked by process 33628.
Process 33628 waits for ShareLock on transaction 6723; blocked by process 33627.
Process 33627: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.628983' WHERE "users"."id" = 1
Process 33628: UPDATE "users" SET "updated_at" = '2014-03-27 23:58:02.632111' WHERE "users"."id" = 2
Вот:
- 3/28 блокировки ID =2 для обновления
- 4/25 блокировок id=1 для обновления
- 3/28 попыток заблокировать id=1 для обновления, блокировка блокировки, удерживаемой 4/25
- 4/25 попыток заблокировать id=2 для обновления, блокировка блокировки, удерживаемой 3/28
На этом этапе ни одна из транзакций не может добиться прогресса, поэтому PostgreSQL прерывает одну из них.
Чтобы этого не происходило, ваше приложение должно гарантировать, что оно всегда получает блокировки в одном и том же порядке. Там, где это невозможно, он должен пытаться работать только с одним зависимым объектом в любой данной транзакции, поэтому проблемы с заказом не могут возникнуть. Или он должен быть готов к обработке взаимоблокировок путем перехвата исключения и повторной выдачи транзакции.
Чтобы узнать больше, см. Явная блокировка в руководстве.