Page MenuHomePhabricator

User::addGroups() gives lock timeouts and deadlocks
Closed, ResolvedPublic

Description

While very hard to reproduce, User::addGroup() seems to be stuck in deadlocks and such:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-03-27 14:00:11 7fc9fef4b700
*** (1) TRANSACTION:
TRANSACTION 117004546, ACTIVE 37 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 781269, OS thread handle 0x7fc938249700, query id 17748393 185.52.2.113 mediawiki update
INSERT /* User::addGroup SleepyMode */ IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 45076 page no 3 n bits 88 index `ug_user_group` of table `developmentwiki`.`user_groups` trx table locks 1 total table locks 2  trx id 117004546 lock_mode X insert intention waiting lock hold time 0 wait time before grant 0
*** (2) TRANSACTION:
TRANSACTION 117004727, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 781387, OS thread handle 0x7fc9fef4b700, query id 17750868 185.52.2.113 mediawiki update
INSERT /* User::addGroup SleepyMode */ IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 45076 page no 3 n bits 88 index `ug_user_group` of table `developmentwiki`.`user_groups` trx table locks 1 total table locks 2  trx id 117004727 lock mode S lock hold time 0 wait time before grant 0
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 45076 page no 3 n bits 88 index `ug_user_group` of table `developmentwiki`.`user_groups` trx table locks 1 total table locks 2  trx id 117004727 lock_mode X insert intention waiting lock hold time 0 wait time before grant 0
*** WE ROLL BACK TRANSACTION (2)
------------

Some stuff found in HHVM error log and MediaWiki database-error log:

Sun Mar 27 13:49:10 UTC 2016    mw1     developmentwiki User::addGroup  185.52.1.77     1213    Deadlock found when trying to get lock; try restarting transaction (185.52.1.77)
        INSERT IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')
Sun Mar 27 13:49:10 UTC 2016    mw1     developmentwiki User::addGroup  185.52.1.77     1213    Deadlock found when trying to get lock; try restarting transaction (185.52.1.77)
        INSERT IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')
Sun Mar 27 13:56:12 UTC 2016    mw1     developmentwiki User::addGroup  185.52.1.77     2062    Read timeout is reached (185.52.1.77)   INSERT IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')
SlowTimer [96863ms] at runtime/ext_mysql: slow query: INSERT /* User::addGroup SleepyMode */ IGNORE INTO `user_groups` (ug_user,ug_group) VALUES ('20','sysop')

(and a lot more)

MediaWiki1.26.2 (7a623f9)
HHVM3.6.6 (srv)
MariaDB10.0.23-MariaDB-0+deb8u1-log
MariaDB configurationhttps://github.com/miraheze/puppet/blob/master/modules/mariadb/templates/config/mw.cnf.erb

This one is hard to reproduce and debug for me, so help would be really appreciated ;) Let me know if you need more information.