Unnecessary queries to DB backend?

[Rayn0r]

While trying to optimize performance for the MariaDB back-end for NC15 I stumbled upon lot's of queries in the log that did not make sense. I was only browsing picture folders but found lot's of queries for Talk and Two Factor. Queries poped up every time the browser loaded a new preview image.

Steps to reproduce

1. Add the following lines to your MySQL/MariaDB CNF file:

slow_query_log=1
slow_query_log_file=/var/log/mysql/slow.log
log_queries_not_using_indexes=1

2. run tail -f /var/log/mysql/slow.log|egrep "oc_talk_rooms|oc_twofactor_providers" while browsing a folder containing pictures in NC, only to find lot's of queries like this:

SELECT `r`.*, `p`.* FROM `oc_talk_rooms` `r` LEFT JOIN `oc_talk_participants` `p` ON (`p`.`user_id` = 'USERNAME') AND (`p`.`room_id` = `r`.`id`) WHERE `p`.`user_id` IS NOT NULL;
SELECT `provider_id`, `enabled` FROM `oc_twofactor_providers` WHERE `uid` = 'USERNAME';

Expected behaviour

I don't see why all those queries are necessary upon loading a new preview picture...

Actual behaviour

Cut the queries to a minimum to take load off the SQL DB.

Server configuration

Operating system: Ubuntu 18.04

Web server: Apache 2.4.29

Database: MariaDB 10.3

PHP version: 7.2.10

Nextcloud version: 15.0.2.0

Updated from an older Nextcloud/ownCloud or fresh install: Upgrade from OC 9

Where did you install Nextcloud from: Updater

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
  - accessibility: 1.1.0
  - activity: 2.8.2
  - admin_audit: 1.5.0
  - cloud_federation_api: 0.1.0
  - comments: 1.5.0
  - dav: 1.8.1
  - federatedfilesharing: 1.5.0
  - federation: 1.5.0
  - files: 1.10.0
  - files_rightclick: 0.11.0
  - files_sharing: 1.7.0
  - files_texteditor: 2.7.0
  - files_trashbin: 1.5.0
  - files_versions: 1.8.0
  - files_videoplayer: 1.4.0
  - firstrunwizard: 2.4.0
  - gallery: 18.2.0
  - impersonate: 1.2.0
  - logreader: 2.0.0
  - lookup_server_connector: 1.3.0
  - nextcloud_announcements: 1.4.0
  - notifications: 2.3.0
  - oauth2: 1.3.0
  - password_policy: 1.5.0
  - provisioning_api: 1.5.0
  - registration: 0.4.5
  - richdocuments: 3.1.1
  - serverinfo: 1.5.0
  - sharebymail: 1.5.0
  - support: 1.0.0
  - survey_client: 1.3.0
  - systemtags: 1.5.0
  - theming: 1.6.0
  - twofactor_backupcodes: 1.4.1
  - twofactor_totp: 2.1.0
  - updatenotification: 1.5.0
  - workflowengine: 1.5.0
Disabled:
  - encryption
  - files_external
  - files_pdfviewer
  - spreed
  - terms_of_service
  - user_ldap

Nextcloud configuration:

Config report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "nextcloud.myserver.domain",
            "home.myserver.domain",
            "10.1.1.254",
            "server"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/nextcloud.myserver.domain\/",
        "htaccess.RewriteBase": "\/",
        "dbtype": "mysql",
        "version": "15.0.2.0",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "forcessl": true,
        "forceSSLforSubdomains": true,
        "tempdirectory": "\/tmp",
        "theme": "",
        "maintenance": false,
        "login_form_autocomplete": false,
        "memcache.local": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "timeout": 0,
            "dbindex": 0
        },
        "loglevel": 0,
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "singleuser": false,
        "updater.release.channel": "stable",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "25",
        "enable_previews": true,
        "preview_max_x": 2048,
        "preview_max_y": 2048,
        "preview_jpeg_quality": 75
    }
}

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

Are you using encryption: no

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

Client configuration

Browser: FF 64.0

Operating system: Win7 64

Logs

Web server error log

Web server error log

nothing particular

Nextcloud log (data/nextcloud.log)

Nextcloud log

nothing particular

Browser log

Browser log

nothing particular

[kesselb]

Query for twofactor is part of the user session. Maybe we could cache the result. @ChristophWurst

Another question regarding your setup. By default long_query_time is 10 seconds. It looks wrong to me that a simple query like SELECT provider_id, enabled FROM oc_twofactor_providers WHERE uid = 'USERNAME'; needs more than 10 seconds 🤔

[Rayn0r]

I added log_queries_not_using_indexes=1 to the CNF file. My assumption is, that above queries are logged because there is no index on the enabled column in oc_twofactor_providers (and not because it is in fact a slow query). I don't think an index would be useful for a column that is only used to store boolean.

I did a quick test and browsed into a folder containing ~350 images. It resulted in 1495 Queries being logged:

grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |wc -l
1495
grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep -v "oc_talk_participants"|wc -l
1123
grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep -v "oc_talk_participants|oc_twofactor_providers"|wc -l
753
grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep -v "oc_talk_participants|oc_twofactor_providers|oc_appconfig"|wc -l
374
grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep -v "oc_talk_participants|oc_twofactor_providers|oc_appconfig|oc_mimetypes"|wc -l
2

btw... There are 751 queries containing oc_appconfig or oc_mimetypes:

grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep "oc_appconfig|oc_mimetypes"|wc -l
751

And those queries are always the same:

grep "oc_" /var/log/mysql/slow.log|grep -i SELECT |egrep "oc_appconfig|oc_mimetypes"|sort -u
SELECT * FROM `oc_appconfig`;
SELECT `id`, `mimetype` FROM `oc_mimetypes`;

[kesselb]

I added log_queries_not_using_indexes=1 to the CNF file. My assumption is, that above queries are logged because there is no index on the enabled column in oc_twofactor_providers (and not because it is in fact a slow query). I don't think an index would be useful for a column that is only used to store boolean.

SELECT provider_id, enabled FROM oc_twofactor_providers WHERE uid = 'USERNAME';

There is an index on uid and also used by the query above. Index on enabled would not help because the column is not used to filter the result.

Have you tried? https://github.com/major/MySQLTuner-perl It's very unusual that simple queries (e.g. selects without join/where/having/...) are logged to slow query log.

[Rayn0r]

If I remove log_queries_not_using_indexes=1 from the CNF file nothing gets logged to /var/log/mysql/slow.log.
My concern is not about slow queries. If I understood this correctly then according to this page unindexed queries "belong" to the slow query log. All above queries complete under 10 ms.

What I'm saying is, that I don't understand why all those queries are fired upon loading a preview image...

MySQLTuner was the reason I looked at unindexed queries, because it suggested the following:
join_buffer_size (> 2.0M, or always use indexes with JOINs)

[skjnldsv]

@rullzer @blizzz maybe a clue on those queries?
I guess related to the user session? Fetching a preview have some security checks that gets triggered? 🤔

[blizzz]

SELECT * FROM oc_appconfig;
SELECT id, mimetype FROM oc_mimetypes;

The full table is read here, using index is not useful here.

about the two-factor providers, I saw on on instance the index being used, and on another (bigger) one it not being used. This is the database's query plan to use the index or not. I'd trust it does the right thing.

SELECT r., p. FROM oc_talk_rooms r LEFT JOIN oc_talk_participants p ON (p.user_id = 'USERNAME') AND (p.room_id = r.id) WHERE p.user_id IS NOT NULL;

Here the query against oc_talk_participants does not use any index (fyi: put an EXPLAIN in front of SELECT in the database console to get information about the query). oc_talk_participants does not have a key defined, indeed. That might be intentional. @Ivansss do you know?

[skjnldsv]

Any updates?

[kesselb]

Is there no way to load less (or only the required) apps for process a preview image?