High CPU usage while syncing apps from phone – php-fpm

[dorsiflexion]

Steps to reproduce

1. Have php-fpm 7.3.8 or 7.3.9 installed. Versions prior to these work fine.
2. Initiate the syncing of an app on a mobile phone with the Nextcloud.

Time was measured with the news app but other apps – like for notes – show similar behavior. Web access via browser seems normal.

Expected behaviour

Syncing takes 1-2 seconds. 1-3 threads of php-fpm utilize 10-20% CPU.
(php-fpm <= 7.3.7)

Actual behaviour

Syncing takes ca. 10-12 seconds. 1-3 threads of php-fpm utilize 50+ % CPU, at
least one close to 100% in that time.
(php-fpm >= 7.3.8)

Server configuration

Hardware: Raspberry Pi 3 Model B

Operating system: Arch Linux ARM

Web server: Lighttpd

Database: MariaDB

PHP version: 7.3.9

Nextcloud version: 16.0.4

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

Where did you install Nextcloud from: Arch package manager – pacman

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
  - accessibility: 1.2.0
  - calendar: 1.7.1
  - cloud_federation_api: 0.2.0
  - contacts: 3.1.3
  - dav: 1.9.2
  - federatedfilesharing: 1.6.0
  - files: 1.11.0
  - files_rightclick: 0.15.1
  - files_trashbin: 1.6.0
  - files_versions: 1.9.0
  - gallery: 18.3.0
  - logreader: 2.1.0
  - lookup_server_connector: 1.4.0
  - news: 13.1.6
  - notes: 3.0.3
  - notifications: 2.4.1
  - oauth2: 1.4.2
  - provisioning_api: 1.6.0
  - serverinfo: 1.6.0
  - tasks: 0.11.3
  - twofactor_backupcodes: 1.5.0
  - updatenotification: 1.6.0
  - workflowengine: 1.6.0
Disabled:
  - activity
  - admin_audit
  - comments
  - encryption
  - federation
  - files_external
  - files_pdfviewer
  - files_sharing
  - files_texteditor
  - files_videoplayer
  - firstrunwizard
  - nextcloud_announcements
  - password_policy
  - privacy
  - recommendations
  - sharebymail
  - support
  - survey_client
  - systemtags
  - theming
  - user_ldap
  - viewer

Nextcloud configuration:

Config report

sudo -u http php /usr/share/webapps/nextcloud/occ config:list system

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "192.168.10.5",
            "localhost",
            "picloud.local",
            "picloud",
            "::1",
            "127.0.1.1"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "16.0.4.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,
        "overwrite.cli.url": "http:\/\/192.168.10.5",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "maintenance": false,
        "loglevel": 2,
        "app_install_overwrite": [
            "calendar",
            "tasks"
        ],
        "mail_smtpmode": "smtp",
        "mail_smtpsecure": "ssl",
        "mail_sendmailmode": "smtp",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "465",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": 1,
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "data-fingerprint": "f6ae37315645dadf1abd0b748a32218a"
    }
}

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: Firefox 69.0.1 (64-bit)

Operating system: 5.3.1-arch1-1-ARCH x86_64 GNU/Linux

Logs

Web server error log

Web server error log

2019-09-22 00:00:02: (server.c.969) [note] graceful shutdown started 
2019-09-22 00:00:02: (server.c.2091) server stopped by UID = 0 PID = 91765 
2019-09-22 00:00:02: (server.c.1521) server started (lighttpd/1.4.54) 
2019-09-22 04:20:05: (server.c.969) [note] graceful shutdown started 
2019-09-22 04:20:05: (server.c.2091) server stopped by UID = 0 PID = 1 
2019-09-22 04:21:03: (server.c.1521) server started (lighttpd/1.4.54) 
2019-09-22 16:53:15: (server.c.969) [note] graceful shutdown started 
2019-09-22 16:53:15: (server.c.2091) server stopped by UID = 0 PID = 1 
2019-09-22 16:53:17: (server.c.1521) server started (lighttpd/1.4.54) 
2019-09-22 22:00:06: (server.c.969) [note] graceful shutdown started 
2019-09-22 22:00:06: (server.c.2091) server stopped by UID = 0 PID = 1 
2019-09-22 22:00:09: (server.c.1521) server started (lighttpd/1.4.54) 
2019-09-22 22:49:46: (server.c.969) [note] graceful shutdown started 
2019-09-22 22:49:46: (server.c.2091) server stopped by UID = 0 PID = 1 
2019-09-22 22:49:47: (server.c.1521) server started (lighttpd/1.4.54) 
2019-09-23 04:20:03: (server.c.969) [note] graceful shutdown started 
2019-09-23 04:20:03: (server.c.2091) server stopped by UID = 0 PID = 1 
2019-09-23 04:20:54: (server.c.1521) server started (lighttpd/1.4.54)

Nextcloud log (data/nextcloud.log)

Nextcloud log

No entries at the time of the event.

Browser log

[kesselb]

Thank you for reporting this issue 👍

You narrowed down the problem to php-fpm. I'm not sure how nextcloud can fix a regression (if there is one) in php-fpm?

[dorsiflexion]

It was asked if I already got in touch with the Nextcloud team, so I did. Any help on further narrowing down the issue would most likely be appreciated. I think info on how php-fpm is involved during the snycing process could help.
Issue @ PHP

[kesselb]

Hmm. We can do some profiling with xdebug and check if there is a difference. Do you see the same with the nextcloud app?

[dorsiflexion]

No. Performance with the Nextcloud app is about the same through the different php-fpm versions. So far I can confirm the problem with Nextcloud news and notes (android app I use). I did not test other apps yet since I don't use those.

[solracsf]

Can't reproduce here.

# php -v
PHP 7.3.9-1+ubuntu18.04.1+deb.sury.org+1 (cli) (built: Sep  2 2019 12:54:24) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.3.9, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.3.9-1+ubuntu18.04.1+deb.sury.org+1, Copyright (c) 1999-2018, by Zend Technologies

[dorsiflexion]

I have no clue what fixed it, but it is working as expected now. Closing...
Thanks for your time.

[rasos]

Facing a similar performance issue after upgrading to php 7.2.24 (see the spikes after Nov 4), running NC 16 also in fpm mode with about 60 active users. No clue yet, optimized all child and spawn parameters.

[kesselb]

We found a infinite loop with search dav requests. Check #17447 for more details.

[muppeth]

@kesselb Any idea when it will be released?

[kesselb]

https://github.com/nextcloud/server/wiki/Maintenance-and-Release-Schedule

17.0.2 / 16.0.7

[muppeth]

Thankks @kesselb
Is just copying 3rdparty/icewind from master to current 17.0.1 installation should fix it? I wonder if I could use it as a solution in the meantime.