Nextcloud constantly accessing mariadb, log is blowing up

Bonecracker · September 3, 2020, 9:59am

Support intro

Sorry to hear you’re facing problems

In order to help you as quickly as possible, before clicking Create Topic please provide as much of the below as you can. Feel free to use a pastebin service for logs, otherwise either indent short log examples with four spaces:

example

Or for longer, use three backticks above and below the code snippet:

longer
example
here

Some or all of the below information will be requested if it isn’t supplied; for fastest response please provide as much as you can

Nextcloud version (eg, 18.0.2): 19.02
Operating system and version (eg, Ubuntu 20.04): Debian 10
Apache or nginx version (eg, Apache 2.4.25): nginx 1.14.2
PHP version (eg, 7.1): 7.3.19

The issue you are facing:

Nextcloud is accessing its database (mariadb) nearly all the time, thus preventing the HDD from spindown. In order to try and fix it i turned on general logging in mariadb (nextcloud is the only one using it), and now, 8 hours later i am nearly at 300mb with my log file, only consisting of nextcloud querys. I will paste some recurring querys at the bottom.

Is this the first time you’ve seen this error? (Y/N):

Steps to replicate it:

Just using Nextcloud

The output of your Nextcloud log in Admin > Logging:

Doctrine\DBAL\Exception\LockWaitTimeoutException: An exception occurred while executing 'DELETE FROM `oc_file_locks` WHERE `ttl` < ?' with params [1599122416]: SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

The output of your config.php file in /path/to/nextcloud (make sure you remove any identifiable information!):

<?php
$CONFIG = array (
  'memcache.local' => '\\OC\\Memcache\\APCu',
  'datadirectory' => '/data',
  'trusted_proxies' => 
  array (
    0 => 'letsencrypt',
  ),
  'overwritewebroot' => '/nextcloud',
  'overwrite.cli.url' => 'https://mydomain.org/nextcloud',
  'trusted_domains' => 
  array (
    0 => 'mydomain.org',
  ),
  'instanceid' => '12345',
  'passwordsalt' => '12345',
  'secret' => '12345',
  'dbtype' => 'mysql',
  'version' => '19.0.2.2',
  'dbname' => 'nextcloud',
  'dbhost' => 'nextclouddb',
  'dbport' => '',
  'dbtableprefix' => 'oc_',
  'mysql.utf8mb4' => true,
  'dbuser' => 'oc_admin',
  'dbpassword' => '12345',
  'installed' => true,
  'updater.secret' => '12345',
  'maintenance' => false,
  'loglevel' => 2,
);

The output of your Apache/nginx/system log in /var/log/____:

::ffff:127.0.0.1 - - [03/Sep/2020:07:52:46 -0200] "GET / HTTP/1.1" 200 3419 "-" "Monit/5.26.0"
::ffff:127.0.0.1 - - [03/Sep/2020:07:53:16 -0200] "GET / HTTP/1.1" 200 3419 "-" "Monit/5.26.0"
::ffff:127.0.0.1 - - [03/Sep/2020:07:53:46 -0200] "GET / HTTP/1.1" 200 3419 "-" "Monit/5.26.0"
::ffff:127.0.0.1 - - [03/Sep/2020:07:54:16 -0200] "GET / HTTP/1.1" 200 3419 "-" "Monit/5.26.0"
::ffff:127.0.0.1 - - [03/Sep/2020:07:54:46 -0200] "GET / HTTP/1.1" 200 3419 "-" "Monit/5.26.0"

some output of mysql.log (the first one is happening sometimes every second)

200903  1:30:01	   198 Query	DELETE FROM `oc_appconfig` WHERE (`appid` = 'core') AND (`configkey` = 'cronErrors')
		   198 Query	SELECT DISTINCT `class`, `entity`, `events` FROM `oc_flow_operations` WHERE `events` <> '[]'
		   198 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599046201) AND (`last_checked` <= 1599089401) ORDER BY `last_checked` ASC LIMIT 1
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599089401', `last_checked` = '1599089401' WHERE (`id` = '8') AND (`reserved_at` = '0') AND (`last_checked` = '1599089101')
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 8
		   198 Query	UPDATE `oc_appconfig` SET `configvalue` = '8' WHERE (`appid` = 'backgroundjob') AND (`configkey` = 'lastjob') AND (`configvalue` <> '8')
		   198 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599046201) AND (`last_checked` <= 1599089401) ORDER BY `last_checked` ASC LIMIT 1
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599089401', `last_checked` = '1599089401' WHERE (`id` = '9') AND (`reserved_at` = '0') AND (`last_checked` = '1599089101')
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 9
		   198 Query	UPDATE `oc_appconfig` SET `configvalue` = '9' WHERE (`appid` = 'backgroundjob') AND (`configkey` = 'lastjob') AND (`configvalue` <> '9')
		   198 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599046201) AND (`last_checked` <= 1599089401) ORDER BY `last_checked` ASC LIMIT 1
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599089401', `last_checked` = '1599089401' WHERE (`id` = '15') AND (`reserved_at` = '0') AND (`last_checked` = '1599089101')
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 15
		   198 Query	UPDATE `oc_appconfig` SET `configvalue` = '15' WHERE (`appid` = 'backgroundjob') AND (`configkey` = 'lastjob') AND (`configvalue` <> '15')
		   198 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599046201) AND (`last_checked` <= 1599089401) ORDER BY `last_checked` ASC LIMIT 1
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599089401', `last_checked` = '1599089401' WHERE (`id` = '16') AND (`reserved_at` = '0') AND (`last_checked` = '1599089101')
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 16
		   198 Query	UPDATE `oc_appconfig` SET `configvalue` = '16' WHERE (`appid` = 'backgroundjob') AND (`configkey` = 'lastjob') AND (`configvalue` <> '16')
		   198 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599046201) AND (`last_checked` <= 1599089401) ORDER BY `last_checked` ASC LIMIT 1
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599089401', `last_checked` = '1599089401' WHERE (`id` = '17') AND (`reserved_at` = '0') AND (`last_checked` = '1599089101')
		   198 Query	UPDATE `oc_jobs` SET `last_run` = 1599089401 WHERE `id` = 17
		   198 Query	SELECT COUNT(`uid`) FROM `oc_users`
		   198 Query	SELECT `userid` FROM `oc_preferences` WHERE `appid` = 'core' AND `configkey` = 'enabled' AND `configvalue` = 'false'
		   198 Query	SELECT COUNT(*) FROM `oc_preferences` WHERE (`appid` = 'login') AND (`configkey` = 'lastLogin') AND (`configvalue` IS NOT NULL)
		   198 Query	UPDATE `oc_jobs` SET `execution_duration` = 0 WHERE `id` = 17
		   198 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 17

and thousands of querys like this:

		   254 Query	SELECT * FROM `oc_jobs` WHERE (`reserved_at` <= 1599063003) AND (`last_checked` <= 1599106203) ORDER BY `last_checked` ASC LIMIT 1
		   254 Query	UPDATE `oc_jobs` SET `reserved_at` = '1599106203', `last_checked` = '1599106203' WHERE (`id` = '18') AND (`reserved_at` = '0') AND (`last_checked` = '1599105903')
		   254 Query	UPDATE `oc_jobs` SET `reserved_at` = '0' WHERE `id` = 18

Maybe someone is able to help me, or tell me where i’m wrong. Thank you!

ChristophWurst · September 3, 2020, 10:40am

Yes, Nextcloud requires a database for almost all operations. This is expected.

If you’re using webcron I would suggest switching to system cron that is run every 5min: https://docs.nextcloud.com/server/stable/developer_manual/app/backgroundjobs.html

Bonecracker · September 3, 2020, 10:43am

Thank you for your answer, but i am quite sure, that this wasn’t the case with my last installation.

ChristophWurst · September 3, 2020, 10:55am

Look into https://docs.nextcloud.com/server/19/admin_manual/configuration_server/caching_configuration.html. You don’t seem to have any caching configured. This makes a huge difference.

Bonecracker · September 3, 2020, 10:59am

Thank you for the input, i’ll look into it!

Edit: As for now: enabling APCu seems to help, thank you!

Edit2: I’ve been to fast… It still hits the database up pretty often. And this is without accessing Nextcloud in any way…

MeiRos · September 4, 2020, 2:55pm

What is this?

'trusted_proxies' => 
  array (
    0 => 'letsencrypt',
  ),

It should be something like this if you use a proxy.

'trusted_proxies' => ['203.0.113.45', '198.51.100.128', '192.168.2.0/24'],

Bonecracker · September 4, 2020, 6:38pm

Letsencrypt is the reverse proxy to access my nextcloud.

MeiRos · September 5, 2020, 4:19pm

I just haven’t seen it with array ( 0 =>…) part…
If it works like that, then it’s ok.

Bonecracker · September 6, 2020, 8:44pm

So the log now is at nearly 5gb of size… Still the same messages as above.

MeiRos · September 6, 2020, 9:43pm

I think I would open my.cnf and edit/add this.

[mysqld]
innodb_lock_wait_timeout=90

Bonecracker · September 7, 2020, 7:31pm

I already have a timeout in place:
wait_timeout = 600

I now just put the DB on my ssd, but i have a constant r/w of about 10-20 mb/s which will kill my ssd in the near future i fear…

MeiRos · September 7, 2020, 10:33pm

Maybe you need to manually remove file locks? If it’s the reason…?

tflidd · September 9, 2020, 10:05am

check out database caching, this makes a huge difference since many things are kept in RAM. You need to log all queries, this also creates a lot i/o operations.

Bonecracker · September 16, 2020, 10:24am

i activated ‘memcache.local’ => ‘\OC\Memcache\APCu’, in my config.php… and stopped the binlog in mariadb… still heavy r/w…

if i monitor my r/w usin iotop, i get:

mysqld --basedir=/usr --datadir=/config/databases --plugin-dir=/usr/lib/mysql/plugin --skip-log-error --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306