Query on oc_filecache uses wrong index - Cron job runs very long

[JohnWalkerx]

➡️ 🚧 Possible workaround (works for me):

1. Kill all running cron.php jobs. Or just restart your machine.
2. Disable your cron job during rescan (just to be sure that it doesn't scan too).
3. Run occ files:scan-app-data on your instance to rescan the appdata folder.

How to use GitHub

• Please use the 👍 reaction to show that you are affected by the same issue.
• Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue.
• Subscribe to receive notifications on status change and new comments.

Steps to reproduce

(0. It began after I run the Preview Generator over 1553047 files (not only pictures). So a lot of previews were generated.)

1. Run cron.php every 5 or 15 minutes.

Expected behaviour

Each cron job is done before the next one is started. CPU is not very high.

Actual behaviour

After some time there are running multiple cron jobs. CPU is at 100% because of mysqld.
This is because there is a very slow query:

SELECT `path` FROM nextcloud.oc_filecache WHERE `storage` = 1 AND `size` < 0 ORDER BY `fileid` DESC

If I enable to log slow querys I get following output:

# User@Host: ncuser[ncuser] @ localhost []  Id: 21805
# Query_time: 253.154251  Lock_time: 0.000205 Rows_sent: 191412  Rows_examined: 1454739
SET timestamp=1603198875;
SELECT `path` FROM `oc_filecache` WHERE (`storage` = 1) AND (`size` < 0) ORDER BY `fileid` DESC;

If I let explain me this query I get following:

# id, select_type, table, partitions, type, possible_keys, key, key_len, ref, rows, filtered, Extra
'1', 'SIMPLE', 'oc_filecache', NULL, 'ref', 'fs_storage_path_hash,fs_storage_mimetype,fs_storage_mimepart,fs_storage_size', 'fs_storage_path_hash', '8', 'const', '788173', '33.33', 'Using where; Using filesort'

So it uses the wrong index fs_storage_path_hash.
I would expect that it uses the fs_storage_size index.

If I execute the query and force the index it looks nice:

SELECT `path` FROM nextcloud.oc_filecache FORCE INDEX (fs_storage_size) WHERE `storage` = 1 AND `size` < 0 ORDER BY `fileid` DESC
# 190921 row(s) returned	3.654 sec / 0.335 sec

Output of EXPLAIN:

# id, select_type, table, partitions, type, possible_keys, key, key_len, ref, rows, filtered, Extra
'1', 'SIMPLE', 'oc_filecache', NULL, 'range', 'fs_storage_size', 'fs_storage_size', '16', NULL, '358248', '100.00', 'Using index condition; Using filesort'

Why it doesn't use the fs_storage_size index?
On a fresh NC20 test instance it uses this index.

Server configuration detail

Operating system: Linux 5.4.0-54-generic #60-Ubuntu SMP Fri Nov 6 10:37:59 UTC 2020 x86_64 / Ubuntu 20.04.29 LTS

Webserver: Apache (apache2handler)

Database: mysql 8.0.22

PHP version:

7.3.24-3+ubuntu20.04.1+deb.sury.org+1
Modules loaded: Core, date, libxml, openssl, pcre, zlib, filter, hash, Reflection, SPL, session, sodium, standard, apache2handler, mysqlnd, PDO, xml, apcu, bcmath, calendar, ctype, curl, dom, mbstring, fileinfo, ftp, gd, gettext, gmp, iconv, igbinary, imagick, intl, json, exif, mysqli, pdo_mysql, apc, posix, readline, redis, shmop, SimpleXML, sockets, sysvmsg, sysvsem, sysvshm, tokenizer, wddx, xmlreader, xmlwriter, xsl, zip, Phar, Zend OPcache

Nextcloud version: 19.0.5 - 19.0.5.2

Updated from an older Nextcloud/ownCloud or fresh install: Updated from 19.0.4 but problem exists there also.

Where did you install Nextcloud from: unknown

Signing status

Array
(
)

List of activated apps

Enabled:
 - accessibility: 1.5.0
 - activity: 2.12.1
 - announcementcenter: 3.8.1
 - apporder: 0.11.0
 - audioplayer: 2.13.1
 - bbb: 1.1.2
 - bookmarks: 3.4.9
 - bruteforcesettings: 2.0.1
 - calendar: 2.0.4
 - cloud_federation_api: 1.2.0
 - comments: 1.9.0
 - contacts: 3.4.2
 - contactsinteraction: 1.0.0
 - cospend: 1.0.5
 - dav: 1.15.0
 - deck: 1.2.2
 - federatedfilesharing: 1.9.0
 - federation: 1.9.0
 - files: 1.14.0
 - files_markdown: 2.3.1
 - files_pdfviewer: 1.8.0
 - files_rightclick: 0.16.0
 - files_sharing: 1.11.0
 - files_trashbin: 1.9.0
 - files_versions: 1.12.0
 - files_videoplayer: 1.8.0
 - firstrunwizard: 2.8.0
 - forms: 2.0.4
 - gpxpod: 4.2.2
 - groupfolders: 7.1.1
 - impersonate: 1.6.1
 - issuetemplate: 0.7.0
 - logreader: 2.4.0
 - lookup_server_connector: 1.7.0
 - mail: 1.4.1
 - maps: 0.1.6
 - nextcloud_announcements: 1.8.0
 - notes: 3.6.4
 - notifications: 2.7.0
 - oauth2: 1.7.0
 - password_policy: 1.9.1
 - photos: 1.1.0
 - polls: 1.6.2
 - previewgenerator: 2.3.0
 - privacy: 1.3.0
 - provisioning_api: 1.9.0
 - ransomware_protection: 1.7.0
 - richdocuments: 3.7.10
 - serverinfo: 1.9.0
 - settings: 1.1.0
 - sharebymail: 1.9.0
 - spreed: 9.0.6
 - support: 1.2.1
 - survey_client: 1.7.0
 - systemtags: 1.9.0
 - tasks: 0.13.6
 - text: 3.0.1
 - theming: 1.10.0
 - twofactor_backupcodes: 1.8.0
 - twofactor_totp: 5.0.0
 - twofactor_u2f: 6.0.0
 - updatenotification: 1.9.0
 - viewer: 1.3.0
 - workflowengine: 2.1.0
Disabled:
 - admin_audit
 - encryption
 - files_external
 - onlyoffice
 - phonetrack
 - recommendations
 - sharerenamer
 - user_ldap

Configuration (config/config.php)

{
    "instanceid": "***REMOVED SENSITIVE VALUE***",
    "passwordsalt": "***REMOVED SENSITIVE VALUE***",
    "secret": "***REMOVED SENSITIVE VALUE***",
    "trusted_domains": [
        "cloud.example.de"
    ],
    "datadirectory": "***REMOVED SENSITIVE VALUE***",
    "overwrite.cli.url": "https:\/\/cloud.example.de\/",
    "htaccess.RewriteBase": "\/",
    "dbtype": "mysql",
    "version": "19.0.5.2",
    "dbname": "***REMOVED SENSITIVE VALUE***",
    "dbhost": "***REMOVED SENSITIVE VALUE***",
    "dbport": "",
    "dbtableprefix": "oc_",
    "mysql.utf8mb4": true,
    "dbuser": "***REMOVED SENSITIVE VALUE***",
    "dbpassword": "***REMOVED SENSITIVE VALUE***",
    "installed": true,
    "memcache.local": "\\OC\\Memcache\\APCu",
    "memcache.locking": "\\OC\\Memcache\\Redis",
    "filelocking.enabled": "true",
    "redis": {
        "host": "***REMOVED SENSITIVE VALUE***",
        "port": 0,
        "dbindex": 0,
        "timeout": 1.5
    },
    "logfile": "\/var\/log\/nextcloud\/nextcloud.log",
    "logtimezone": "Europe\/Berlin",
    "loglevel": 2,
    "log_rotate_size": "10485760",
    "default_language": "de",
    "default_locale": "de_DE",
    "maintenance": false,
    "mail_smtpmode": "smtp",
    "mail_smtpauthtype": "LOGIN",
    "mail_from_address": "***REMOVED SENSITIVE VALUE***",
    "mail_domain": "***REMOVED SENSITIVE VALUE***",
    "mail_smtpauth": 1,
    "mail_smtpsecure": "ssl",
    "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
    "mail_smtpport": "465",
    "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
    "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
    "trashbin_retention_obligation": "30, 90",
    "updater.release.channel": "stable",
    "app_install_overwrite": [
        "calendar"
    ],
    "preview_max_x": "2048",
    "preview_max_y": "2048",
    "jpeg_quality": "60"
}

Are you using external storage, if yes which one: No

Are you using encryption: No

Are you using an external user-backend, if yes which one: No

Client configuration

Browser: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:82.0) Gecko/20100101 Firefox/82.0

Operating system: -

Logs

There are no relevant logs

[kesselb]

cc @rullzer @nickvergessen @icewind1991

[nickvergessen]

Maybe the index is missing on your instance?

can you run:

sudo -u www-data php occ db:add-missing-indices

[JohnWalkerx]

I would say the index fs_storage_size is already there. See the possible_keys of the first "explain output" of the query.

Output of db:add-missing-indices:

Check indices of the share table.
Check indices of the filecache table.
Check indices of the twofactor_providers table.
Check indices of the login_flow_v2 table.
Check indices of the whats_new table.
Check indices of the cards table.
Check indices of the cards_properties table.
Check indices of the calendarobjects_props table.
Check indices of the schedulingobjects table.
Check indices of the oc_properties table.
Done.

I will observe if anything has changed.

[kesselb]

On 19.0.4 (updated from 16.0.0).

[JohnWalkerx]

Problem still exists.

After the query (e.g. process ID 21787) is done, query time ("Zeit") starts again. It looks like that the query is executed over and over again.

Actual two cron jobs are running. Intervall of calling is 15 minutes.

In the past after some time there are 3 cron jobs which are executing this query.

CPU graph over the last 24 hours:

[nickvergessen]

On a fresh NC20 test instance it uses this index.

Well this means our database structure and code are correct. Maybe you can run some repair/optimize commands on your database?

[JohnWalkerx]

I tried following today:

• ANALYZE TABLE nextcloud.oc_filecache
• OPTIMIZE TABLE nextcloud.oc_filecache. But for engine InnoDB this only works very limited.
• Recreated the fs_storage_size index.
• Recreated table by dump and replace it.

Nothing helps. The query optimizer still wants to use the fs_storage_path_hash index.

I'm not the only one who have this issue. There are others on the forum.

Maybe it depends on the size of the table. The table of my clean NC20 instance is very small.

Here the info of my indexes:

I also find a site in the MySQL Docs: Optimizer-Related Issues

Is it possible that we force the index in the query from nextcloud?

[nickvergessen]

Is it possible that we force the index in the query from nextcloud?

Not really as this is not supported by all databases Nextcloud supports.

Also just for the record I get different results depending on the storage. E.g. for us storage with ID 1 does not exist. Result:

MariaDB [oc]> EXPLAIN SELECT `path` FROM oc_filecache WHERE `storage` = 1 AND `size` < 0 ORDER BY `fileid` DESC;
+------+-------------+--------------+------+------------------------------------------------------------------------------+----------------------+---------+-------+------+-----------------------------+
| id   | select_type | table        | type | possible_keys                                                                | key                  | key_len | ref   | rows | Extra                       |
+------+-------------+--------------+------+------------------------------------------------------------------------------+----------------------+---------+-------+------+-----------------------------+
|    1 | SIMPLE      | oc_filecache | ref  | fs_storage_path_hash,fs_storage_mimetype,fs_storage_mimepart,fs_storage_size | fs_storage_path_hash | 8       | const |    1 | Using where; Using filesort |
+------+-------------+--------------+------+------------------------------------------------------------------------------+----------------------+---------+-------+------+-----------------------------+
1 row in set (0.001 sec)

If I change the ID to 3 it uses the correct index:

MariaDB [oc]> EXPLAIN SELECT `path` FROM oc_filecache WHERE `storage` = 3 AND `size` < 0 ORDER BY `fileid` DESC;
+------+-------------+--------------+-------+------------------------------------------------------------------------------+-----------------+---------+------+------+---------------------------------------+
| id   | select_type | table        | type  | possible_keys                                                                | key             | key_len | ref  | rows | Extra                                 |
+------+-------------+--------------+-------+------------------------------------------------------------------------------+-----------------+---------+------+------+---------------------------------------+
|    1 | SIMPLE      | oc_filecache | range | fs_storage_path_hash,fs_storage_mimetype,fs_storage_mimepart,fs_storage_size | fs_storage_size | 16      | NULL |   52 | Using index condition; Using filesort |
+------+-------------+--------------+-------+------------------------------------------------------------------------------+-----------------+---------+------+------+---------------------------------------+
1 row in set (0.001 sec)

[JohnWalkerx]

On my instance storage with ID 1 is the normal data directory.

I looked a little bit at the processes/queries which mysqld is running.
And I'm wondering that the same process is running the same query again and again.
Why does Nextcloud do this query multiple times?

While I'm typing this comment, two cron jobs are running and each job queried it at least 3 times.
EDIT: After 10 hours still the same two cron jobs processes. A third cron job also joined with the same query.

[feutl]

I want to jump onto this bandwagon ;) Even though I am not sure if it is the same problem, but at least for people searching, they should get linked through the different articles and sites. Therefor linking at least the Nextcloud Forum post I started and used to link some additional threads and sites as reference
https://help.nextcloud.com/t/background-job-scanfiles-triggered-via-cron-php-breaks-my-system/95971

I fixed my problem (for now) by cleaning up my photo previews on disk and in the database.

Besides this, why "scan files" is done twice a day is still unclear, I thought this would not be necessary if everything is pushed via the standard API / Interfaces.

[JohnWalkerx]

Does anyone know what is done with this query?

I searched a little bit deeper and had a look at the output of this query.
And I get 179465 rows with this kind of data (sorted by column path):

'appdata_myinstanceid'
'appdata_myinstanceid/preview'
'appdata_myinstanceid/preview/0'
'appdata_myinstanceid/preview/0/0'
'appdata_myinstanceid/preview/0/0/0/0/a'
'appdata_myinstanceid/preview/0/0/0/0/a/0'
'appdata_myinstanceid/preview/0/0/0/0/a/0/f'
'appdata_myinstanceid/preview/0/0/0/2'
'appdata_myinstanceid/preview/0/0/0/2/7'
'appdata_myinstanceid/preview/0/0/0/2/7/4'
'appdata_myinstanceid/preview/0/0/0/2/a'
'appdata_myinstanceid/preview/0/0/0/2/a/c'
'appdata_myinstanceid/preview/0/0/0/2/a/c/0'
'appdata_myinstanceid/preview/0/0/0/3/8'
'appdata_myinstanceid/preview/0/0/0/3/8/f'
'appdata_myinstanceid/preview/0/0/0/3/8/f/e'
'appdata_myinstanceid/preview/0/0/0/3/f'
'appdata_myinstanceid/preview/0/0/0/3/f/a'
'appdata_myinstanceid/preview/0/0/0/3/f/a/c'
...

And the output are just directories in the preview folder (excepted the first one).
For example in the end of the "folder path"appdata_myinstanceid/preview/0/0/0/2/a/c/0there is the directory 36492 containing some previews.
I checked some directories and in most of them it looks like this.

There are also a lot of directories in the preview directory with a number containing some previews.

Maybe this information can point someone in the right direction.

[robertugo2]

I am running mariadb database and I am affected by the same issue. I used preview generator as well. I am using docker instance for nextcloud version 20.0.3.