Details
-
Bug
-
Resolution: Done
-
High
-
5.4.6
-
None
-
None
Description
In the system there are following entries in the database:
[ Mai 23 2016 12:13:32 ] [127.0.0.1] eZDFSFileHandlerMySQLiBackend::_startCacheGeneration: Unexpected error #1213 when trying to start cache generation on var/cache/user-info/1/0/user-data-10.cache.php (Deadlock found when trying to get lock; try restarting transaction)
This is hard to reproduce as it occurs in production environments, but it is believed to be caused by two files being generated at a single point in time by different servers. In the example user-info is represented, but occurrence is not limited to it. It is simply the case that most often surfaces due to frequent access.
You can able to reproduce a similar scenario on the database with just the queries from the log file where two separate front end servers (192.168.255.23 and 192.168.255.21) are rows to the cache at the exact same time (according to mtime). For the test case I have two MySQL consoles to simulate the servers.
In the first one I start a transaction and begin the insert, but do NOT commit it yet:
MariaDB [foobar]> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) MariaDB [foobar]> INSERT INTO ezdfsfile_cache ( name, name_trunk, name_hash, scope, datatype, mtime, expired ) VALUES('var/cache/user-info/1/0/user-data-10.cache.php.generating', 'var/cache/user-info/1/0/user-data-10.cache.php.generating', MD5('var/cache/user-info/1/0/user-data-10.cache.php.generating'), '', '', 1466062010, 0); Query OK, 1 row affected (0.00 sec) MariaDB [foobar]>
In the other console I start a similar transaction, which results in a failed transaction, similar
MariaDB [foobar]> START TRANSACTION; Query OK, 0 rows affected (0.00 sec) MariaDB [foobar]> INSERT INTO ezdfsfile_cache ( name, name_trunk, name_hash, scope, datatype, mtime, expired ) VALUES('var/cache/user-info/1/0/user-data-10.cache.php.generating', 'var/cache/user-info/1/0/user-data-10.cache.php.generating', MD5('var/cache/user-info/1/0/user-data-10.cache.php.generating'), '', '', 1466062010, 0); ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction MariaDB [foobar]>
The innodb log file snippet in question is this:
------------------------ LATEST DETECTED DEADLOCK ------------------------ 160616 9:26:50 *** (1) TRANSACTION: TRANSACTION 37966469, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 LOCK WAIT 3 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 26393657, OS thread handle 0x7f5bb0161700, query id 2320819111 192.168.255.23 admin update INSERT INTO ezdfsfile_cache ( name, name_trunk, name_hash, scope, datatype, mtime, expired ) VALUES('var/cache/user-info/1/0/user-data-10.cache.php.generating', 'var/cache/user-info/1/0/user-data-10.cache.php.generating', MD5('var/cache/user-info/1/0/user-data-10.cache.php.generating'), '', '', 1466062010, 0) *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 6223 page no 22340 n bits 136 index `PRIMARY` of table `cluster_live_db`.`ezdfsfile_cache` trx id 37966469 lock_mode X locks rec but not gap waiting *** (2) TRANSACTION: TRANSACTION 37966442, ACTIVE 0 sec inserting mysql tables in use 1, locked 1 3 lock struct(s), heap size 1248, 2 row lock(s) MySQL thread id 26393656, OS thread handle 0x7f5bb0224700, query id 2320819042 192.168.255.21 admin update INSERT INTO ezdfsfile_cache ( name, name_trunk, name_hash, scope, datatype, mtime, expired ) VALUES('var/cache/user-info/1/0/user-data-10.cache.php.generating', 'var/cache/user-info/1/0/user-data-10.cache.php.generating', MD5('var/cache/user-info/1/0/user-data-10.cache.php.generating'), '', '', 1466062010, 0) *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 6223 page no 22340 n bits 136 index `PRIMARY` of table `cluster_live_db`.`ezdfsfile_cache` trx id 37966442 lock mode S locks rec but not gap *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 6223 page no 22340 n bits 136 index `PRIMARY` of table `cluster_live_db`.`ezdfsfile_cache` trx id 37966442 lock_mode X locks rec but not gap waiting *** WE ROLL BACK TRANSACTION (2)
