MySQL 1213 Deadlock when creating a lot of directories in parallel #18918

individual-it · 2015-09-09T06:36:13Z

Steps to reproduce

create a lot of directories in parallel. e.g with pyocclient http://github.com/owncloud/pyocclient/

import owncloud
import multiprocessing
import sys

multiOc=[]
users=[{'login':'test1','password':'test1'},{'login':'test2','password':'test2'},{'login':'test3','password':'test3'},{'login':'test4','password':'test4'}]

for user in users:
    oc=owncloud.Client('http://localhost/owncloud-core/')
    oc.login(user['login'],user['password'])
    multiOc.append(oc)

for oc in multiOc:
    try:
        oc.delete('owncloudtest')
    except Exception:
        pass
    oc.mkdir('owncloudtest')

jobs = []

for i in xrange(100):
    for oc in multiOc:
        p = multiprocessing.Process(target=oc.mkdir, args=('owncloudtest/' + str(i),))
        p.start()
        jobs.append(p)

    for j in jobs:
        j.join()
        sys.stdout.write(".")
        sys.stdout.flush()

Expected behaviour

directories are created and "HTTP 201" code is returned on every request

Actual behaviour

After a while some requests get "HTTP 500" error returned

<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>Doctrine\DBAL\Exception\DriverException</s:exception>
  <s:message>An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` &gt;= 0' with params ["files\/b8f3fe72dfbddfc28eda340f56721d26"]:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction</s:message>
</d:error>

Server configuration

Operating system:
Linux deepthought2 4.0.0-2-amd64 #1 SMP Debian 4.0.4-1tanglu2 (2015-05-31) x86_64 GNU/Linux
Web server:
Apache/2.4.10
Database:
MySQL 5.5.44-0
PHP version:
PHP Version 5.6.12-0+deb8u1~tanglu3.1

ownCloud version: (see ownCloud admin page)
ownCloud 8.2 pre alpha (git)
Updated from an older ownCloud or fresh install:
updated
List of acti40.0.3vated apps:

Enabled:
  - files: 1.1.11
  - files_sharing: 0.6.3
  - files_versions: 1.0.6
  - provisioning_api: 0.2
Disabled:
  - encryption
  - files_external
  - files_trashbin
  - user_ldap
  - user_webdavauth

The content of config/config.php:

{
    "system": {
        "instanceid": "ocv62j2zwgab",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "localhost"
        ],
        "datadirectory": "\/home\/www\/owncloud-core\/data",
        "overwrite.cli.url": "http:\/\/localhost\/owncloud-core",
        "dbtype": "mysql",
        "version": "8.2.0.4",
        "dbname": "owncloud",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "UTC",
        "installed": true,
        "theme": "",
        "maintenance": false,
        "singleUser": true
    }
}

Are you using external storage, if yes which one: local/smb/sftp/...
no
Are you using encryption: yes/no
no
Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/...
no

Client configuration

Browser:
Firefox 40.0.3
Operating system:
Linux deepthought2 4.0.0-2-amd64 #1 SMP Debian 4.0.4-1tanglu2 (2015-05-31) x86_64 GNU/Linux

Logs

Wireshark dump

https://inf.blaucloud.de/index.php/s/GJkE0VDy8hHvq8n
password: wireshark

Web server error log

nothing

ownCloud log (data/owncloud.log)

{"reqId":"pdN3YMJAMNv6rUOP\/JAp","remoteAddr":"::1","app":"webdav","message":"Exception: {\"Message\":\"An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` >= 0' with params [\\\"files\\\\\\\/b8f3fe72dfbddfc28eda340f56721d26\\\"]:\\n\\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction\",\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Code\":0,\"Trace\":\"#0 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(116): Doctrine\\\\DBAL\\\\Driver\\\\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n#1 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Connection.php(996): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOMySql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'UPDATE `oc_file...', Array)\\n#2 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/db\\\/connection.php(203): Doctrine\\\\DBAL\\\\Connection->executeUpdate('UPDATE `oc_file...', Array, Array)\\n#3 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/lock\\\/dblockingprovider.php(89): OC\\\\DB\\\\Connection->executeUpdate('UPDATE `*PREFIX...', Array)\\n#4 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/storage\\\/common.php(638): OC\\\\Lock\\\\DBLockingProvider->acquireLock('files\\\/b8f3fe72d...', 1)\\n#5 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(571): OC\\\\Files\\\\Storage\\\\Common->acquireLock('files\\\/owncloudt...', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#6 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(571): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('files\\\/owncloudt...', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#7 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/view.php(1763): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->acquireLock('files\\\/owncloudt...', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#8 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/view.php(1858): OC\\\\Files\\\\View->lockPath('owncloudtest', 1, false)\\n#9 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/files\\\/view.php(1174): OC\\\\Files\\\\View->lockFile('owncloudtest', 1)\\n#10 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/lib\\\/private\\\/connector\\\/sabre\\\/objecttree.php(148): OC\\\\Files\\\\View->getFileInfo('owncloudtest')\\n#11 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1134): OC\\\\Connector\\\\Sabre\\\\ObjectTree->getNodeForPath('owncloudtest')\\n#12 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(583): Sabre\\\\DAV\\\\Server->createCollection('owncloudtest\\\/7', Array, Array)\\n#13 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpMkcol(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#14 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#15 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(469): Sabre\\\\Event\\\\EventEmitter->emit('method:MKCOL', Array)\\n#16 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#17 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/apps\\\/files\\\/appinfo\\\/remote.php(55): Sabre\\\\DAV\\\\Server->exec()\\n#18 \\\/home\\\/artur\\\/www\\\/owncloud-core\\\/remote.php(137): require_once('\\\/home\\\/artur\\\/www...')\\n#19 {main}\",\"File\":\"\\\/home\\\/artur\\\/www\\\/owncloud-core\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractMySQLDriver.php\",\"Line\":115}","level":4,"time":"2015-09-09T04:59:27+00:00"}

pyocclient output

Traceback (most recent call last):
  File "/usr/lib/python2.7/multiprocessing/process.py", line 258, in _bootstrap
    self.run()
  File "/usr/lib/python2.7/multiprocessing/process.py", line 114, in run
    self._target(*self._args, **self._kwargs)
  File "build/bdist.linux-x86_64/egg/owncloud/owncloud.py", line 501, in mkdir
    return self.__make_dav_request('MKCOL', path)
  File "build/bdist.linux-x86_64/egg/owncloud/owncloud.py", line 1451, in __make_dav_request
    raise HTTPResponseError(res)
HTTPResponseError: HTTP error: 500

The text was updated successfully, but these errors were encountered:

karlitschek · 2015-09-09T11:48:33Z

@icewind1991 idea idea? is this expected?

individual-it · 2015-09-09T13:37:36Z

happens also with the desktop sync client when copying folders with a lot of small files within a synced folder

09-09 17:06:20:925 0x24f2de0 void OCC::SyncJournalDb::commitInternal(const QString&, bool) Transaction commit  "upload file start" and starting new transaction 
09-09 17:06:20:925 0x24f2de0 void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "owncloudtest/00 (noch eine Kopie)/02.txt" INSTRUCTION_NEW 4 "" 
09-09 17:06:20:925 0x24f2de0 SocketApi:  Sending message:  "STATUS:OK:/home/artur/OwnCloud/test4@localhost/owncloudtest/00 (noch eine Kopie)/02.txt" 
09-09 17:06:20:928 0x24f2de0 !!! OCC::PUTFileJob created for "http://localhost/owncloud-core" + "/owncloudtest/00 (noch eine Kopie)/05.txt" 
09-09 17:06:20:928 0x24f2de0 void OCC::AbstractNetworkJob::slotFinished() 299 "Error downloading http://localhost/owncloud-core/remote.php/webdav/owncloudtest/00%20(noch%20eine%20Kopie)/03.txt - server replied: Internal Server Error" QVariant(int, 500) 
09-09 17:06:20:928 0x24f2de0 void OCC::PropagateUploadFileQNAM::slotPutFinished()  QUrl( "http://localhost/owncloud-core/remote.php/webdav/owncloudtest/00 (noch eine Kopie)/03.txt" )  FINISHED WITH STATUS 299 "Error downloading http://localhost/owncloud-core/remote.php/webdav/owncloudtest/00%20(noch%20eine%20Kopie)/03.txt - server replied: Internal Server Error" QVariant(int, 500) QVariant(QString, "Internal Server Error") 
09-09 17:06:20:928 0x24f2de0 "<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>Doctrine\DBAL\Exception\DriverException</s:exception>
  <s:message>An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` &gt;= 0' with params ["files\/d6ff094377e6f692c2a118642f11dffb"]:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction</s:message>
</d:error>
" 
09-09 17:06:20:929 0x24f2de0 blacklisting  "owncloudtest/00 (noch eine Kopie)/03.txt"  for  25 , retry count  1 
09-09 17:06:20:929 0x24f2de0 set blacklist entry for  "owncloudtest/00 (noch eine Kopie)/03.txt" 1 "Error downloading http://localhost/owncloud-core/remote.php/webdav/owncloudtest/00%20(noch%20eine%20Kopie)/03.txt - server replied: Internal Server Error (An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` >= 0' with params ["files\/d6ff094377e6f692c2a118642f11dffb"]:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction)" 1441797680 25 1391527099 "" 
09-09 17:06:20:929 0x24f2de0 void OCC::SyncEngine::slotItemCompleted(const OCC::SyncFileItem&, const OCC::PropagatorJob&) "owncloudtest/00 (noch eine Kopie)/03.txt" INSTRUCTION_NEW 2 "Error downloading http://localhost/owncloud-core/remote.php/webdav/owncloudtest/00%20(noch%20eine%20Kopie)/03.txt - server replied: Internal Server Error (An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` >= 0' with params ["files\/d6ff094377e6f692c2a118642f11dffb"]:

SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction)" 
09-09 17:06:20:929 0x24f2de0 SocketApi:  Sending message:  "STATUS:ERROR:/home/artur/OwnCloud/test4@localhost/owncloudtest/00 (noch eine Kopie)/03.txt"

I run into that problem when doing my performance tests for PR #18753
Something must have happened after commit 73b43db because with a fork that has that commit as the latest one the problem does not happen

individual-it · 2015-09-11T05:28:08Z

I'm trying to understand how the file locking is supposed to work.
Where can I find documentation about the file locks?

individual-it · 2015-09-11T08:10:40Z

That Exception is thrown in dblockingprovider.php https://github.com/owncloud/core/blob/master/lib/private/lock/dblockingprovider.php#L87
Because of the transaction a part of the lock table is blocked. Actually because of AND lock >= 0 I guess a big part of the table might be blocked and not only that single key.

so either we have to do without the transaction (why do we actually need?) it or we have to catch the Exception. E.g. a LockedException could be thrown, so the file where the lock could not be updated would be also regarded as locked.

        $this->connection->beginTransaction();
        try {
            $this->initLockField ( $path );
            if ($type === self::LOCK_SHARED) {
                $result = $this->connection->executeUpdate ( 'UPDATE `*PREFIX*file_locks` SET `lock` = `lock` + 1 WHERE `key` = ? AND `lock` >= 0', [ 
                        $path 
                ] );
            } else {
                $result = $this->connection->executeUpdate ( 'UPDATE `*PREFIX*file_locks` SET `lock` = -1 WHERE `key` = ? AND `lock` = 0', [ 
                        $path 
                ] );
            }
            $this->connection->commit ();
            if ($result !== 1) {
                throw new LockedException ( $path );
            }
        } catch ( \Exception $e ) {
            $this->logger->warning("catched exception " . $e);
            throw new LockedException ( $path );
        }

icewind1991 · 2015-09-14T14:26:53Z

or we have to catch the Exception

That seems like the best approach (we need the transaction to prevent some race conditions)
Could you make a PR for it (the above code should be fine)?

individual-it · 2015-09-14T16:03:55Z

Could the race conditions not happen also in changeLog() or releaseLog() ? If so we would need to have transactions there too and finally shouldn't there be consequently also a roll back?

icewind1991 · 2015-09-15T12:02:30Z

No, acquireLock needs one since it does 2 db operations, making sure the entry exists and setting the lock

PVince81 · 2015-09-17T09:18:09Z

So would #19098 fix this ?

individual-it · 2015-09-17T10:12:13Z

Yes with the disadvantages discussed there. Could close this as soon as its decided how exactly the lock will be implemented and the PR merged

karlitschek added the bug - not reproducible label Sep 9, 2015

karlitschek added Type:Bug and removed bug - not reproducible labels Sep 9, 2015

individual-it mentioned this issue Sep 14, 2015

reduce amount of db calls needed for file-locks #18993

Closed

individual-it mentioned this issue Sep 15, 2015

[db-locking] warnings about lock aquisition within transaction #18584

Closed

individual-it mentioned this issue Sep 17, 2015

Remove the need for the transaction in the database locking backend #19098

Merged

individual-it closed this as completed Oct 2, 2015

lock bot locked as resolved and limited conversation to collaborators Aug 9, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MySQL 1213 Deadlock when creating a lot of directories in parallel #18918

MySQL 1213 Deadlock when creating a lot of directories in parallel #18918

individual-it commented Sep 9, 2015

karlitschek commented Sep 9, 2015

individual-it commented Sep 9, 2015

individual-it commented Sep 11, 2015

individual-it commented Sep 11, 2015

icewind1991 commented Sep 14, 2015

individual-it commented Sep 14, 2015

icewind1991 commented Sep 15, 2015

PVince81 commented Sep 17, 2015

individual-it commented Sep 17, 2015

MySQL 1213 Deadlock when creating a lot of directories in parallel #18918

MySQL 1213 Deadlock when creating a lot of directories in parallel #18918

Comments

individual-it commented Sep 9, 2015

Steps to reproduce

Expected behaviour

Actual behaviour

Server configuration

Client configuration

Logs

Wireshark dump

Web server error log

ownCloud log (data/owncloud.log)

pyocclient output

karlitschek commented Sep 9, 2015

individual-it commented Sep 9, 2015

individual-it commented Sep 11, 2015

individual-it commented Sep 11, 2015

icewind1991 commented Sep 14, 2015

individual-it commented Sep 14, 2015

icewind1991 commented Sep 15, 2015

PVince81 commented Sep 17, 2015

individual-it commented Sep 17, 2015