UPDATE `oc_filecache` error

Server
1

Hi,
I have an owncloud setup and running for now 10 days and is working, on an Ubuntu server 18.04LTS runing with MySQL and Apache.

When I check at the logs, there is always the same issue repeating over and over :
I don’t think it is actually hurting the user experience (for now I havn’t) but I would have like to know why and how to solve it.

{“reqId”:“64a40c92-9e39-42fd-839b-d5b684397b10”,“level”:4,“time”:“2019-02-05T10:03:51+00:00”,“remoteAddr”:“192.168.1.154”,“user”:“5E08A3B5-F46D-4655-915B-449C6EE67BCE”,“app”:“webdav”,“method”:“PROPFIND”,“url”:"/remote.php/dav/files/5E08A3B5-F46D-4655-915B-449C6EE67BCE/Shared",“message”:“Exception: An exception occurred while executing 'UPDATE oc_filecache SET size=? WHERE (size <> ? OR size IS NULL) AND fileid = ? ’ with params [-1, -1, “625714”]:\n\nSQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction: {“Exception”:“Doctrine\\DBAL\\Exception\\DriverException”,“Message”:“An exception occurred while executing 'UPDATE oc_filecache SET size=? WHERE (size <> ? OR size IS NULL) AND fileid = ? ’ with params [-1, -1, \“625714\”]:\n\nSQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction”,“Code”:0,“Trace”:”#0 \/var\/www\/html\/lib\/composer\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/DBALException.php(128): Doctrine\\DBAL\\Driver\\AbstractMySQLDriver->convertException(‘An exception oc…’, Object(Doctrine\\DBAL\\Driver\\PDOException))\n#1 \/var\/www\/html\/lib\/composer\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php(855): Doctrine\\DBAL\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\DBAL\\Driver\\PDOMySql\\Driver), Object(Doctrine\\DBAL\\Driver\\PDOException), ‘UPDATE oc_file...', Array)\\n#2 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/DB\\\/Connection.php(187): Doctrine\\\\DBAL\\\\Connection->executeQuery('UPDATEoc_file…’, Array, Array, NULL)\n#3 \/var\/www\/html\/lib\/private\/Files\/Cache\/Cache.php(326): OC\\DB\\Connection->executeQuery(‘UPDATE `oc_file…’, Array)\n#4 \/var\/www\/html\/lib\/private\/Files\/Cache\/Scanner.php(406): OC\\Files\\Cache\\Cache->update(‘625714’, Array)\n#5 \/var\/www\/html\/lib\/private\/Files\/Cache\/Scanner.php(328): OC\\Files\\Cache\\Scanner->scanChildren(’’, false, 3, ‘625714’, true)\n#6 \/var\/www\/html\/lib\/private\/Files\/View.php(1367): OC\\Files\\Cache\\Scanner->scan(’’, false)\n#7 \/var\/www\/html\/lib\/private\/Files\/View.php(1408): OC\\Files\\View->getCacheEntry(Object(OCA\\Files_Trashbin\\Storage), ‘’, ‘Shared’)\n#8 \/var\/www\/html\/apps\/dav\/lib\/Connector\/Sabre\/ObjectTree.php(179): OC\\Files\\View->getFileInfo(’\/5E08A3B5-F46D-…’)\n#9 \/var\/www\/html\/apps\/dav\/lib\/Tree.php(67): OCA\\DAV\\Connector\\Sabre\\ObjectTree->getNodeForPath(‘Shared’)\n#10 \/var\/www\/html\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(966): OCA\\DAV\\Tree->getNodeForPath(‘files\/5E08A3B5-…’)\n#11 \/var\/www\/html\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(1665): Sabre\\DAV\\Server->getPropertiesIteratorForPath(‘files\/5E08A3B5-…’, Array, 0)\n#12 \/var\/www\/html\/lib\/composer\/sabre\/dav\/lib\/DAV\/CorePlugin.php(355): Sabre\\DAV\\Server->generateMultiStatus(Object(Generator), false)\n#13 [internal function]: Sabre\\DAV\\CorePlugin->httpPropFind(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#14 \/var\/www\/html\/lib\/composer\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#15 \/var\/www\/html\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(479): Sabre\\Event\\EventEmitter->emit(‘method:PROPFIND’, Array)\n#16 \/var\/www\/html\/lib\/composer\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#17 \/var\/www\/html\/apps\/dav\/lib\/Server.php(298): Sabre\\DAV\\Server->exec()\n#18 \/var\/www\/html\/apps\/dav\/appinfo\/v2\/remote.php(31): OCA\\DAV\\Server->exec()\n#19 \/var\/www\/html\/remote.php(165): require_once(’\/var\/www\/html\/a…’)\n#20 {main}",“File”:"\/var\/www\/html\/lib\/composer\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/AbstractMySQLDriver.php",“Line”:115}"}

Server configuration

Operating system: Ubuntu 18.04LTS

Web server: Apache 2

Database: MySQL 14.14 Distrib 5.7.25 for Linux (x86_64)

PHP version: 7.2

ownCloud version: 10.0.10.4

Updated from an older ownCloud or fresh install: Fresh install

Thanks a lot for your help!
AM.

2

It seems a problem with the DB, so you might want to check some configuration option in MySQL.

If you can reproduce the problem consistently maybe we can have a look.

3

Hi and thank you for your answer.

The thing is that I currently have 1.1MB of logs (in ~5 days) full of this error and it keeps on happening.
its seems to be related to file caching?
for file caching I am using Redis (not really sure it is related though).

Thanks a lot.
AM.

4

Yes and no. The table contains metadata about the file, but it isn’t really a cache despite of the name.
Redis isn’t related with the problem.

Maybe you can check some configuration in the DB about the lock wait timeout. Other than that, try to figure out how to reproduce the problem and try to provide steps to reproduce the issue

5

Hi,
I increased the timeout wait to 100 in mySQL, and I still see the same error message but now on other tables: oc_appconfig.

Should I keep on increasing that lock wait? it is the expected behavior?

Thanks,
AM.

6

Is there any other process that could be accessing to the data? maybe some backup or monitoring application?
Maybe the server where you run the DB isn’t powerful enough, or if you have other apps using the same DB maybe those apps are using too many resources and MySQL can’t respond quick enough

It isn’t normal, but if you can’t consistently reproduce the problem and somehow prove that ownCloud is the one causing (not suffering) the locks, I don’t think there is anything to do on ownCloud’s side.

If you still hit the lock timeout with a high number I don’t expect that increasing that number will fix the problem, it will just happen later or maybe less frequently.

7

Hi,

I do not think anything is running and could lock the tables since it is a fresh Owncloud install.
No backup of that virtual machine are currently in place since we are in trial.

The virtual machine is equipped with 4 virtual cores and 4GB of RAM and we use it very very lightly so I don’t believe it is due to computational power.

As for MySQL, I tried to have a look at the currently used table (see screenshots).
image

image
image.png1498×267 8.18 KB

I don’t really know what else to test.
Thanks a lot,
AM.

EDIT: in the last screenshot, owncloud INSERT and UPDATE at the same time, for some reason one of the two request lock the table for more than the timeout, if I understand correctly?

image
image.png1396×151 6.85 KB

8

I do think I found a solution.
It seems that MySQL on the latest Ubuntu 18.04 LTS is having speed issues.

see

I do not have the error log any more after appending:

innodb_read_io_threads=4 
innodb_write_io_threads=8 #To stress the double write buffer 
innodb_buffer_pool_size=20G # 70-80% available Memory 
innodb_buffer_pool_load_at_startup=ON 
innodb_log_file_size = 32M #Small log files, more page flush 
innodb_log_files_in_group=2 
innodb_file_per_table=1 
innodb_log_buffer_size=8M 
innodb_flush_method=O_DIRECT 
innodb_flush_log_at_trx_commit=0 
skip-innodb_doublewrite 

on mysqld.cnf

I hope that is a consistent fix!
Thanks again,
AM.
1 Like
9

Yes. It isn’t normal that just updating one record that is expected to be indexed takes more than 8 seconds. The insert seems blocked until the update finish, so I guess it would timeout at some point.

Glad you’ve found a solution!