SetupCheck is taking too long / Detect and log slow running setup checks

[nickvergessen]

On our instance the setup check did almost not finish.
I added var_dump(time() . $setupCheck->getService()); in the SetupCheckManager to find out it's actually the log reader taking all the time.
Our nextcloud.log.1 and nextcloud.log files are ~101MB both and the SetupCheck takes almost 20 minutes:

string(59) "1709933440 - OCA\DAV\SetupChecks\NeedsSystemAddressBookSync"
string(48) "1709933440 - OCA\LogReader\SetupChecks\LogErrors" <--------- WATCH THIS
string(70) "1709934599 - OCA\Notifications\Settings\SetupWarningOnRateLimitReached"
string(63) "1709934599 - OCA\Settings\SetupChecks\AppDirsWithDifferentOwner"
string(57) "1709934599 - OCA\Settings\SetupChecks\BruteForceThrottler"
string(59) "1709934599 - OCA\Settings\SetupChecks\CheckUserCertificates"
string(51) "1709934599 - OCA\Settings\SetupChecks\CodeIntegrity"
string(48) "1709934599 - OCA\Settings\SetupChecks\CronErrors"
string(46) "1709934599 - OCA\Settings\SetupChecks\CronInfo"
string(63) "1709934599 - OCA\Settings\SetupChecks\DatabaseHasMissingColumns"
string(63) "1709934599 - OCA\Settings\SetupChecks\DatabaseHasMissingIndices"
string(67) "1709934599 - OCA\Settings\SetupChecks\DatabaseHasMissingPrimaryKeys"
string(70) "1709934600 - OCA\Settings\SetupChecks\DatabasePendingBigIntConversions"
string(59) "1709934600 - OCA\Settings\SetupChecks\DefaultPhoneRegionSet"
string(57) "1709934600 - OCA\Settings\SetupChecks\EmailTestSuccessful"
string(49) "1709934600 - OCA\Settings\SetupChecks\FileLocking"
string(57) "1709934600 - OCA\Settings\SetupChecks\ForwardedForHeaders"
string(58) "1709934600 - OCA\Settings\SetupChecks\InternetConnectivity"
string(55) "1709934600 - OCA\Settings\SetupChecks\JavaScriptModules"
string(56) "1709934600 - OCA\Settings\SetupChecks\LegacySSEKeyFormat"
string(60) "1709934600 - OCA\Settings\SetupChecks\MaintenanceWindowStart"
string(56) "1709934600 - OCA\Settings\SetupChecks\MemcacheConfigured"
string(53) "1709934600 - OCA\Settings\SetupChecks\OverwriteCliUrl"
string(55) "1709934600 - OCA\Settings\SetupChecks\PhpDefaultCharset"
string(56) "1709934600 - OCA\Settings\SetupChecks\PhpFreetypeSupport"
string(47) "1709934600 - OCA\Settings\SetupChecks\PhpGetEnv"
string(52) "1709934600 - OCA\Settings\SetupChecks\PhpMemoryLimit"
string(48) "1709934600 - OCA\Settings\SetupChecks\PhpModules"
string(53) "1709934600 - OCA\Settings\SetupChecks\PhpOpcacheSetup"
string(49) "1709934600 - OCA\Settings\SetupChecks\PhpOutdated"
string(56) "1709934600 - OCA\Settings\SetupChecks\PhpOutputBuffering"
string(54) "1709934600 - OCA\Settings\SetupChecks\RandomnessSecure"
string(52) "1709934600 - OCA\Settings\SetupChecks\ReadOnlyConfig"
string(55) "1709934600 - OCA\Settings\SetupChecks\SupportedDatabase"
string(51) "1709934600 - OCA\Settings\SetupChecks\SystemIs64bit"
string(58) "1709934600 - OCA\Settings\SetupChecks\TransactionIsolation"
string(55) "1709934600 - OCA\SttWhisper\SetupChecks\ModelFilesCheck"
string(56) "1709934600 - OCA\SttWhisper\SetupChecks\BinaryFilesCheck"
string(53) "1709934600 - OCA\Theming\SetupChecks\PhpImagickModule"
string(57) "1709934600 - OCA\Translate\SetupChecks\MachineSupportsAvx"
string(55) "1709934600 - OCA\Translate\SetupChecks\ModelsDownloaded"
string(50) "1709934600 - OCA\Translate\SetupChecks\NodejsWorks"
string(55) "1709934600 - OCA\User_LDAP\SetupChecks\LdapInvalidUuids"

1.159 seconds = 19 minutes and 19 seconds...

This is not really acceptable.

I think we should skip the setupcheck when the file is bigger then 5 MB or something (home server level size), or we need to change it to simply grep | wc -l, but looping over the file in PHP and json decoding each line does not scale.

[nickvergessen]

Should also build a check into the server code, that it logs an warning (> 5/10 seconds) or error (> 60 seconds) when a setupcheck is taking too long

[come-nc]

@nickvergessen Note that there is already a log line for this purpose: $this->logger->debug('Running check '.get_class($setupCheckObject));
So with debug log level you can look at the timestamp of these lines in the log and see which one is taking long.

[nickvergessen]

So with debug log level you can look at the timestamp of these lines in the log and see which one is taking long.

I can't really enable debug on production :D

[come-nc]

So with debug log level you can look at the timestamp of these lines in the log and see which one is taking long.

I can't really enable debug on production :D

You can on a single occ run with env var NC_loglevel=0

[nickvergessen]

yeah, anyway error logging very long running setupchecks sounds still good :)
Sample:
https://github.com/nextcloud/server/blob/131f481a67766d9bc5629948cc0abe1424308f00/lib/private/InitialStateService.php#L91-L101

[icewind1991]

#1179 should speed things up a bunch

[Mat-DB]

Hi,

Is this issue fixed?
I am experiencing something similar on nextcloud 29.0.7

When going to the admin -> overview I get Error occurred whilst checking server setup and when I run occ setupchecks it takes 1min8sec to complete.

Thanks for looking into this!

[come-nc]

Hi,

Is this issue fixed? I am experiencing something similar on nextcloud 29.0.7

When going to the admin -> overview I get Error occurred whilst checking server setup and when I run occ setupchecks it takes 1min8sec to complete.

Thanks for looking into this!

This issue was fixed for logreader with PR #1178
Maybe you can run your setup checks with loglevel debug and see if you manage to see in the logs which check is taking so long?

[Mat-DB]

I updated to 29.0.8 and it is solved!
Apologies for reacting before updating.

[joshtrichards]

@Mat-DB It's alright. The issue is still sitting open so it's understandable. :)

Seems we could close this with #1178 and #1179 being in place. I think this is still open to remind us about the idea to add automated detection and non-debug level logging of overly slow running setup checks here:

https://github.com/nextcloud/server/blob/5be832344eacb8328600d256c3090671c3f582d2/lib/private/SetupCheck/SetupCheckManager.php#L29-L38

to be kind of like we already do here, as @nickvergessen mentioned:

https://github.com/nextcloud/server/blob/131f481a67766d9bc5629948cc0abe1424308f00/lib/private/InitialStateService.php#L91-L101