Как может возникнуть тупик, если не заданы блокировки строк или таблиц? (вызвано рельсами 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 прерывает одну из них.

Чтобы этого не происходило, ваше приложение должно гарантировать, что оно всегда получает блокировки в одном и том же порядке. Там, где это невозможно, он должен пытаться работать только с одним зависимым объектом в любой данной транзакции, поэтому проблемы с заказом не могут возникнуть. Или он должен быть готов к обработке взаимоблокировок путем перехвата исключения и повторной выдачи транзакции.

Чтобы узнать больше, см. Явная блокировка в руководстве.

Другие вопросы по тегам