NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) #8977

Rayn0r · 2018-03-25T22:43:05Z

Steps to reproduce

Create a folder, copy around 366 JPGs into it (or the same pic with different names).
change into the folder and wait

Expected behaviour

Files should be display within milliseconds after changing into a folder

Actual behaviour

It takes over 8 seconds for the content to appear.
During this time the MySQL instance is at 80-100% CPU usage.
After the files are finally displayed, thumbnails are loaded instantly.

To dig a bit deeper I enabled:
general_log_file = /var/log/mysql/mysql.log
general_log = 1
in my mysql.cnf.

While PROPFIND is running, Nextcloud issues around 413 MySQL commands.
366 Queries look like this:
SELECT * FROM oc_properties WHERE userid = 'username' AND propertypath = '/list-test/1/IMG_XXXXXXXX_XXXXXX.jpg' AND propertyname in ('{http://nextcloud.org/ns}is-encrypted')

There is one query for each file inside the list-test directory...

I also created a folder and created 365 empty folders inside it. Listing this folder only takes around 280ms.
Listing those 365 directories only issues 47 queries and none of the above...

47+366 is 413... Which is the exact number of queries for the directory containing files!

The URL inside the query in question is "http://nextcloud.org/ns" Trying to resolve nextcloud.org results in an error. There does not seem to be a DNS A-Record for this domain.

So, what is being queried in those 366 queries?
What's even more interesting: What purpose do those queries have?

Server configuration

Operating system: Ubuntu 16.04

Web server: Apache 2.4.18

Database: MySQL 5.7.21

PHP version: 7.0.28

Nextcloud version: 13.0.1.1

Hardware: Intel Xeon E3-1245 v6, 16GB RAM

Updated from an older Nextcloud/ownCloud or fresh install: Upgrade from OC9 manually. Then used Updater App to go from 9 to 10 and so forth.
After upgrading to 13.0.1 I also ran this while in maintenance mode:
sudo -u www-data php occ db:add-missing-indice
sudo -u www-data php occ db:convert-filecache-bigint

Where did you install Nextcloud from: Upgrade via Updater from 12.0.06

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
  - activity: 2.6.1
  - admin_audit: 1.3.0
  - bruteforcesettings: 1.0.3
  - calendar: 1.6.1
  - comments: 1.3.0
  - dav: 1.4.6
  - federatedfilesharing: 1.3.1
  - federation: 1.3.0
  - files: 1.8.0
  - files_sharing: 1.5.0
  - files_texteditor: 2.5.1
  - files_trashbin: 1.3.0
  - files_versions: 1.6.0
  - files_videoplayer: 1.2.0
  - firstrunwizard: 2.2.1
  - gallery: 18.0.0
  - impersonate: 1.0.3
  - logreader: 2.0.0
  - lookup_server_connector: 1.1.0
  - nextcloud_announcements: 1.2.0
  - notifications: 2.1.2
  - oauth2: 1.1.0
  - password_policy: 1.3.0
  - piwik: 0.3.2
  - provisioning_api: 1.3.0
  - registration: 0.4.0
  - richdocuments: 2.0.4
  - serverinfo: 1.3.0
  - sharebymail: 1.3.0
  - survey_client: 1.1.0
  - systemtags: 1.3.0
  - theming: 1.4.1
  - twofactor_backupcodes: 1.2.3
  - twofactor_totp: 1.4.1
  - updatenotification: 1.3.0
  - workflowengine: 1.3.0
Disabled:
  - encryption
  - files_external
  - files_pdfviewer
  - user_external
  - user_ldap

Nextcloud configuration:

Config report

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "home.myinstance.org",
            "nextcloud.myinstance.org",
            "192.xxx.xxx.xxx",
            "server"
        ],
        "htaccess.RewriteBase": "\/",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/nextcloud.myinstance.org",
        "dbtype": "mysql",
        "version": "13.0.1.1",
        "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,
        "memcache.local": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "timeout": 0,
            "dbindex": 0
        },
        "loglevel": 2,
        "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",
        "mail_smtpauthtype": "LOGIN"
    }
}

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 58.0.2

Operating system: Windows 7

Logs

Web server error log

nextcloud.myinstance.org:443 xxx.xxx.xxx.xxx - - [25/Mar/2018:23:31:33 +0200] "PROPFIND /remote.php/webdav/list-test/1 HTTP/1.1" 207 311523 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:58.0) Gecko/20100101 Firefox/58.0"
nextcloud.myinstance.org:443 xxx.xxx.xxx.xxx - - [25/Mar/2018:23:31:41 +0200] "GET /index.php/apps/files/ajax/getstoragestats.php?dir=%2Flist-test%2F1 HTTP/1.1" 200 1198 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:58.0) Gecko/20100101 Firefox/58.0"
nextcloud.myinstance.org:443 xxx.xxx.xxx.xxx - - [25/Mar/2018:23:31:44 +0200] "GET /ocs/v2.php/apps/notifications/api/v2/notifications HTTP/1.1" 200 1426 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:59.0) Gecko/20100101 Firefox/59.0"
nextcloud.myinstance.org:443 xxx.xxx.xxx.xxx - - [25/Mar/2018:23:31:49 +0200] "GET /ocs/v2.php/apps/notifications/api/v2/notifications HTTP/1.1" 200 959 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:58.0) Gecko/20100101 Firefox/58.0"
nextcloud.myinstance.org:443 xxx.xxx.xxx.xxx - - [25/Mar/2018:23:31:50 +0200] "GET /ocs/v2.php/apps/notifications/api/v2/notifications HTTP/1.1" 200 806 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:58.0) Gecko/20100101 Firefox/58.0"

Nextcloud log (data/nextcloud.log)

Nextcloud log

noting in nextcloud.log while opening the folder

Browser log


![propfind](https://user-images.githubusercontent.com/4147858/37880303-4ba5d886-3086-11e8-9eac-ea3b1b1bee08.JPG)

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

Rayn0r · 2018-03-27T21:22:51Z

I wondered why 47 queries only take 280ms where 413 queries take 8 seconds. The 47 queries should at least take a little bit longer.
But they don't.

The reason is, that a query in the form of:
SELECT * FROM oc_properties WHERE userid = 'username' AND propertypath = '/list-test/1/IMG_XXXXXXXX_XXXXXX.jpg' AND propertyname in ('{http://nextcloud.org/ns}is-encrypted')
takes between 0.02 and 0.04 seconds to complete.
All other queries return instantly (at least mysql says 0.00 sec)

The query takes about the same amount of time even when the last condition is omitted:
SELECT * FROM oc_properties WHERE userid = 'username' AND propertypath = '/list-test/1/IMG_XXXXXXXX_XXXXXX.jpg'

Shortening the query even more to:
SELECT * FROM oc_properties WHERE userid = 'username'

Returns a set of almost 25000 entries...

There seems to be an index on userid on the table. Since there is pretty much only one user in this table with close to 25000 entries, the index might not have a great effect (please correct me if I'm wrong).

I can see how it can take 8 seconds to go through all this 366 times... In total these are 9 million lines.

Rayn0r · 2018-03-27T22:36:49Z

I reverted back to 12.0.6 (restored DB, cleared appdata_xxxxxxxxxxxx, and copied 12.0.6 files into place).
Now listing a directory is fast again. There are only 52 DB queries upon chdir. There is no query to oc_properties at all.

@icewind1991 @rullzer Do you know what changed in regards of listing files between 12.0.6 and 13.0.1?

rullzer · 2018-03-28T05:49:53Z

Ah yes. I think I know.

rullzer · 2018-03-28T05:50:38Z

I'll prepare a pr once at my laptop

fixes #8977 Else for all files in a folder we would launch off more queries. Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>

Rayn0r · 2018-03-28T06:50:38Z

@rullzer
I applied the patch and Firefox now reports a PROPFIND time of 250ms.
Thanks a lot!

You added this patch to milestone 14. Could this patch by any chance also go into 13.0.2?

rullzer · 2018-03-28T13:21:35Z

@Rayn0r we'll evaluate that once it is merged.

Of course if this is mission critical to you I would recommend you contact sales at https://nextcloud.com/enterprise/ (I'm just guessing you have a fairly large setup by the hardware specs you are have 😉 )

fixes #8977 Else for all files in a folder we would launch off more queries. Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>

Rayn0r changed the title ~~NC 13.0.1 takes long on chdir, when the dir contains lots of files~~ NC 13.0.1: Listing dir content takes long on chdir, when the dir contains lots of files Mar 26, 2018

Rayn0r changed the title ~~NC 13.0.1: Listing dir content takes long on chdir, when the dir contains lots of files~~ NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) Mar 26, 2018

rullzer added a commit that referenced this issue Mar 28, 2018

Do not treat is-encrypted as customer property

e8b7e9e

fixes #8977 Else for all files in a folder we would launch off more queries. Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>

rullzer mentioned this issue Mar 28, 2018

Do not treat is-encrypted as custom property #9006

Merged

MorrisJobke closed this as completed in #9006 Apr 3, 2018

MorrisJobke added this to the Nextcloud 14 milestone Apr 3, 2018

MorrisJobke added the bug label Apr 3, 2018

rullzer added a commit that referenced this issue Apr 4, 2018

Do not treat is-encrypted as customer property

df09b65

fixes #8977 Else for all files in a folder we would launch off more queries. Signed-off-by: Roeland Jago Douma <roeland@famdouma.nl>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) #8977

NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) #8977

Rayn0r commented Mar 25, 2018

Rayn0r commented Mar 27, 2018

Rayn0r commented Mar 27, 2018

rullzer commented Mar 28, 2018

rullzer commented Mar 28, 2018

Rayn0r commented Mar 28, 2018

rullzer commented Mar 28, 2018

NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) #8977

NC 13.0.1: PROPFIND takes long on chdir, when the dir contains lots of files (listing the same No. of directories is fast) #8977

Comments

Rayn0r commented Mar 25, 2018

Steps to reproduce

Expected behaviour

Actual behaviour

Server configuration

Client configuration

Logs

Web server error log

Nextcloud log (data/nextcloud.log)

Browser log

Rayn0r commented Mar 27, 2018

Rayn0r commented Mar 27, 2018

rullzer commented Mar 28, 2018

rullzer commented Mar 28, 2018

Rayn0r commented Mar 28, 2018

rullzer commented Mar 28, 2018