Single query repeated dozens of times causes high CPU usage

ℹ️ Support
#1

Nextcloud version: 13.0.4
Operating system and version: Debian 9.4
Apache or nginx version: 2.4.25
PHP version: 7.0.24

Hello everyone,

I just noticed that my NC installation causes high CPU usage on my server:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
36280 www-data  20   0  931664  72136  48160 R  92,7  1,2  37:14.74 apache2
37791 www-data  20   0  904284  75260  48004 R  91,4  1,2  34:21.40 apache2
36278 www-data  20   0 1200964  80960  51084 S  88,4  1,3  21:00.76 apache2
38132 www-data  20   0  824428  68912  45268 R  87,7  1,1  21:53.29 apache2
  560 mysql     20   0 2171032 272324  15776 S  35,4  4,5  54:26.50 mysqld

Besides some GET-Requests to /ocs/v2.php/apps/notifications/api/v2/notifications no requests were made for the last ~20 minutes.
The last entry in NC-Log is from last night:

Jul 26 00:23:17 nextcloud ownCloud[31811]: {index} Exception: {"Exception":"OCP\\Lock\\LockedException","Message":"\" *** FILE PATH ***\" is locked","Code":0,"Trace":"#0 \/var\/www\/nextcloud\/lib\/private\/Files\/View.php(2038): OC\\Files\\View->lockPath('\/files\/**...', 1)
#1 \/var\/www\/nextcloud\/lib\/private\/Files\/View.php(1134): OC\\Files\\View->lockFile('\/files\/**...', 1)
#2 \/var\/www\/nextcloud\/lib\/private\/Files\/View.php(987): OC\\Files\\View->basicOperation('fopen', '\/files\/**...', Array, 'r')
#3 \/var\/www\/nextcloud\/lib\/private\/Files\/View.php(998): OC\\Files\\View->fopen('\/files\/**...', 'r')
#4 \/var\/www\/nextcloud\/lib\/private\/Preview\/Bitmap.php(42): OC\\Files\\View->toTmpFile('\/files\/**...')
#5 \/var\/www\/nextcloud\/lib\/private\/Preview\/GeneratorHelper.php(54): OC\\Preview\\Bitmap->getThumbnail('\/files\/**...', 512, 512, false, Object(OC\\Files\\View))
#6 \/var\/www\/nextcloud\/lib\/private\/Preview\/Generator.php(190): OC\\Preview\\GeneratorHelper->getThumbnail(Object(OC\\Preview\\PDF), Object(OC\\Files\ode\\File), 512, 512)
#7 \/var\/www\/nextcloud\/lib\/private\/Preview\/Generator.php(118): OC\\Preview\\Generator->getMaxPreview(Object(OC\\Files\\SimpleFS\\SimpleFolder), Object(OC\\Files\ode\\File), 'application\/pdf')
#8 \/var\/www\/nextcloud\/lib\/private\/PreviewManager.php(202): OC\\Preview\\Generator->getPreview(Object(OC\\Files\ode\\File), 64, 64, true, 'fill', 'application\/pdf')
#9 \/var\/www\/nextcloud\/core\/Controller\/PreviewController.php(114): OC\\PreviewManager->getPreview(Object(OC\\Files\ode\\File), 64, 64, true, 'fill')
#10 [internal function]: OC\\Core\\Controller\\PreviewController->getPreview(Object(OC\\Files\ode\\File), 64, 64, false, false, 'fill')
#11 \/var\/www\/nextcloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php(161): call_user_func_array(Array, Array)
#12 \/var\/www\/nextcloud\/lib\/private\/AppFramework\/Http\/Dispatcher.php(91): OC\\AppFramework\\Http\\Dispatcher->executeController(Object(OC\\Core\\Controller\\PreviewController), 'getPreview')
#13 \/var\/www\/nextcloud\/lib\/private\/AppFramework\/App.php(115): OC\\AppFramework\\Http\\Dispatcher->dispatch(Object(OC\\Core\\Controller\\PreviewController), 'getPreview')
#14 \/var\/www\/nextcloud\/lib\/private\/AppFramework\/Routing\/RouteActionHandler.php(47): OC\\AppFramework\\App::main('OC\\\\Core\\\\Control...', 'getPreview', Object(OC\\AppFramework\\DependencyInjection\\DIContainer), Array)
#15 [internal function]: OC\\AppFramework\\Routing\\RouteActionHandler->__invoke(Array)
#16 \/var\/www\/nextcloud\/lib\/private\/Route\/Router.php(297): call_user_func(Object(OC\\AppFramework\\Routing\\RouteActionHandler), Array)
#17 \/var\/www\/nextcloud\/lib\/base.php(999): OC\\Route\\Router->match('\/core\/preview.p...')
#18 \/var\/www\/nextcloud\/index.php(42): OC::handleRequest()
#19 {main}","File":"\/var\/www\/nextcloud\/lib\/private\/Files\/View.php","Line":1929}

I don’t think this is related?!

I then turned on global log of mysql and got a 35M file in about 2 minutes with the following query logged permanently:

SELECT `fileid`, `storage`, `path`, `path_hash`, `parent`, `name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `permissions`, `checksum`
FROM `oc_filecache` 
WHERE `storage` = '1' AND `path_hash` = 'd41d8cd98f00b204e9800998ecf8427e';

Result:

+--------+---------+------+----------------------------------+--------+------+----------+----------+------------+------------+---------------+-----------+---------------+-------------+----------+
| fileid | storage | path | path_hash                        | parent | name | mimetype | mimepart | size       | mtime      | storage_mtime | encrypted | etag          | permissions | checksum |
+--------+---------+------+----------------------------------+--------+------+----------+----------+------------+------------+---------------+-----------+---------------+-------------+----------+
|      1 |       1 |      | d41d8cd98f00b204e9800998ecf8427e |     -1 |      |        2 |        1 | 2362406802 | 1532618566 |    1531163093 |         0 | 5b59e74605703 |          23 |          |
+--------+---------+------+----------------------------------+--------+------+----------+----------+------------+------------+---------------+-----------+---------------+-------------+----------+

My config looks like this:

'instanceid' => '',
'passwordsalt' => '',
'secret' => '',
'trusted_domains' =>
array (
    0 => '',
),
'trusted_proxies' =>
array (
    0 => '172.30.150.100',
),
'datadirectory' => '/var/nextcloud/data',
'overwrite.cli.url' => 'http://172.31.2.65/nextcloud',
'dbtype' => 'mysql',
'version' => '13.0.4.0',
'dbname' => 'nextcloud',
'dbhost' => 'localhost',
'dbport' => '',
'dbtableprefix' => 'oc_',
'mysql.utf8mb4' => true,
'dbuser' => 'oc_Admin',
'dbpassword' => '',
'installed' => true,
'mail_smtpmode' => 'sendmail',
'mail_smtpauthtype' => 'LOGIN',
'mail_from_address' => 'nextcloud',
'mail_domain' => '',
'mail_smtphost' => '172.31.1.9',
'mail_smtpport' => '25',
'log_type' => 'syslog',
'logtimezone' => 'Europe/Berlin',
'logfile' => '/var/nextcloud/log/nextcloud.log',
'loglevel' => 2,
'enabledPreviewProviders' =>
array (
    0 => 'OC\\Preview\\PNG',
    1 => 'OC\\Preview\\JPEG',
    2 => 'OC\\Preview\\GIF',
    3 => 'OC\\Preview\\BMP',
    4 => 'OC\\Preview\\XBitmap',
    5 => 'OC\\Preview\\MP3',
    6 => 'OC\\Preview\\TXT',
    7 => 'OC\\Preview\\MarkDown',
    8 => 'OC\\Preview\\TIFF',
    9 => 'OC\\Preview\\PDF',
),
'maintenance' => false,
'theme' => '',
'memcache.local' => '\\OC\\Memcache\\APCu',
'memcache.locking' => '\\OC\\Memcache\\Redis',
            'redis' => array(
            'host' => 'localhost',
            'port' => 6379,
),
'preview_max_x' => 512,
'preview_max_y' => 512,
'preview_max_scale_factor' => 1,
'skeletondirectory' => '',

I removed all sensitive parts.

Cronjobs are defined as the following for user www-data:

*/15  *  *  *  * php -f /var/www/nextcloud/cron.php
*/30  *  *  *  * php -f /var/www/nextcloud/occ preview:pre-generate

Any idea how to further debug this? The server is still running like this, I hesitated to restart the apache process in case we can figure out whats causing this.
The server itself is acces through a reverse proxy (nginx) in case it matters.

Thanks in advance.

#2

After reboot everything looked normal at first. After a few days I’m back to the original problem:

top - 15:03:41 up 33 days, 14:09,  1 user,  load average: 8,13, 8,22, 8,19
Tasks: 140 total,   9 running, 131 sleeping,   0 stopped,   0 zombie
%Cpu(s): 57,0 us, 43,0 sy,  0,0 ni,  0,0 id,  0,0 wa,  0,0 hi,  0,0 si,  0,0 st
KiB Mem :  6106072 total,  2198472 free,   853336 used,  3054264 buff/cache
KiB Swap:  2095100 total,  2095100 free,        0 used.  4862232 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 6172 www-data  20   0  846264  87388  49228 R  89,7  1,4   3713:48 apache2
 4373 www-data  20   0  847192  79324  45632 R  89,4  1,3   4352:28 apache2
 6189 www-data  20   0  845108  79052  43284 R  76,5  1,3   4271:41 apache2
 4682 www-data  20   0  951180  84548  49996 R  73,5  1,4   3750:22 apache2
 4369 www-data  20   0  844960  89888  45848 R  72,2  1,5   4320:49 apache2
 4375 www-data  20   0  845072  78768  45040 R  66,2  1,3   4352:16 apache2
 4698 www-data  20   0 1222980  90868  49144 R  62,6  1,5   4191:18 apache2
 4367 www-data  20   0  844792  80360  46748 R  51,3  1,3   4328:29 apache2
  560 mysql     20   0 2697400 310656  15776 S  16,6  5,1   1763:39 mysqld

Anyone got a idea how to fix this or debug this?!

Thanks!

#3

Got exactly the same issue here, but can’t figure out where it comes from.

Sometimes it works days, then only a few minutes, the end result is that the whole server is running at 100% cpu load.

And for me it’s the same file hash d41d8cd98f00b204e9800998ecf8427e which is constantly repeated

Select … FROM oc_filecache
INSERT INTO oc_file_locks …
UPDATE oc_file_locks …

repeat