Unnecessary queries to DB backend? #14010

Rayn0r · 2019-02-04T12:42:38Z

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

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

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

nothing particular

Nextcloud log (data/nextcloud.log)

Nextcloud log

nothing particular

Browser log

nothing particular

The text was updated successfully, but these errors were encountered:

kesselb · 2019-02-06T10:55:01Z

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 · 2019-02-06T20:48:12Z

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 · 2019-02-06T21:07:40Z

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 · 2019-02-07T07:56:47Z

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 · 2019-04-30T10:35:09Z

@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 · 2019-05-21T08:38:20Z

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 · 2020-03-10T08:15:34Z

Any updates?

kesselb · 2020-04-09T18:25:35Z

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

nickvergessen · 2020-06-17T09:39:30Z

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

Yes, see #20865

Closing this issue as the talk query was fixed in the meantime

Rayn0r added 0. Needs triage Pending check for reproducibility or if it fits our roadmap bug labels Feb 4, 2019

skjnldsv added the needs info label Mar 10, 2020

ghost added the stale Ticket or PR with no recent activity label Apr 9, 2020

nextcloud deleted a comment Apr 9, 2020

kesselb removed the stale Ticket or PR with no recent activity label Apr 9, 2020

ghost added the stale Ticket or PR with no recent activity label May 14, 2020

ghost closed this as completed May 28, 2020

kesselb reopened this May 28, 2020

ghost removed the stale Ticket or PR with no recent activity label May 28, 2020

nextcloud deleted a comment May 28, 2020

kesselb removed the needs info label May 28, 2020

nickvergessen closed this as completed Jun 17, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unnecessary queries to DB backend? #14010

Unnecessary queries to DB backend? #14010

Rayn0r commented Feb 4, 2019 •

edited

Loading

kesselb commented Feb 6, 2019 •

edited

Loading

Rayn0r commented Feb 6, 2019

kesselb commented Feb 6, 2019 •

edited

Loading

Rayn0r commented Feb 7, 2019

skjnldsv commented Apr 30, 2019

blizzz commented May 21, 2019

skjnldsv commented Mar 10, 2020

kesselb commented Apr 9, 2020

nickvergessen commented Jun 17, 2020

Unnecessary queries to DB backend? #14010

Unnecessary queries to DB backend? #14010

Comments

Rayn0r commented Feb 4, 2019 • edited Loading

Steps to reproduce

Expected behaviour

Actual behaviour

Server configuration

Client configuration

Logs

Web server error log

Nextcloud log (data/nextcloud.log)

Browser log

kesselb commented Feb 6, 2019 • edited Loading

Rayn0r commented Feb 6, 2019

kesselb commented Feb 6, 2019 • edited Loading

Rayn0r commented Feb 7, 2019

skjnldsv commented Apr 30, 2019

blizzz commented May 21, 2019

skjnldsv commented Mar 10, 2020

kesselb commented Apr 9, 2020

nickvergessen commented Jun 17, 2020

Rayn0r commented Feb 4, 2019 •

edited

Loading

kesselb commented Feb 6, 2019 •

edited

Loading

kesselb commented Feb 6, 2019 •

edited

Loading