Всем привет! Уже почти неделю ковыряюсь с аномалиями в транзакциях mysql, идей больше нет и решил обратиться за помощью!
Server version: 5.7.20-19-log Percona Server (GPL), Release '19', Revision '3c5d3e5d53c'
Transaction isolation: REPEATABLE READ
БД используется на довольно нагруженном сайте, где часть задач выполняется в фоне. Используется очередь сообщений, которую обрабатывают около 10 воркеров. Каждый воркер открывает по одному соединению к БД, и как правило, оно открыто все время жизни воркера(от суток до 2х недель). Проблемы были замечены только в них.
Схема данных будет сильно упрощена для наглядности. (
SQLFiddle )
Схема
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
CREATE TABLE `currencies` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`symbol` char(3) COLLATE utf8_unicode_ci NOT NULL,
`name` varchar(20) COLLATE utf8_unicode_ci NOT NULL,
PRIMARY KEY (`id`),
UNIQUE KEY `currencies_symbol_unique` (`symbol`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
CREATE TABLE `accounts` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`user_id` int(10) unsigned NOT NULL, # in real DB foreign on users table
`currency_id` int(10) unsigned NOT NULL,
`balance` decimal(20,8) NOT NULL DEFAULT '0.00000000',
PRIMARY KEY (`id`),
UNIQUE KEY `accounts_user_id_currency_id_unique` (`user_id`, `currency_id`),
KEY `accounts_currency_id_foreign` (`currency_id`),
CONSTRAINT `accounts_currency_id_foreign` FOREIGN KEY (`currency_id`) REFERENCES `currencies` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
CREATE TABLE `stats` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`date` date NOT NULL,
`user_id` int(10) unsigned NOT NULL, # in real DB foreign on users table
`currency_id` int(10) unsigned DEFAULT NULL,
`op_count` int(10) unsigned NOT NULL DEFAULT '0',
PRIMARY KEY (`id`),
UNIQUE KEY `daily_user_stats_date_user_id_currency_id_unique` (`date`,`user_id`,`currency_id`),
KEY `stats_user_id_foreign` (`user_id`),
KEY `stats_currency_id_foreign` (`currency_id`),
CONSTRAINT `stats_currency_id_foreign` FOREIGN KEY (`currency_id`) REFERENCES `currencies` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
CREATE TABLE `operations` (
`id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`user_id` int(10) unsigned NOT NULL,
`currency_id` int(10) unsigned NOT NULL,
`op_hash` varchar(70) COLLATE utf8_unicode_ci DEFAULT NULL,
`amount` decimal(20,8) NOT NULL DEFAULT '0.00000000',
PRIMARY KEY (`id`),
CONSTRAINT `operations_currency_id_foreign` FOREIGN KEY (`currency_id`) REFERENCES `currencies` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;
Как видно из схемы таблица stats имеет не совсем работающий уникальный ключ, из-за того, что в нем используется nullable поле currency_id. Первая проблема которая привлекла внимание -- дубликаты записей в этой таблице вида DATE, USER_ID, CURRENCY_ID IS NULL. Первые мысли были на рейс кондишн и не использование/неправильное использование блокировок. После аудита мест создания записей рейс кондишн не был обнаружен.
Наличие дубликатов в той таблице не особо портило жизнь и с этой проблемой решили пока жить.
НО! немного позже стали поступать жалобы от пользователей на некорректное обновление балансов после создания "операций" (таблица operations). Опять же первым делом был сделан поиск рейс кондишинов, но и в этот раз они не были найдены. Поэтому включили general_log и стали ждать повторений багов. Вот пример запросов в котором воспроизводится баг.
1.
2.
3.
4.
5.
6.
7.
8.
9.
2018-02-08T16:00:29.391039Z 107061357 Query START TRANSACTION
2018-02-08T16:00:29.394849Z 107061357 Execute select * from `currencies` where `currencies`.`id` = 1 limit 1 lock in share mode
2018-02-08T16:00:29.396052Z 107061357 Execute select * from `operations` where `user_id` = 1155 and `currency_id` = 1 and `op_hash` = 'XXXCCC' limit 1 for update
2018-02-08T16:00:29.784439Z 107061357 Execute select * from `accounts` where (`user_id` = 1155 and `currency_id` = 1) limit 1 for update
2018-02-08T16:00:36.737472Z 107061357 Execute update `accounts` set `balance` = '100' where `id` = 100500
2018-02-08T16:00:36.738622Z 107061357 Execute select * from `stats` where (`user_id` = 1155 and `currency_id` is null and `date` = '2018-02-08') limit 1 for update # Select if exists and update, or insert otherwise
2018-02-08T16:00:36.740155Z 107061357 Execute insert into `stats` (`user_id`, `currency_id`, `date`, `op_count`) values (303155, NULL, '2018-02-08', 1)
2018-02-08T16:00:38.004752Z 107061357 Execute insert into `operations` (`user_id`, `currency_id`, `op_hash`, `amount`) values (303155, 2, 'XXXCCC', '100')
2018-02-08T16:00:38.128726Z 107061357 Query COMMIT
После выполнения этой транзакции, записи в таблице operations и stats были добавлены, но к моему удивлению accounts.balance содержал старое значение! Я не мог поверить своим глазам! Еще что смутило, так это то, что в таблице stats до выполнения операции уже была запись за этот день для этого пользователя currency_id is null, но почему то код вставил еще одну запись, не найдя ее по критерию поиска. Таким образом создав дубликат, о котором я писал выше.
Дальше было много поисков по логам grep'ом, но особых результатов это не дало. Четко коррелируется между всеми повторениями багов вот какие факты:
Аномалии всегда происходят в воркерах
Аномалии всегда происходят с операциями которые добавлены в начале часа (об этом позже)
Во всех логах аномалий, были выявлены также аномалии с созданием дубликата записи в таблицу stats(в случаях создания операции без багов, всегда запись находится и обновляется)
Далее было принято решение посмотреть general_log на слейве, и конечно же операции UPDATE для accounts я там не увидел, но INSERT в operations и в stats там были. Полез смотреть бинлог, и в нем таже история, такое чувство что после/перед запросом
1.
select * from `stats` ... for update
транзакция делает rollback и потом опять открывается.
вот пример бинлога
бинлог
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
#180208 16:00:36 server id 2 end_log_pos 31456966 CRC32 0xd32e6f52 Intvar
SET INSERT_ID=1982809/*!*/;
#180208 16:00:36 server id 2 end_log_pos 31457177 CRC32 0x87dd5690 Query thread_id=107061357 exec_time=1 error_code=0
SET TIMESTAMP=1518105636/*!*/;
insert into `stats` (`user_id`, `currency_id`, `date`, `op_count`) values (1155, NULL, '2018-02-08', 1)
/*!*/;
# at 31457177
#180208 16:00:36 server id 2 end_log_pos 31457208 CRC32 0x11b139be Xid = 8755238199
COMMIT/*!*/;
# at 31457208
#180208 16:00:38 server id 2 end_log_pos 31512632 CRC32 0x321e6aa7 Query thread_id=107061357 exec_time=0 error_code=0
SET TIMESTAMP=1518105638/*!*/;
BEGIN
/*!*/;
# at 31512612
#180208 16:00:38 server id 2 end_log_pos 31512664 CRC32 0xe76dd851 Intvar
SET INSERT_ID=8113929/*!*/;
#180208 16:00:38 server id 2 end_log_pos 31513127 CRC32 0xa0eb9a2b Query thread_id=107061357 exec_time=0 error_code=0
SET TIMESTAMP=1518105648/*!*/;
insert into `operations` (`user_id`, `currency_id`, `op_hash`, `amount`) values (1155, 1, 'XXXCCC', '100')
/*!*/;
# at 31513117
т.е. как видим и тут UPDATE account нет.
Дальше вот какие появились мысли.
Так как приложение часто находится под нагрузкой, иногда возникают дедлоки, и на уровне приложения в тех местах где это возможно,
оно пытается перезапустить транзакцию и повторить операцию как это советует дока к БД.
Так как все аномалии встречаются близко к 00:00, начали искать процессы которые запускаются по крону, и нашли парочку тяжеловесов. Вспомнили что раньше проскакивали дедлоки в логах тоже ближе к началу каждого часа, но после того как внедрили повторение операций, они пропали.... Решил взглянуть в INNODB STATUS и увидел что последний дедлок был как раз на таблицу stats и operations.
Deadlock
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
------------------------
LATEST DETECTED DEADLOCK
------------------------
2018-02-08 16:44:08 0x7f1bf5e7b700
*** (1) TRANSACTION:
TRANSACTION 443740480, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 14 lock struct(s), heap size 1136, 8 row lock(s), undo log entries 4
MySQL thread id 107582382, OS thread handle 139758067050240, query id 8765564614 172.17.0.2 DB Sending data
select * from `stats` where (`user_id` = 5116 and `currency_id` is null and `date` = '2018-02-08') limit 1 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 149 page no 15866 n bits 736 index stats_date_user_id_currency_id_unique of table `DB`.`stats` trx id 443740480 lock_mode X waiting
*** (2) TRANSACTION:
TRANSACTION 443740461, ACTIVE 45 sec inserting
mysql tables in use 1, locked 1
41 lock struct(s), heap size 8400, 45 row lock(s), undo log entries 31
MySQL thread id 107516770, OS thread handle 139758066448128, query id 8765564657 172.17.0.2 DB update
insert into `operations` (`user_id`, `currency_id`, `op_hash`, `amount`) values (5116, 1, 'CCZXCZX', '100500')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 149 page no 15866 n bits 736 index stats_date_user_id_currency_id_unique of table `DB`.`stats` trx id 443740461 lock_mode X
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 221 page no 2910 n bits 120 index PRIMARY of table `DB`.`users` trx id 443740461 lock mode S locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)
но что конкретно приводит к откату части транзакции так и не удалось понять! Собственно прошу помощи или совета, куда копать!
в доке есть упоминание об откате одного SQL statement
. However, if just a single SQL statement is rolled back as a result of an error, some of the locks set by the statement may be preserved.
но насколько я понял по тексту, только из-за ошибки. Если там ошибка то почему драйвер ее не бросает как исключение? в общем странно все это....
Всем добра!
