Repository navigation
SetupCheck is taking too long / Detect and log slow running setup checks #1170
Description
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.
Activity
nickvergessen commentedon Mar 8, 2024
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 commentedon Mar 11, 2024
@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 commentedon Mar 11, 2024
I can't really enable debug on production :D
come-nc commentedon Mar 11, 2024
You can on a single occ run with env var
NC_loglevel=0nickvergessen commentedon Mar 11, 2024
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 commentedon Mar 11, 2024
#1179 should speed things up a bunch
Mat-DB commentedon Oct 10, 2024
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 setupand when I runocc setupchecksit takes 1min8sec to complete.Thanks for looking into this!
come-nc commentedon Oct 14, 2024
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 commentedon Oct 16, 2024
I updated to 29.0.8 and it is solved!
Apologies for reacting before updating.
joshtrichards commentedon Oct 16, 2024
@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
[-]SetupCheck is taking too long[/-][+]SetupCheck is taking too long / Detect and log slow running setup checks[/+]