Nextcloud updater is very slow

kentw · June 10, 2017, 3:38pm

I have 9 instances of nextcloud running on a server. None of them are heavily used. I am currently working on updating from 11.0.3 to 12.0.0 but have had this issue for the last few updates.

When I start the updater it jumps into gear and clicks through the bullets down to the backup. This takes at least 20 minutes to conduct. Then the download can take 5 or more minutes and the extract can take 5-10 minutes. The processor is barely loaded so I know it’s not a load issue. Once extraction is done it picks back up and I can be done in a minute or two. These are not large installs only a few users each.

I have watched this process on a friends setup that is very similar to mine only with a lesser processor. It all happened in a few minutes. He is on a 10 mbit internet connection and I have gigabit.

This just doesn’t make sense so I thought I would ask. I am assuming there must be something to my setup that is causing this slowness. Any suggestions would be appreciated. It is however somewhat hard to test as I can only test when I have updates to do.

Nextcloud version (eg, 11.0.3):
Operating system and version (eg, Ubuntu 16.04):
Apache or nginx version (eg, Apache 2.4.18):
PHP version (eg, 7.0):
Is this the first time you’ve seen this error?:
This is not a error but unexplained slowness
Can you reliably replicate it? (If so, please outline steps):
Every time I use the updater to update to the next version.
The issue you are facing:
Since I have 9 of these to update 45-60 minutes per site takes a very long time.

tflidd · June 10, 2017, 10:50pm

I tested some beta versions where some updates took some time. The download however was very fast and it should take a couple of seconds on your gigabit-connection. You can perhaps test the connection by downloading manually a Nextcloud-archive (from nextcloud.com/changelog).

For the rest you can check the logfiles for errors. Another factor is how many users and how many files they have. Larger setups can take significantly longer. Next time you can run a manual upgrade on one of the instances and compare the time.

kentw · June 11, 2017, 1:09pm

I went ahead and did the manual upgrade on 5 of my sites. The download took seconds and after the files were in place the actual upgrade process took seconds just like when I run the updater. It’s the backup/download/extract/put in place etc that take so long it’s not worth using. I did 5 sites manually in 10 minutes. Before that I did two sites using the updater that took almost an hour. They were running at the same time but again my processor load was under 1 for a four core processor.

I wish I knew something to look for in the logs and that is why I posted this, just to ask the question. Obviously I can do the manual update but it’s really nice to just click the link and do it right in the browser.

JasonBayton · June 11, 2017, 1:31pm

That’s an interesting one. When you’re running the updater it might be worth having htop/iotop running and keeping an eye on the Apache and syslog.

We’re unfortunately as blind on this as you without something to go on

kentw · June 11, 2017, 7:26pm

I’ll try to watch that next time there is a update.

JasonBayton · June 11, 2017, 7:50pm

Or spin up a test box. However you like

Mehlstaub · August 11, 2017, 8:49pm

I can confirm that the updater is super slow on my installation.
Nextcloud 12 to 12.0.1
But this also happend on older Updates.

Step backup takes forever
I have my data folder on a nfs share. The NFS share is a WD My Cloud EX2. Performance is normally amazing with this thing.
But the updater seems to have troube using the full nfs power of that thing. Backup takes minimum 20 minutes.
Having iotop open i see barely activity. 30K-100K
htop says machine is bored 2-8% CPU, RAM 1/5GB
iftop also only shows very low transmission rates to and from my nfs.
Syslog contains nothing

Transfering another file from or to the nfs results in around 70 MB/s transfer speed

To the extracting step:
also takes quite long. htop, iotop and iftop show the same behaviour
Syslog contains nothing

Downloading step
pretty quick on my 35 MBit connection

Will attach the updater log.
But from my point of view it looks like every interaction with the nfs storage is super slow.

System Spec
Ubuntu 16.04.2 LTS
Intel® Core™ i5-4250U CPU @ 1.30GHz Dual Core
5 GB DDR 3 RAM
45 GB SSD Main Storage (where also /var/www/nextcloud is located)
4 TB NFS Storage (for data folder)
Apache 2.4.18
PHP 7.0.22
Machine is Virtual Box on Windows 10 1607

Super long updater log

2017-08-11T21:53:17+0200 bd1564kdmB [info] request to updater
2017-08-11T21:53:17+0200 bd1564kdmB [info] currentStep()
2017-08-11T21:53:18+0200 bd1564kdmB [info] show HTML page
2017-08-11T21:53:18+0200 bd1564kdmB [info] current version: 12.0.0 build time: 2017-05-22T08:27:00+00:00 98e26f8b5c8b238e7f3556e900c524ce78bde95a
2017-08-11T21:53:18+0200 bd1564kdmB [info] getUpdateServerResponse()
2017-08-11T21:53:18+0200 bd1564kdmB [info] updaterServer: https://updates.nextcloud.org/updater_server/
2017-08-11T21:53:18+0200 bd1564kdmB [info] releaseChannel: stable
2017-08-11T21:53:18+0200 bd1564kdmB [info] internal version: 12.0.0.29
2017-08-11T21:53:18+0200 bd1564kdmB [info] updateURL: https://updates.nextcloud.org/updater_server/?version=12x0x0x29xxxstablexx2017-05-22T08%3A27%3A00%2B00%3A00+98e26f8b5c8b238e7f3556e900c524ce78bde95ax7x0x18
2017-08-11T21:53:18+0200 bd1564kdmB [info] getUpdateServerResponse response: Array
(
[version] => 12.0.1.5
[versionstring] => Nextcloud 12.0.1
[url] => https://download.nextcloud.com/server/prereleases/nextcloud-12.0.1.zip
[web] => https://docs.nextcloud.com/server/11/admin_manual/maintenance/upgrade.html
[autoupdater] => 1
[signature] => R6+aQoW/L0L7RyM/ER06kH7XJHyskvmuOHcUKIydWGbFN1PQTjblqXiiUcsmFtsD
+ZLeiPtWg3wquzuA3GWk7vrJrRvIKguULBEdtaDv76jeOxX8IVtPZYyq9ywSleHU
qd9CCurtREBZVmaQLy79+aXvan+pSvq4f9kl9jVVDp/v9QDpaHSLtKrUCHGgyQZO
0APf4QTMn+Jlw40JD3vbQSPkxWb7dcQEE6gGg6htN7iLHRRVXf8sJWFrLGotCHCH
RVY+A9o0d/+e49hXBsqNA03y1ZETQkVle1X7618aFj+Rfekq+yANXG1w2yD69Erv
DB8RQvd5QS/1Igt4LyTdMw==
)

2017-08-11T21:53:18+0200 bd1564kdmB [info] checkForUpdate() Array
(
[version] => 12.0.1.5
[versionstring] => Nextcloud 12.0.1
[url] => https://download.nextcloud.com/server/prereleases/nextcloud-12.0.1.zip
[web] => https://docs.nextcloud.com/server/11/admin_manual/maintenance/upgrade.html
[autoupdater] => 1
[signature] => R6+aQoW/L0L7RyM/ER06kH7XJHyskvmuOHcUKIydWGbFN1PQTjblqXiiUcsmFtsD
+ZLeiPtWg3wquzuA3GWk7vrJrRvIKguULBEdtaDv76jeOxX8IVtPZYyq9ywSleHU
qd9CCurtREBZVmaQLy79+aXvan+pSvq4f9kl9jVVDp/v9QDpaHSLtKrUCHGgyQZO
0APf4QTMn+Jlw40JD3vbQSPkxWb7dcQEE6gGg6htN7iLHRRVXf8sJWFrLGotCHCH
RVY+A9o0d/+e49hXBsqNA03y1ZETQkVle1X7618aFj+Rfekq+yANXG1w2yD69Erv
DB8RQvd5QS/1Igt4LyTdMw==
)

2017-08-11T21:53:19+0200 bd1564kdmB [info] end of checkForUpdate() Update to Nextcloud 12.0.1 available. (channel: “stable”)
Following file will be downloaded automatically: https://download.nextcloud.com/server/prereleases/nextcloud-12.0.1.zip
2017-08-11T21:53:22+0200 U27FhCejSu [info] request to updater
2017-08-11T21:53:22+0200 U27FhCejSu [info] currentStep()
2017-08-11T21:53:22+0200 U27FhCejSu [info] POST request for step "1"
2017-08-11T21:53:23+0200 U27FhCejSu [info] startStep(“1”)
2017-08-11T21:53:23+0200 U27FhCejSu [info] checkForExpectedFilesAndFolders()
2017-08-11T21:53:23+0200 U27FhCejSu [info] end of checkForExpectedFilesAndFolders()
2017-08-11T21:53:23+0200 U27FhCejSu [info] endStep(“1”)
2017-08-11T21:53:23+0200 6AvkqBCUGg [info] request to updater
2017-08-11T21:53:23+0200 6AvkqBCUGg [info] currentStep()
2017-08-11T21:53:23+0200 6AvkqBCUGg [info] Step 1 is in state “end”.
2017-08-11T21:53:24+0200 6AvkqBCUGg [info] POST request for step "2"
2017-08-11T21:53:24+0200 6AvkqBCUGg [info] startStep(“2”)
2017-08-11T21:53:24+0200 6AvkqBCUGg [info] checkWritePermissions()
2017-08-11T21:53:24+0200 6AvkqBCUGg [info] end of checkWritePermissions()
2017-08-11T21:53:24+0200 6AvkqBCUGg [info] endStep(“2”)
2017-08-11T21:53:24+0200 oSupYBuiOQ [info] request to updater
2017-08-11T21:53:24+0200 oSupYBuiOQ [info] currentStep()
2017-08-11T21:53:24+0200 oSupYBuiOQ [info] Step 2 is in state “end”.
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] POST request for step "3"
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] startStep(“3”)
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] setMaintenanceMode(“true”)
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] configFileName /etc/nextcloud/config.php
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] end of setMaintenanceMode()
2017-08-11T21:53:25+0200 oSupYBuiOQ [info] endStep(“3”)
2017-08-11T21:53:25+0200 UIT1oaDCuw [info] request to updater
2017-08-11T21:53:26+0200 UIT1oaDCuw [info] currentStep()
2017-08-11T21:53:26+0200 UIT1oaDCuw [info] Step 3 is in state “end”.
2017-08-11T21:53:26+0200 UIT1oaDCuw [info] POST request for step "4"
2017-08-11T21:53:26+0200 UIT1oaDCuw [info] startStep(“4”)
2017-08-11T21:53:26+0200 UIT1oaDCuw [info] createBackup()
2017-08-11T22:20:46+0200 UIT1oaDCuw [info] end of createBackup()
2017-08-11T22:20:47+0200 UIT1oaDCuw [info] endStep(“4”)
2017-08-11T22:20:47+0200 7A7CVxeysV [info] request to updater
2017-08-11T22:20:47+0200 7A7CVxeysV [info] currentStep()
2017-08-11T22:20:47+0200 7A7CVxeysV [info] Step 4 is in state “end”.
2017-08-11T22:20:47+0200 7A7CVxeysV [info] POST request for step "5"
2017-08-11T22:20:47+0200 7A7CVxeysV [info] startStep(“5”)
2017-08-11T22:20:47+0200 7A7CVxeysV [info] downloadUpdate()
2017-08-11T22:20:47+0200 7A7CVxeysV [info] getUpdateServerResponse()
2017-08-11T22:20:48+0200 7A7CVxeysV [info] updaterServer: https://updates.nextcloud.org/updater_server/
2017-08-11T22:20:48+0200 7A7CVxeysV [info] releaseChannel: stable
2017-08-11T22:20:48+0200 7A7CVxeysV [info] internal version: 12.0.0.29
2017-08-11T22:20:48+0200 7A7CVxeysV [info] updateURL: https://updates.nextcloud.org/updater_server/?version=12x0x0x29xxxstablexx2017-05-22T08%3A27%3A00%2B00%3A00+98e26f8b5c8b238e7f3556e900c524ce78bde95ax7x0x18
2017-08-11T22:20:48+0200 7A7CVxeysV [info] getUpdateServerResponse response: Array
(
[version] => 12.0.1.5
[versionstring] => Nextcloud 12.0.1
[url] => https://download.nextcloud.com/server/prereleases/nextcloud-12.0.1.zip
[web] => https://docs.nextcloud.com/server/11/admin_manual/maintenance/upgrade.html
[autoupdater] => 1
[signature] => R6+aQoW/L0L7RyM/ER06kH7XJHyskvmuOHcUKIydWGbFN1PQTjblqXiiUcsmFtsD
+ZLeiPtWg3wquzuA3GWk7vrJrRvIKguULBEdtaDv76jeOxX8IVtPZYyq9ywSleHU
qd9CCurtREBZVmaQLy79+aXvan+pSvq4f9kl9jVVDp/v9QDpaHSLtKrUCHGgyQZO
0APf4QTMn+Jlw40JD3vbQSPkxWb7dcQEE6gGg6htN7iLHRRVXf8sJWFrLGotCHCH
RVY+A9o0d/+e49hXBsqNA03y1ZETQkVle1X7618aFj+Rfekq+yANXG1w2yD69Erv
DB8RQvd5QS/1Igt4LyTdMw==
)

2017-08-11T22:20:48+0200 7A7CVxeysV [info] storage location exists
2017-08-11T22:21:55+0200 7A7CVxeysV [info] end of downloadUpdate()
2017-08-11T22:21:55+0200 7A7CVxeysV [info] endStep(“5”)
2017-08-11T22:21:55+0200 OQNjgLUK4I [info] request to updater
2017-08-11T22:21:55+0200 OQNjgLUK4I [info] currentStep()
2017-08-11T22:21:55+0200 OQNjgLUK4I [info] Step 5 is in state “end”.
2017-08-11T22:21:55+0200 OQNjgLUK4I [info] POST request for step "6"
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] startStep(“6”)
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] verifyIntegrity()
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] getUpdateServerResponse()
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] updaterServer: https://updates.nextcloud.org/updater_server/
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] releaseChannel: stable
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] internal version: 12.0.0.29
2017-08-11T22:21:56+0200 OQNjgLUK4I [info] updateURL: https://updates.nextcloud.org/updater_server/?version=12x0x0x29xxxstablexx2017-05-22T08%3A27%3A00%2B00%3A00+98e26f8b5c8b238e7f3556e900c524ce78bde95ax7x0x18
2017-08-11T22:21:58+0200 OQNjgLUK4I [info] getUpdateServerResponse response: Array
(
[version] => 12.0.1.5
[versionstring] => Nextcloud 12.0.1
[url] => https://download.nextcloud.com/server/prereleases/nextcloud-12.0.1.zip
[web] => https://docs.nextcloud.com/server/11/admin_manual/maintenance/upgrade.html
[autoupdater] => 1
[signature] => R6+aQoW/L0L7RyM/ER06kH7XJHyskvmuOHcUKIydWGbFN1PQTjblqXiiUcsmFtsD
+ZLeiPtWg3wquzuA3GWk7vrJrRvIKguULBEdtaDv76jeOxX8IVtPZYyq9ywSleHU
qd9CCurtREBZVmaQLy79+aXvan+pSvq4f9kl9jVVDp/v9QDpaHSLtKrUCHGgyQZO
0APf4QTMn+Jlw40JD3vbQSPkxWb7dcQEE6gGg6htN7iLHRRVXf8sJWFrLGotCHCH
RVY+A9o0d/+e49hXBsqNA03y1ZETQkVle1X7618aFj+Rfekq+yANXG1w2yD69Erv
DB8RQvd5QS/1Igt4LyTdMw==
)

2017-08-11T22:21:58+0200 OQNjgLUK4I [info] storage location: /mnt/cloud/owncloud/data//updater-oc6xfwx9u4yr/downloads/
2017-08-11T22:21:58+0200 OQNjgLUK4I [info] end of verifyIntegrity()
2017-08-11T22:21:58+0200 OQNjgLUK4I [info] endStep(“6”)
2017-08-11T22:21:58+0200 BYruZPFDs9 [info] request to updater
2017-08-11T22:21:58+0200 BYruZPFDs9 [info] currentStep()
2017-08-11T22:21:59+0200 BYruZPFDs9 [info] Step 6 is in state “end”.
2017-08-11T22:21:59+0200 BYruZPFDs9 [info] POST request for step "7"
2017-08-11T22:21:59+0200 BYruZPFDs9 [info] startStep(“7”)
2017-08-11T22:21:59+0200 BYruZPFDs9 [info] extractDownload()
2017-08-11T22:21:59+0200 BYruZPFDs9 [info] storage location: /mnt/cloud/owncloud/data//updater-oc6xfwx9u4yr/downloads/
2017-08-11T22:41:37+0200 BYruZPFDs9 [info] end of extractDownload()
2017-08-11T22:41:37+0200 BYruZPFDs9 [info] endStep(“7”)
2017-08-11T22:41:37+0200 azKhcFPqdh [info] request to updater
2017-08-11T22:41:38+0200 azKhcFPqdh [info] currentStep()
2017-08-11T22:41:38+0200 azKhcFPqdh [info] Step 7 is in state “end”.
2017-08-11T22:41:38+0200 azKhcFPqdh [info] POST request for step "8"
2017-08-11T22:41:38+0200 azKhcFPqdh [info] startStep(“8”)
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replaceEntryPoints()
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replace index.php
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replace status.php
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replace remote.php
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replace public.php
2017-08-11T22:41:38+0200 azKhcFPqdh [info] replace ocs/v1.php
2017-08-11T22:41:39+0200 azKhcFPqdh [info] replace ocs/v2.php
2017-08-11T22:41:39+0200 azKhcFPqdh [info] end of replaceEntryPoints()
2017-08-11T22:41:39+0200 azKhcFPqdh [info] endStep(“8”)
2017-08-11T22:41:39+0200 l289lpVf9Z [info] request to updater
2017-08-11T22:41:39+0200 l289lpVf9Z [info] currentStep()
2017-08-11T22:41:39+0200 l289lpVf9Z [info] Step 8 is in state “end”.
2017-08-11T22:41:39+0200 l289lpVf9Z [info] POST request for step "9"
2017-08-11T22:41:39+0200 l289lpVf9Z [info] startStep(“9”)
2017-08-11T22:41:39+0200 l289lpVf9Z [info] deleteOldFiles()
2017-08-11T22:41:40+0200 l289lpVf9Z [info] config sample exists
2017-08-11T22:41:40+0200 l289lpVf9Z [info] thmes README exists
2017-08-11T22:41:40+0200 l289lpVf9Z [info] end of deleteOldFiles()
2017-08-11T22:41:40+0200 l289lpVf9Z [info] endStep(“9”)
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] request to updater
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] currentStep()
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] Step 9 is in state “end”.
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] POST request for step "10"
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] startStep(“10”)
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] moveNewVersionInPlace()
2017-08-11T22:41:41+0200 YLYqfXgVBJ [info] storage location: /mnt/cloud/owncloud/data//updater-oc6xfwx9u4yr/downloads/nextcloud/
2017-08-11T22:43:01+0200 YLYqfXgVBJ [info] end of moveNewVersionInPlace()
2017-08-11T22:43:01+0200 YLYqfXgVBJ [info] endStep(“10”)
2017-08-11T22:43:08+0200 e92QslX8Gk [info] request to updater
2017-08-11T22:43:08+0200 e92QslX8Gk [info] currentStep()
2017-08-11T22:43:08+0200 e92QslX8Gk [info] Step 10 is in state “end”.
2017-08-11T22:43:08+0200 e92QslX8Gk [info] POST request for step "12"
2017-08-11T22:43:09+0200 e92QslX8Gk [info] startStep(“12”)
2017-08-11T22:43:09+0200 e92QslX8Gk [info] finalize()
2017-08-11T22:43:09+0200 e92QslX8Gk [info] storage location: /mnt/cloud/owncloud/data//updater-oc6xfwx9u4yr/downloads/nextcloud/
2017-08-11T22:43:09+0200 e92QslX8Gk [info] end of finalize()
2017-08-11T22:43:09+0200 e92QslX8Gk [info] endStep(“12”)

Mehlstaub · August 25, 2017, 8:48am

same for update from 12.0.1 to 12.0.2

kentw · February 3, 2018, 1:21pm

I just got back to this issue. I am updating to the latest 12.05 version. I have htop running and there is very little load from what I can tell. iotop running is giving anywhere from 70K/s to 150K/s write speeds. I am in the “backup” portion of the upgrade. This always takes 20-30 minutes.

My storage is connected via an NFS share running a Linux Raid 1 array. This connection doesn’t seem to be a bottle neck during normal use. Locally I can transfer a gig file to the nextcloud site in 20-30 seconds. I would think it has to do with transferring all the individual files to the backup. If they were zipped or tared first the transfer would be quick maybe. Just my thoughts.

Just went into the Extracting portion of the upgrade. I am seeing hits into the 400+ K/s (still not sure exactally what unit that is?) Kilobyte, Kilobit, Kibbi would be nice if that were more clear in iotop.

Extracting can take 20-30 minutes as well on my setup.

Apollo13 · November 19, 2020, 11:09am

Any news on that? I know this thread is a little dusty but I am facing the exact same problem with my setup. To me it seems that having the data directory on an NFS share could be the reason for this delay. iotop, top, htop all show only very low usage.
On systems where the data directory resides on the same disk/partition as the nextcloud code I don’t have those problems at all…

What is this backup step in the updater actually doing? Is it scanning the content of the data directory?

EDIT: And as I can see in the extraction step the downloaded data gets extracted to the data directory as well - but depending on the configuration many small packets can be kind of a problem for NFS…

Guillermo · November 24, 2020, 5:52pm

I agree.
Nextcloud upgrade via web is still slow because an alternate directory cannot be specified to backup the installation. In my case the code resides on a local SSD disk and the data resides on a GlusterFS server and in normal use I have no performance problems. However, updates via web, which make backup in the data directory, take a long time.

f.sell · October 11, 2023, 9:53am

Just updating 27.1.1 to 27.1.2 via updater.par

Backup: took >2 hours
Extracting: is very slow.
Delete old files: only sporadic access to disk

iotop:
Total DISK READ: 0.00 B/s | Total DISK WRITE: 45.70 K/s
Current DISK READ: 0.00 B/s | Current DISK WRITE: 3.81 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
1192 be/4 www-data 0.00 B/s 45.70 K/s 0.00 % 24.26 % php upda~ater.phar

Normaly write on disk is >100G/s

This can’t be normal!

f.sell · October 12, 2023, 7:13am

It seems that I found a solution.

NextCloud doesn’t like to delete old backups manually in the /data/updater-…/backups directory.

It becomes fatal if you do this while the updater is running. Then everything stands and the new backup directory stops at a fill level of ~64MB.

Mallet method:

kill updater;
delete all backup directories;
in the directory ‘/data/updater-…/’ delete the ‘.step*’ files;
restart updater;

Backup then takes about 5min for me.

jtr · October 13, 2023, 1:49pm

Are you saying you were cleaning up the old backup directories while (i.e. at the same time as) the updater was running and that was triggering this situation?

If you get a chance, it would be interesting to see your updater.log for that updater run. It might have some clues. The log file will be located in your datadirectory (same spot where nextcloud.log gets placed by default).

If you see a legitimate bug related to the updater, or believe you have a suggestion for possible optimization, there is a repository specifically for those observations/ideas here: Issues · nextcloud/updater · GitHub