Ship production optimization M1-M12.5A: queues, metrics, HTTP observability, and vector search reliability.
Keep similar-ai from tripping the global circuit on a lone URL 502, clamp Qdrant search to 100, and add Server-Timing plus slow-request logging. Studio shared props, Academy S3 exists caching, heat chunking, and Redis/scheduler hygiene stay in this rollout.
This commit is contained in:
@@ -0,0 +1,290 @@
|
||||
# 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)
|
||||
Reference in New Issue
Block a user