From 28b55bba55cb0124d3ad00e5c48a9afe70cd52d3 Mon Sep 17 00:00:00 2001 From: Joas Schilling Date: Wed, 20 Dec 2023 10:58:08 +0100 Subject: [PATCH 1/2] feat(cron): Warn on excessive memory consumption in background jobs Signed-off-by: Joas Schilling --- cron.php | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/cron.php b/cron.php index 7d661621ed090..41c5157befa9d 100644 --- a/cron.php +++ b/cron.php @@ -149,8 +149,22 @@ } $logger->debug('CLI cron call has selected job with ID ' . strval($job->getId()), ['app' => 'cron']); + + $memoryBefore = memory_get_usage(); + $memoryPeakBefore = memory_get_peak_usage(); + $job->execute($jobList, $logger); + $memoryAfter = memory_get_usage(); + $memoryPeakAfter = memory_get_peak_usage(); + + if ($memoryAfter - $memoryBefore > 10_000_000) { + $logger->warning('Used memory grew by more than 10 MB when executing job ' . get_class($job) . ' : ' . \OCP\Util::humanFileSize($memoryAfter). ' (before: ' . \OCP\Util::humanFileSize($memoryBefore) . ')', ['app' => 'cron']); + } + if ($memoryPeakAfter > 300_000_000) { + $logger->warning('Cron job used more than 300 MB of ram after executing job ' . get_class($job) . ': ' . \OCP\Util::humanFileSize($memoryPeakAfter) . ' (before: ' . \OCP\Util::humanFileSize($memoryPeakBefore) . ')', ['app' => 'cron']); + } + // clean up after unclean jobs \OC_Util::tearDownFS(); $tempManager->clean(); From b8c57efaad12461efdb0f3778594b71952793577 Mon Sep 17 00:00:00 2001 From: Joas Schilling Date: Wed, 20 Dec 2023 15:35:40 +0100 Subject: [PATCH 2/2] fix(log): Improve logging of background job details for better reproduction/debugging Signed-off-by: Joas Schilling --- cron.php | 7 ++++--- lib/public/BackgroundJob/Job.php | 7 ++++--- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/cron.php b/cron.php index 41c5157befa9d..a6716a68714df 100644 --- a/cron.php +++ b/cron.php @@ -148,7 +148,8 @@ break; } - $logger->debug('CLI cron call has selected job with ID ' . strval($job->getId()), ['app' => 'cron']); + $jobDetails = get_class($this) . ' (id: ' . $this->getId() . ', arguments: ' . json_encode($this->getArgument()) . ')'; + $logger->debug('CLI cron call has selected job ' . $jobDetails, ['app' => 'cron']); $memoryBefore = memory_get_usage(); $memoryPeakBefore = memory_get_peak_usage(); @@ -159,10 +160,10 @@ $memoryPeakAfter = memory_get_peak_usage(); if ($memoryAfter - $memoryBefore > 10_000_000) { - $logger->warning('Used memory grew by more than 10 MB when executing job ' . get_class($job) . ' : ' . \OCP\Util::humanFileSize($memoryAfter). ' (before: ' . \OCP\Util::humanFileSize($memoryBefore) . ')', ['app' => 'cron']); + $logger->warning('Used memory grew by more than 10 MB when executing job ' . $jobDetails . ': ' . \OCP\Util::humanFileSize($memoryAfter). ' (before: ' . \OCP\Util::humanFileSize($memoryBefore) . ')', ['app' => 'cron']); } if ($memoryPeakAfter > 300_000_000) { - $logger->warning('Cron job used more than 300 MB of ram after executing job ' . get_class($job) . ': ' . \OCP\Util::humanFileSize($memoryPeakAfter) . ' (before: ' . \OCP\Util::humanFileSize($memoryPeakBefore) . ')', ['app' => 'cron']); + $logger->warning('Cron job used more than 300 MB of ram after executing job ' . $jobDetails . ': ' . \OCP\Util::humanFileSize($memoryPeakAfter) . ' (before: ' . \OCP\Util::humanFileSize($memoryPeakBefore) . ')', ['app' => 'cron']); } // clean up after unclean jobs diff --git a/lib/public/BackgroundJob/Job.php b/lib/public/BackgroundJob/Job.php index a574e90e1a043..2842486b74d8a 100644 --- a/lib/public/BackgroundJob/Job.php +++ b/lib/public/BackgroundJob/Job.php @@ -76,16 +76,17 @@ public function start(IJobList $jobList): void { $logger = $this->logger ?? \OCP\Server::get(LoggerInterface::class); try { + $jobDetails = get_class($this) . ' (id: ' . $this->getId() . ', arguments: ' . json_encode($this->getArgument()) . ')'; $jobStartTime = $this->time->getTime(); - $logger->debug('Run ' . get_class($this) . ' job with ID ' . $this->getId(), ['app' => 'cron']); + $logger->debug('Starting job ' . $jobDetails, ['app' => 'cron']); $this->run($this->argument); $timeTaken = $this->time->getTime() - $jobStartTime; - $logger->debug('Finished ' . get_class($this) . ' job with ID ' . $this->getId() . ' in ' . $timeTaken . ' seconds', ['app' => 'cron']); + $logger->debug('Finished job ' . $jobDetails . ' in ' . $timeTaken . ' seconds', ['app' => 'cron']); $jobList->setExecutionTime($this, $timeTaken); } catch (\Throwable $e) { if ($logger) { - $logger->error('Error while running background job (class: ' . get_class($this) . ', arguments: ' . print_r($this->argument, true) . ')', [ + $logger->error('Error while running background job ' . $jobDetails, [ 'app' => 'core', 'exception' => $e, ]);