From 6ac65e547281639edeeece8442c0f35f323cff54 Mon Sep 17 00:00:00 2001 From: Celeo Date: Sun, 19 Jul 2026 14:21:36 -0700 Subject: [PATCH] Fix moodle:sync piling up overlapping instances via category-fetch N+1 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The api-worker pod was found running 4 concurrent, still-alive moodle:sync processes stacked ~3 hours apart (elapsed 11h41m/8h41m/5h41m/2h41m), each holding ~55-63MB RSS. moodle:sync is scheduled every 3 hours with a 120-minute withoutOverlapping() lock; once a run's wall-clock time exceeds that lock, the scheduler treats the slot as free and starts a new instance on the next tick even though the previous one is still running. Nothing kills the stale runs, so they pile up indefinitely. Root cause: MoodleSync::sync() calls VATUSAMoodle::getCategoryFromShort() 5 times per user, and every call re-fetches Moodle's entire category tree live via getCategories() — a full HTTP round-trip that's identical on every call within a single run. For a large user table this N+1 is almost certainly what pushes total runtime past the 120-minute lock. Per api/CLAUDE.md, the 120/60-minute withoutOverlapping() windows on moodle:sync/moodle:competency were deliberately shortened (commit a324474) so an orphaned lock self-heals in ~1-2h instead of Laravel's 24h default - lengthening them back would reintroduce that problem, so this fix instead makes the job's real runtime reliably fit inside the existing window. - VATUSAMoodle::getCategories() now memoizes its result for the lifetime of the instance. The same instance is injected once into MoodleSync and reused across its whole User::chunk() loop, so this collapses up to 5x live fetches per user down to 1 for the entire run, with no change to which categories/roles get assigned. - VATUSAMoodle::request() now bounds every Moodle HTTP call to 30s via a scoped default_socket_timeout (save/restore per call, since that ini setting is process-global and also touches predis). The vendored MoodleRest package has no explicit timeout and otherwise falls back to PHP's 60s default. - Kernel.php's before/after scheduler hooks now bridge elapsed time via Cache instead of a shared closure variable, since runInBackground() events run their 'after' hook in a separate schedule:finish process with no memory in common with schedule:work. Logs a WARN if moodle:sync/ moodle:competency exceed 75% of their respective lock windows (90/45 min), so a future regression surfaces as a log line instead of another live-pod investigation. Explicitly out of scope: the withoutOverlapping() windows themselves, MoodleCompetency.php (doesn't share the getCategories() N+1 and wasn't observed stacked), and parallelizing the remaining per-user Moodle calls (no production data to justify it yet - the new WARN log exists to catch that if the N+1 fix alone isn't sufficient). Co-Authored-By: Claude Sonnet 5 --- app/Classes/VATUSAMoodle.php | 38 +++++++++++++++++++++++++++++++++++- app/Console/Kernel.php | 32 ++++++++++++++++++++++-------- 2 files changed, 61 insertions(+), 9 deletions(-) diff --git a/app/Classes/VATUSAMoodle.php b/app/Classes/VATUSAMoodle.php index 652bba2..24a7e85 100644 --- a/app/Classes/VATUSAMoodle.php +++ b/app/Classes/VATUSAMoodle.php @@ -53,6 +53,12 @@ class VATUSAMoodle extends MoodleRest private $isTest; + /** @var array|null Memoized result of getCategories() for the lifetime of this instance */ + private $categoriesCache = null; + + /** @var int Seconds to bound each Moodle HTTP request to */ + private const HTTP_TIMEOUT_SECONDS = 30; + /** * VATUSAMoodle constructor. * @@ -91,6 +97,32 @@ public function setSSO(bool $isSSO = true) } } + /** + * Make the request, with a bounded HTTP timeout. + * + * The vendored MoodleRest::request() uses file_get_contents()/stream contexts with no + * explicit timeout, so it silently falls back to PHP's default_socket_timeout ini + * (60s, not guaranteed). Scope an explicit timeout tightly around each individual call + * rather than setting it once for the process, since default_socket_timeout is a + * process-global ini setting also consulted by predis (CACHE_DRIVER=redis). + * + * @param string $function + * @param array|null $parameters + * @param string $method + * + * @return mixed + * @throws \Exception + */ + public function request($function, $parameters = null, $method = self::METHOD_GET) + { + $previous = ini_set('default_socket_timeout', self::HTTP_TIMEOUT_SECONDS); + try { + return parent::request($function, $parameters, $method); + } finally { + ini_set('default_socket_timeout', $previous); + } + } + /** * Get all Cohorts * @return mixed @@ -124,7 +156,11 @@ public function getCohortMembers(): array */ public function getCategories() { - return $this->request("core_course_get_categories"); + if ($this->categoriesCache === null) { + $this->categoriesCache = $this->request("core_course_get_categories"); + } + + return $this->categoriesCache; } /** diff --git a/app/Console/Kernel.php b/app/Console/Kernel.php index 192fa85..a0063e2 100644 --- a/app/Console/Kernel.php +++ b/app/Console/Kernel.php @@ -4,6 +4,8 @@ use Illuminate\Console\Scheduling\Schedule; use Illuminate\Foundation\Console\Kernel as ConsoleKernel; +use Illuminate\Support\Facades\Cache; +use Illuminate\Support\Facades\Log; class Kernel extends ConsoleKernel { @@ -30,18 +32,32 @@ class Kernel extends ConsoleKernel */ protected function schedule(Schedule $schedule) { - // Helper function to create a 'before' hook closure with the command name + // Helper function to create a 'before' hook closure with the command name. + // Records the start time in cache (not a shared closure variable) because + // runInBackground() events run their 'after' hook in a separate, freshly-booted + // `schedule:finish` process with no memory in common with this one. $createBeforeHook = function (string $commandName) { return function () use ($commandName) { - // Use logger() or Log::info() etc. logger("Starting scheduled task: {$commandName}"); + Cache::put("schedule:started:{$commandName}", now(), now()->addHours(6)); }; }; - // Helper function to create an 'after' hook closure with the command name - $createAfterHook = function (string $commandName) { - return function () use ($commandName) { - logger("Finished scheduled task: {$commandName}"); + // Helper function to create an 'after' hook closure with the command name. + // $warnAfterMinutes, when given, logs a WARN if the run exceeded that duration — + // used for commands with a withoutOverlapping() lock window to catch a run + // approaching that window before it starts stacking overlapping instances. + $createAfterHook = function (string $commandName, ?int $warnAfterMinutes = null) { + return function () use ($commandName, $warnAfterMinutes) { + $startedAt = Cache::pull("schedule:started:{$commandName}"); + $elapsedMinutes = $startedAt ? round(now()->diffInSeconds($startedAt) / 60, 1) : null; + + logger("Finished scheduled task: {$commandName}" . + ($elapsedMinutes !== null ? " ({$elapsedMinutes} min)" : "")); + + if ($warnAfterMinutes !== null && $elapsedMinutes !== null && $elapsedMinutes > $warnAfterMinutes) { + Log::warning("Scheduled task {$commandName} took {$elapsedMinutes} minutes, exceeding the {$warnAfterMinutes}-minute warn threshold."); + } }; }; @@ -60,7 +76,7 @@ protected function schedule(Schedule $schedule) ->runInBackground() ->withoutOverlapping(120) ->before($createBeforeHook($commandName)) - ->after($createAfterHook($commandName)); + ->after($createAfterHook($commandName, 90)); $commandName = 'vatsim:flights'; $schedule->command($commandName) @@ -86,7 +102,7 @@ protected function schedule(Schedule $schedule) ->withoutOverlapping(60) ->runInBackground() ->before($createBeforeHook($commandName)) - ->after($createAfterHook($commandName)); + ->after($createAfterHook($commandName, 45)); $commandName = "controller:eligibility"; $schedule->command($commandName)