From d9a565b57a596f919a3c7fb00579215959bd90ad Mon Sep 17 00:00:00 2001 From: "russell@unturf.com" Date: Wed, 11 Feb 2026 10:13:52 -0500 Subject: [PATCH] Add tickets MPS-4 and MPS-5 for 502 worker recycling fix MPS-4: Eliminate intermittent 502s via uwsgi config tuning MPS-5: Investigate root cause of worker memory growth (~40MB/min) --- docs/tickets/mps-4.md | 115 ++++++++++++++++++++++++++++++++++++++ docs/tickets/mps-5.md | 126 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 241 insertions(+) create mode 100644 docs/tickets/mps-4.md create mode 100644 docs/tickets/mps-5.md diff --git a/docs/tickets/mps-4.md b/docs/tickets/mps-4.md new file mode 100644 index 0000000..0027c17 --- /dev/null +++ b/docs/tickets/mps-4.md @@ -0,0 +1,115 @@ +# MPS-4: Eliminate intermittent 502s from uWSGI worker recycling + +## Problem + +Visitors intermittently see 502 Bad Gateway errors that resolve on refresh. +Root cause: uWSGI workers hit the `--reload-on-rss 256` memory limit every +4-5 minutes under normal watch mode traffic, triggering a kill+respawn cycle. +With only 2 workers (`--processes=2`), when both recycle near-simultaneously +Caddy's `reverse_proxy` gets no available backend and returns 502. + +### Evidence (2026-02-11 ~09:15-09:22 UTC) + +**Worker memory growth** (from `ps aux`): +- Worker 882747 (spawned 09:18): 242MB RSS after 4 minutes +- Worker 882737 (spawned 09:17): 188MB RSS after 5 minutes +- Both approaching the 256MB kill threshold simultaneously + +**Worker recycling frequency** (from `journalctl`): +``` +09:15:24 - worker 2 (882687) "Seeya!" → killed → Respawned as 882699 +09:15:29 - worker 1 (882640) "Seeya!" → killed → Respawned as 882708 +09:15:39 - worker 2 (882699) "Seeya!" → killed → Respawned as 882717 +09:17:36 - worker 2 (882717) "Seeya!" → killed → Respawned as 882737 +09:18:22 - worker 1 (882708) "Seeya!" → killed → Respawned as 882747 +``` + +Workers survive only ~15 seconds to ~3 minutes under load before hitting +the RSS limit. The 09:15:24 and 09:15:29 kills are only 5 seconds apart — +both workers recycling nearly simultaneously. + +**Cold start penalty**: First request after respawn takes 400-600ms +(vs normal 100-130ms) while the app re-initializes: +- 882699 first request: 413ms +- 882717 first request: 409ms +- 882747 first request: 533ms + +**System resources**: 4GB total RAM, 1.9GB swap used — memory pressure. + +### Current uWSGI config + +``` +--reload-on-rss 256 +--processes=2 +--threads 8 +--max-requests 10000 +--http=127.0.0.1:6001 +``` + +## Solution + +Tune uWSGI config to prevent simultaneous worker unavailability: + +### 1. Raise RSS limit + +Raise `--reload-on-rss` from 256 to 512. Workers currently grow to 242MB +in 4 minutes — 256 is too aggressive and causes constant churn. At 512MB +with 2 workers, worst case is ~1GB for workers, still well within the 4GB +system budget (Caddy + master + crypto_watcher use ~300MB combined). + +### 2. Add `--reload-on-rss-stagger` + +If available in the installed uWSGI version, or use `--max-requests` with +variance (`--max-requests-delta`) to prevent both workers from recycling at +the same instant. Set `--max-requests-delta 1000` to add randomness +(each worker gets max-requests ± 1000). + +### 3. Use lazy-apps mode + +Add `--lazy-apps` so each worker loads the application independently after +fork. This costs a bit more memory but means the master doesn't need to +re-fork the full app — workers initialize in parallel and the surviving +worker keeps serving while the new one starts. + +### 4. Add `--harakiri` timeout + +Add `--harakiri 30` as a safety net — if any request takes >30 seconds +(stuck DB query, deadlock), kill that worker instead of blocking a slot +forever. + +### Proposed new config + +``` +--reload-on-rss 512 +--processes=2 +--threads 8 +--max-requests 10000 +--max-requests-delta 2000 +--harakiri 30 +--die-on-term +--http=127.0.0.1:6001 +--lazy-apps +``` + +## Testing + +1. Apply config change on prod (`systemctl edit --full my.makepostsell.com`) +2. `systemctl restart my.makepostsell.com` +3. Monitor with: `watch -n 5 'ps -o pid,rss,vsz,etimes,cmd -p $(pgrep -f "uwsgi.*make_post")'` +4. Verify no 502s during a full watch mode auto-play cycle +5. Monitor swap usage — if swap grows past 2.5GB, back off to 384MB limit + +## Risk + +Low. Config-only change, easily reversible with a service restart. +The service unit is managed by salt (`/home/fox/foxhop-pillar/caddy/makepostsell.sls`) +so the salt pillar should be updated after validating the new values. + +## Depends On + +Nothing. Can be applied immediately. + +## Blocks + +MPS-5 (memory investigation — the RSS tuning buys time but doesn't fix the +underlying memory growth). diff --git a/docs/tickets/mps-5.md b/docs/tickets/mps-5.md new file mode 100644 index 0000000..0132c11 --- /dev/null +++ b/docs/tickets/mps-5.md @@ -0,0 +1,126 @@ +# MPS-5: Investigate and fix uWSGI worker memory growth + +## Problem + +uWSGI workers grow from ~83MB (post-fork baseline) to 256MB+ in 4-5 minutes +under normal watch mode traffic. This is ~40MB/minute of RSS growth, which +is excessive for a Python/Pyramid WSGI application serving 40-80KB HTML/JSON +responses. + +The rapid growth forces aggressive worker recycling (MPS-4), which causes +intermittent 502s. MPS-4 raises the RSS threshold as a band-aid, but this +ticket addresses the root cause. + +### Observed memory timeline + +``` +Worker 882747 (spawned 09:18): + - Baseline after fork: ~83MB (from master RSS) + - After 4 minutes: 242MB (6.0% of 4GB) + - Growth rate: ~40MB/min +``` + +### Potential causes + +1. **Jinja2 template caching**: Each rendered template (62-81KB output) may + accumulate compiled template objects. With 8 threads per worker, concurrent + renders could multiply this. + +2. **SQLAlchemy session accumulation**: If sessions aren't properly closed + after each request, objects pile up in the identity map. The + `lazy="dynamic"` relationships (e.g., `shop.products`) return query objects + that may hold references. + +3. **Response body retention**: uWSGI with `--http` mode may buffer response + bodies in worker memory. The 40-80KB HTML pages add up across threads. + +4. **Watch mode JSON responses**: The `/watch/{id}/json` endpoint generates + 41-51KB JSON responses. Under auto-play, a single visitor generates one of + these every 3-7 seconds. If these response strings linger in memory (Python + string interning, GC generation 2), they accumulate. + +5. **Thread-local accumulation**: With 8 threads, any per-thread leak is + multiplied 8x. Thread-local storage, logging buffers, or connection pools + that grow per-thread. + +## Investigation Plan + +### Step 1: Add memory logging + +Add a tween or middleware that logs RSS after every Nth request: + +```python +import resource + +def memory_tween_factory(handler, registry): + counter = [0] + def memory_tween(request): + response = handler(request) + counter[0] += 1 + if counter[0] % 100 == 0: + rss_mb = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss / 1024 + log.warning("RSS after %d requests: %dMB [%s]", + counter[0], rss_mb, request.path) + return response + return memory_tween +``` + +This tells us which request patterns correlate with memory spikes. + +### Step 2: Profile with tracemalloc + +On a dev instance, enable `tracemalloc` and compare snapshots: + +```python +import tracemalloc +tracemalloc.start() +# ... after N requests ... +snapshot = tracemalloc.take_snapshot() +top_stats = snapshot.statistics('lineno') +for stat in top_stats[:20]: + print(stat) +``` + +### Step 3: Check SQLAlchemy session cleanup + +Verify that `pyramid_tm` is properly closing sessions after each request. +Check if `DBSession.remove()` is called in an `after_request` hook. If using +scoped sessions with threads, each thread needs its own session lifecycle. + +### Step 4: Test with `--threads 1` + +Temporarily run with `--threads 1 --processes 4` instead of `--threads 8 +--processes 2`. If memory growth rate drops proportionally, the leak is +per-thread. If it stays the same per-worker, it's in shared state. + +### Step 5: Test without watch mode traffic + +Hit only static-ish pages (shop landing, product pages) without the SPA +watch mode auto-play. If memory growth slows dramatically, the leak is +specific to the `/watch/{id}/json` or `/signals/beacon` endpoints. + +## Solution + +Depends on investigation results. Likely fixes: + +- **If SQLAlchemy sessions**: Ensure `pyramid_tm` transaction manager commits + and closes properly per-request. Add explicit `DBSession.remove()` in a + response callback. +- **If Jinja2 templates**: Set `jinja2.cache_size` to a bounded value + (default is 400, may be unbounded). +- **If response bodies**: Consider adding `--http-keepalive` or switching + from `--http` to `--http-socket` with Caddy using uwsgi protocol. +- **If thread-local**: Restructure to fewer threads, more processes. + +## Files Likely Changed + +| File | Change | +|------|--------| +| `__init__.py` or `tweens.py` | Memory logging tween | +| `production.ini` | Jinja2 cache_size if needed | +| systemd service | Thread/process ratio tuning | + +## Depends On + +MPS-4 (apply the RSS band-aid first to reduce 502 frequency while +investigating).