Very slow user deletion

[dossantg]

Steps to reproduce

We need to delete users from our nextcloud instance. We use the occ command: occ user:delete AXXXXXX

We notice that the deletion is very slow.

When we look at mysql slow log we can see theese requests during the deletion. We can see that Update and delete takes more than 17s each to execute during this operation.

# Time: 201107 18:46:46
# User@Host: nextcloud[nextcloud]
# Thread_id: 45851526  Schema: nextcloud  QC_hit: No
# **Query_time: 8.355477**  Lock_time: 0.000044  Rows_sent: 1  Rows_examined: 69068
# Rows_affected: 0  Bytes_sent: 10180
SET timestamp=1604771206;
SELECT `id`, `uri`, `lastmodified`, `etag`, `size`, `carddata`, `uid` FROM `oc_cards` WHERE (`addressbookid` = '2') AND (`uri` = 'LDAP:AXXXXX.vcf') LIMIT 1;

# Time: 201107 18:47:04
# User@Host: nextcloud[nextcloud]
# Thread_id: 45851526  Schema: nextcloud  QC_hit: No
# **Query_time: 17.572336**  Lock_time: 0.000046  Rows_sent: 0  Rows_examined: 148810
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1604771224;
UPDATE `oc_cards` SET `carddata` = 'BEGIN:VCARD\r\nVERSION:3.0\r\nPRODID:-//Sabre//Sabre VObject 4.3.0//EN\r\nUID:AXXXXXXXXX\r\nFN:XXXXXXXXX (XXXXXXXXXXXXXX)\r\nN:(XXXXXXXXXXXXXXXXXXXX);XXXXXXXXXXXX;;\r\nEMAIL;TYPE=OTHER:XXXXXXXXXXXXXXX\r\nCLOUD:AXXXXXXXXX\r\nEND:VCARD\r\n', `lastmodified` = '1604771207', `size` = '294', `etag` = '71a5200e457eaf849d75289d9d178a34', `uid` = 'AXXXXXX' WHERE (`uri` = 'LDAP:AXXXXXX.vcf') AND (`addressbookid` = '2');

# Time: 201107 18:47:12
# User@Host: nextcloud[nextcloud]
# Thread_id: 45851526  Schema: nextcloud  QC_hit: No
# **Query_time: 8.065805**  Lock_time: 0.000022  Rows_sent: 1  Rows_examined: 69068
# Rows_affected: 0  Bytes_sent: 830
SET timestamp=1604771232;
SELECT `id`, `uri`, `lastmodified`, `etag`, `size`, `carddata`, `uid` FROM `oc_cards` WHERE (`addressbookid` = '2') AND (`uri` = 'LDAP:AXXXXX.vcf') LIMIT 1;

# Time: 201107 18:47:30
# User@Host: nextcloud[nextcloud] 
# Thread_id: 45851526  Schema: nextcloud  QC_hit: No
# **Query_time: 17.900369**  Lock_time: 0.000067  Rows_sent: 0  Rows_examined: 148810
# Rows_affected: 1  Bytes_sent: 52
SET timestamp=1604771250;
UPDATE `oc_cards` SET `carddata` = 'BEGIN:VCARD\r\nVERSION:3.0\r\nPRODID:-//Sabre//Sabre VObject 4.3.0//EN\r\nUID:AXXXXX\r\nFN:XXXXXXX (XXXXX@XXXXX)\r\nN:(XXXXX@XXXXX);XXXXXXXXX;;\r\nEMAIL;TYPE=OTHER:XXXXX@XXXXX\r\nCLOUD:AXXXXX@XXXXXXXX\r\nEND:VCARD\r\n', `lastmodified` = '1604771233', `size` = '294', `etag` = '71a5200e457eaf849d75289d9d178a34', `uid` = 'AXXXXX' WHERE (`uri` = 'LDAP:AXXXXX.vcf') AND (`addressbookid` = '2');

# Time: 201107 18:47:49
# User@Host: nextcloud[nextcloud]
# Thread_id: 45851526  Schema: nextcloud  QC_hit: No
# **Query_time: 17.616706**  Lock_time: 0.000032  Rows_sent: 0  Rows_examined: 148810
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1604771269;
DELETE FROM `oc_cards` WHERE (`addressbookid` = '2') AND (`uri` = 'LDAP:AXXXXX.vcf');

When we make select resquests on oc_cards whith filter on id column we get the result in less than 1s.

MariaDB [nextcloud]> select * from oc_cards where id=4 \G
1 row in set (0.000 sec)

For information, there is 150k lines in the table oc_cards. We are testing with accounts that do not have data on the filesystem. The deletion time therefore comes from operations on the database like we can see in mariadb's logs.

Maybe this table need an index on addressbookid and uri columns.

Best regards Gaétan

Expected behaviour

Delete user account in less than 10s

Actual behaviour

Account deletion take more than 1 minute

Server configuration detail

Operating system: Linux 4.19.0-5-amd64 #1 SMP Debian 4.19.37-5+deb10u2 (2019-08-08) x86_64

Webserver: Apache/2.4.38 (Debian) (fpm-fcgi)

Database: mysql 10.1.45

PHP version:

7.3.19-1~deb10u1 Modules loaded: Core, date, libxml, openssl, pcre, zlib, filter, hash, Reflection, SPL, session, sodium, standard, cgi-fcgi, mysqlnd, PDO, xml, apcu, bcmath, calendar, ctype, curl, dom, mbstring, fileinfo, ftp, gd, gettext, gmp, iconv, igbinary, imagick, intl, json, ldap, 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.3 - 19.0.3.1

Updated from an older Nextcloud/ownCloud or fresh install: Updated from older Nextcloud

Where did you install Nextcloud from: git

Signing status

Integrity checker has been disabled. Integrity cannot be verified.

List of activated apps

``` Enabled: - accessibility: 1.5.0 - activity: 2.12.1 - cloud_federation_api: 1.2.0 - comments: 1.9.0 - contactsinteraction: 1.0.0 - dav: 1.15.0 - federatedfilesharing: 1.9.0 - files: 1.14.0 - files_sharing: 1.11.0 - files_trashbin: 1.9.0 - files_versions: 1.12.0 - files_videoplayer: 1.8.0 - issuetemplate: 0.7.0 - lookup_server_connector: 1.7.0 - notifications: 2.7.0 - oauth2: 1.7.0 - photos: 1.1.0 - provisioning_api: 1.9.0 - richdocuments: 3.7.5 - settings: 1.1.0 - sharebymail: 1.9.0 - theming: 1.10.0 - twofactor_backupcodes: 1.8.0 - updatenotification: 1.9.0 - user_ldap: 1.9.1 - user_saml: 3.2.1 - viewer: 1.3.0 - workflowengine: 2.1.0 Disabled: - admin_audit - encryption - federation - files_external - files_texteditor - systemtags - testing ```

Configuration (config/config.php)

``` { "instanceid": "***REMOVED SENSITIVE VALUE***", "passwordsalt": "***REMOVED SENSITIVE VALUE***", "secret": "***REMOVED SENSITIVE VALUE***", "trusted_proxies": "***REMOVED SENSITIVE VALUE***", "datadirectory": "***REMOVED SENSITIVE VALUE***", "overwrite.cli.url": "https:\/\/***REMOVED SENSITIVE VALUE***", "overwriteprotocol": "https", "dbtype": "mysql", "version": "19.0.3.1", "dbname": "***REMOVED SENSITIVE VALUE***", "dbhost": "***REMOVED SENSITIVE VALUE***", "dbport": "", "dbtableprefix": "oc_", "mysql.utf8mb4": true, "dbuser": "***REMOVED SENSITIVE VALUE***", "dbpassword": "***REMOVED SENSITIVE VALUE***", "installed": true, "ldapIgnoreNamingRules": false, "ldapProviderFactory": "\\OCA\\User_LDAP\\LDAPProviderFactory", "ldapUserCleanupInterval": 0, "memcache.local": "\\OC\\Memcache\\APCu", "memcache.distributed": "\\OC\\Memcache\\Redis", "memcache.locking": "\\OC\\Memcache\\Redis", "filelocking.enabled": true, "redis": { "host": "***REMOVED SENSITIVE VALUE***", "port": 6379, "dbindex": 1 }, "filesystem_check_changes": 0, "enable_avatars": false, "mail_from_address": "***REMOVED SENSITIVE VALUE***", "mail_smtpmode": "sendmail", "mail_smtpauthtype": "LOGIN", "mail_domain": "***REMOVED SENSITIVE VALUE***", "share_folder": "\/Shared", "cron_log": true, "loglevel": "2", "maintenance": false, "trashbin_retention_obligation": 30, "trashbin_auto_expire": true, "logfile": "\/var\/log\/nextcloud\/nextcloud.log", "knowledgebaseenabled": false, "sharing.maxAutocompleteResults": 20, "sharing.minSearchStringLength": 3, "activity_expire_days": "180" } ```

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

Are you using encryption:

Are you using an external user-backend, if yes which one: LDAP/SAML

LDAP configuration (delete this par if not used)

``` ```

Client configuration

Browser: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.75 Safari/537.36

Operating system:

Logs

Web server error log

``` ```

Nextcloud log

``` ```

Browser log

[kesselb]

cc @rullzer @skjnldsv

[skjnldsv]

Hey! Have you checked if that could be related to the data as well maybe? I assume if the user have a lot of data, this can lead to a pretty big waiting time?

We are testing with accounts that do not have data on the filesystem.

I should learn to read! 🙈

[skjnldsv]

Maybe this table need an index on addressbookid and uri columns.

That would be very practical indeed. You limited the result to 1 on the select, but how many rows were there for the addressbook && Uri select combination?

[dossantg]

Hello, It is not me who puts the limit 1 in the request. These are the queries that are generated by the occ user: delete command. I just looked and it looks like i only have one row with this combination.

But maybe I don't understand your question.

Regards

[skjnldsv]

I just looked and it looks like i only have one row with this combination.

Thanks, and it takes 17 Seconds? That is definitely not acceptable, I'll try it later to check as well :)

[skjnldsv]

Pretty fast to me. I filled the cards table with 1k rows. Deleting the user took somewhat half a second (no data either)

Could you run a occ db:add-missing-indices maybe? Is everything green in your /settings/admin/overview page?

[skjnldsv]

cc @blizzz might be an issue with ldap? :shrug:

[dossantg]

I have 148k row in oc_cards:

MariaDB [nextcloud]> select count(*) from oc_cards;
+----------+
| count(*) |
+----------+
|   148810 |
+----------+
1 row in set (0.043 sec)

My table is 2gb in size:

du -hs /var/lib/mysql/nextcloud/oc_cards.ibd 
2,1G    /var/lib/mysql/nextcloud/oc_cards.ibd

I already launch occ db:add-missing-indices and everithing is fine.

Here the actual index on the table:

MariaDB [nextcloud]> show index from oc_cards;
+----------+------------+------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table    | Non_unique | Key_name   | Seq_in_index | Column_name   | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+----------+------------+------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| oc_cards |          0 | PRIMARY    |            1 | id            | A         |      139739 |     NULL | NULL   |      | BTREE      |         |               |
| oc_cards |          1 | cards_abid |            1 | addressbookid | A         |           2 |     NULL | NULL   |      | BTREE      |         |               |
+----------+------------+------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
2 rows in set (0.000 sec)

[skjnldsv]

For information, there is 150k lines in the table oc_cards.

What is wrong with my reading tonight! I swear! :see_no_evil: :eyes:

I'm sorry for this nonsense. Yeah, it doesn't scale, I guess having indexes should help? cc @MorrisJobke @blizzz @rullzer @ChristophWurst :)

[ChristophWurst]

yes

[szaimen]

Hi, please update to 24.0.9 or better 25.0.3 and report back if it fixes the issue. Thank you!

My goal is to add a label like e.g. 25-feedback to this ticket of an up-to-date major Nextcloud version where the bug could be reproduced. However this is not going to work without your help. So thanks for all your effort!

If you don't manage to reproduce the issue in time and the issue gets closed but you can reproduce the issue afterwards, feel free to create a new bug report with up-to-date information by following this link: https://github.com/nextcloud/server/issues/new?assignees=&labels=bug%2C0.+Needs+triage&template=BUG_REPORT.yml&title=%5BBug%5D%3A+