Uploaded image for project: 'eZ Publish / Platform'
  1. eZ Publish / Platform
  2. EZP-25916

Clustering cache (eZDFS) can lead to database deadlocks (MySQL)

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: High High
    • Resolution: Done
    • Affects Version/s: 5.4.6
    • Fix Version/s: Customer request, 5.4.11-rc
    • Component/s: None
    • Labels:
      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)
      

        Issue Links

          Activity

          Hide
          Tomasz Madeyski (Inactive) added a comment -
          Show
          Tomasz Madeyski (Inactive) added a comment - New PR for this issue: https://github.com/ezsystems/ezpublish-legacy/pull/1301
          Show
          André Rømcke added a comment - Merged: https://github.com/ezsystems/ezpublish-legacy/commit/07ed37870a857a4fe2c36ea33c38b2d4261747af
          Hide
          Eduardo Fernandes added a comment -

          QA approved with sanity checks

          Show
          Eduardo Fernandes added a comment - QA approved with sanity checks

            People

            • Assignee:
              Unassigned
              Reporter:
              Jani Tarvainen
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: