# M1 — Nightly recommendation job failures ## 1. Executive Summary Production Horizon marks `RecComputeSimilarByBehaviorJob` and `RecComputeSimilarHybridJob` failed every night with `MaxAttemptsExceededException` at **~02:18** and **~02:31**. This is **not** the old 90-second Supervisor `queue:work` timeout. Production uses Horizon workers with **timeout=960**. The Redis queue connection has **`retry_after=90`**. A still-running nightly rebuild is treated as abandoned, re-queued, and Horizon `--tries=1` fails it. ```text ROOT-H — Redis retry_after (90s) shorter than job runtime, interacting with Horizon tries=1 and a single-job full-catalog scan (~50k artworks). ``` Local fix (not deployed): 1. Default `queue.connections.redis.retry_after` **1080** (> Horizon 960). 2. Fan-out Behavior and Hybrid rebuilds into cursor batches of 200, matching `RecComputeSimilarByTagsJob` (already chunked in production). Mail queue `LLEN=3` is **deferred** (not entangled). --- ## 2. Production Symptom ```text failed_jobs ≈ 329 RecComputeSimilarByBehaviorJob ~02:18 daily RecComputeSimilarHybridJob ~02:31 daily exception: Illuminate\Queue\MaxAttemptsExceededException "... has been attempted too many times." ``` Schedule (Europe/Ljubljana): | Job | dailyAt | | --- | ------- | | RecComputeSimilarByTagsJob | 02:00 | | RecComputeSimilarByBehaviorJob | 02:15 | | RecComputeSimilarHybridJob | 02:30 | Tags does **not** appear in the nightly failure list (already cursor-batched). --- ## 3. Production Evidence PRODUCTION SERVER (`ssh server3`, read-only): - `config('queue.connections.redis.retry_after')` = **90** - `config('horizon.defaults.supervisor-default.timeout')` = **960** - Horizon worker: `--queue=search --timeout=960 --tries=1 --memory=128` - `recommendations.queue` = `default` - CLI `memory_limit` = `-1` (Horizon 128 MB is post-job worker recycle, not the kill mechanism at 90s) - Failed exception text is MaxAttemptsExceeded **without** a wrapped `TimeoutExceededException` / memory error - Timing: ```text Behavior 02:15 dispatch → fail ~02:18 (~180s or ~90s after the minute the scheduler actually queued it) Hybrid 02:30 dispatch → fail ~02:31:33 (≈ retry_after 90s) ``` Laravel Redis queues use `retry_after` as the reservation TTL. If the job is still reserved after 90s, Redis exposes it again. The next pop has `attempts=2`. Horizon `--tries=1` then raises `MaxAttemptsExceededException` **before** the job body runs. That matches the Hybrid `tries=1` failure ~90 seconds after start. Behavior’s class `$tries=2` is overridden by the worker `--tries=1`. No production files, jobs, or services were changed during M1. --- ## 4. Local vs Production Code | Item | Production `5af95f65` | Local `f52879ed` (before M1) | | ---- | --------------------- | ---------------------------- | | RecComputeSimilarByBehaviorJob | `$tries=2`, `$timeout=600`, **full `chunkById` catalog** | same | | RecComputeSimilarHybridJob | `$tries=1`, `$timeout=900`, **full catalog**, WithoutOverlapping only per-artwork | same | | RecComputeSimilarByTagsJob | cursor `afterArtworkId` batches of 200 | same | | redis retry_after | 90 | 90 | Local did **not** already contain this fix. M1 implements it. --- ## 5. Job Architecture (after M1) Nightly catalog rebuild (`artworkId=null`): ```text load ≤ batchSize artworks after cursor → process each → if batch full, dispatch next job with afterArtworkId = last id ``` Per-artwork rebuilds (observers) unchanged: Hybrid still uses `WithoutOverlapping` + `dontRelease()`. | Job | tries | timeout | batch | | --- | ----: | ------: | ----: | | Behavior | 2 | 120s | 200 | | Hybrid | 1 | 180s | 200 | | Tags | 2 | 600s | 200 (already) | --- ## 6. Scheduler Flow Unchanged. `Schedule::job(...)->dailyAt(...)->withoutOverlapping()`. Behavior and Hybrid still start at 02:15 / 02:30; work continues as chained queue jobs instead of one 15+ minute reservation. Root crontab that invokes `schedule:run` remains unseen (sudo). Empirical evidence (nightly fails + 10:30 sitemap files) shows the scheduler **is** running. --- ## 7. Horizon Configuration Production supervisors unchanged in M1 (no deploy). Local comment on `supervisor-default.timeout` now documents that **`retry_after` must exceed 960**. Horizon `tries=1` remains. Batch jobs should finish well under 90s; `retry_after=1080` is the safety net for any remaining long job. --- ## 8. Failed Job Analysis Grouped: Behavior then Hybrid, every night, same exception. No payload dump. No evidence of immediate SQL exception (would usually wrap a QueryException). No SIGKILL/memory lines inspected in failed_jobs. Horizon log at inspection time showed healthy `IndexUserJob` / Scout jobs, not the 02:xx window. --- ## 9. Lock / Middleware Analysis Full-catalog Behavior: **no** WithoutOverlapping. Full-catalog Hybrid: `middleware()` returns `[]` when `artworkId === null`. **Not** the failure path. Scheduler `withoutOverlapping()` would **skip** dispatch, not fail a job. **Disproved:** `$tries=1` + WithoutOverlapping release as the nightly cause. **Proved:** Redis reservation TTL 90s vs long-running catalog job. --- ## 10. Runtime / Memory Analysis PHP CLI memory is unlimited. Horizon `--memory=128` typically exits **after** a job. A 50k-artwork in-memory scan could still grow, but the 90-second fail clock is Redis, not 128 MB. After chunking, each batch holds 200 models + pair rows, similar to the tags job that already succeeds. --- ## 11. Query Analysis Behavior, per artwork: - `UNION` on `rec_item_pairs` (`a_artwork_id` / `b_artwork_id` indexed) - `artworks` `whereIn` related ids - `updateOrCreate` on `rec_artwork_recs` ~50k × 3 queries in **one** reservation was unbounded vs 90s. No new index in M1. Chunking reduces reservation time; query shape unchanged. --- ## 12. Root Cause Classification ```text ROOT-H — Redis retry_after=90s < running catalog job + Horizon --tries=1 + Behavior/Hybrid process the full catalog in one job ``` Not ROOT-C (memory) as primary. Not ROOT-B (900s timeout) as the **observed** fail time (~90s). After fixing retry_after alone, ROOT-B could appear next (~600–900s). Chunking prevents that. --- ## 13. Fix 1. `config/queue.php` redis `retry_after` default **1080** (`REDIS_QUEUE_RETRY_AFTER`). 2. `.env.example` documents the production requirement. 3. Behavior + Hybrid catalog runs use the same cursor fan-out as Tags. 4. Structured batch logs: `duration_ms`, `memory_mb`, `processed`, `has_more` (no PII). 5. Per-artwork try/catch on Behavior (Hybrid already had it). Correctness: same scoring/persist per artwork; batches are sequential by `id`. Idempotent `updateOrCreate`. --- ## 14. Files Changed ```text config/queue.php config/horizon.php .env.example app/Jobs/RecComputeSimilarByBehaviorJob.php app/Jobs/RecComputeSimilarHybridJob.php tests/Unit/Jobs/RecComputeSimilarByBehaviorJobTest.php tests/Unit/Jobs/RecComputeSimilarHybridJobTest.php tests/Feature/Recommendations/RecComputeSimilarJobsTest.php docs/optimization-m1-recommendation-jobs.md ``` No migrations. --- ## 15. Tests ```text php artisan test --filter=RecComputeSimilar Tests: 13 passed (16 assertions) Duration: 15.67s ``` Covers retry_after vs Horizon timeout, cursor dispatch, partial batch no-dispatch, hybrid idempotency. Full suite not re-run (known unrelated failures from earlier audits). --- ## 16. Performance Impact Expected: many short default-queue jobs (~50k/200 ≈ 250 Behavior + 250 Hybrid) instead of two 15-minute jobs. Worker slots free between batches. Redis no longer duplicates in-flight catalog jobs. --- ## 17. Correctness Impact Same rec lists; order of artwork processing remains increasing `id`. A crash mid-chain can resume by re-dispatching from the last completed cursor (or wait for the next night). No silent catch-all. --- ## 18. Deployment Requirements ```text 1. Deploy this release (includes config/queue.php). 2. Set production .env REDIS_QUEUE_RETRY_AFTER=1080 if you pin the value (default in config is already 1080 if unset). 3. php artisan config:cache (normal deploy optimize). 4. Restart Horizon via the usual Supervisor restart / queue:restart. ``` Without restarting Horizon, workers keep old cached config. --- ## 19. Post-Deploy Verification ```text 1. php artisan horizon:status → running 2. php artisan tinker: config('queue.connections.redis.retry_after') === 1080 3. Next night: no new MaxAttemptsExceeded for RecComputeSimilarByBehavior/Hybrid 4. rec_artwork_recs computed_at advances for similar_behavior and similar_hybrid 5. Horizon log: "[RecComputeSimilarByBehavior] Batch complete" with has_more true then false 6. failed_jobs count not increasing for these classes 7. Optional: sample duration_ms / memory_mb ``` Do not retry the 329 historical failures unless product wants a one-off backfill; they are the old reservation pattern. --- ## 20. Rollback Plan ```text - Roll back the release symlink / previous release - config:cache + Horizon restart - No DB migration to roll back - Cursor jobs in flight may still complete; safe - No Redis lock cleanup required for catalog jobs ``` --- ## 21. Deferred Findings ```text DEFER TO M2/M1B: queues:mail LLEN=3, Horizon does not consume `mail` DEFER: sitemap index stale DEFER: artwork_metric_snapshots_hourly size DEFER: swap / FPM / Sentry sample rates ``` --- ## 22. Remaining Unknowns - Exact `schedule:run` crontab user (sudo required) - Whether any Behavior run ever reached the 600s job timeout (masked by 90s retry_after) - Historical failed_jobs payloads not inspected (by design)