davidmerfield / davidmerfield/blot

Perf investigation: archive/tag page render cost + container crashes on large blogs

Open
#1,806 1 comment 0 reactions 0 assignees View on GitHub
enhancement
Dominant language
JavaScript
Stars
2k
Forks
98
Avg merge
10h 51m
Merged PRs (30d)
174

Description

## Summary

Investigated a production performance degradation (rising response times, declining APDEX over several months) and repeated container crashes/restarts (`blot-container-blue`, `blot-container-yellow`). Root-caused both to the same underlying pattern: a small number of large, heavily-crawled blogs doing expensive, fully-uncached, full-recompute work on every request to certain pages.

### What was actually happening

One blog in particular (nashp.com, ~800 entries, ~40 tags) surfaced the problem clearly:

- **`/archives`** rebuilds the entire year/month index from scratch on every request - no caching, no precomputed index. It loads every entry in the blog in full (including rendered HTML body, even though the page only needs `dateStamp`/`url`/`title`), then runs a fully synchronous grouping loop over all of them.
- **`/tagged/`** and the archives page's tag sidebar both go through `Tags.list`, which issued **2 sequential, individually-`await`ed Redis round trips per tag** (`GET` name + `ZCARD`/`ZRANGE` count) in a plain loop - for N tags, 2N serialized round trips.
- Both of these are synchronous/serialized enough to **block Node's single event loop** for the duration - since one Node process serves many sites, a slow render for one site stalls every other site sharing that process.
- Under aggressive bot crawling (many distinct tag/archive URLs, often with cache-busting query strings so nothing is reusable), this combination produced JS heap exhaustion (`FATAL ERROR: Ineffective mark-compacts near heap limit... JavaScript heap out of memory`) and took down whichever container was serving that traffic - including the failover container when the primary ones were already degraded.
- Separately, a **dormant, previously-reverted migration** (`config.redis.readEntriesFromHash`, see the "Entry hashes, stage 2.5" revert) is designed to fix the "load every entry in full" problem by fetching only the fields a page actually needs, but its hash-read implementation (`app/models/entry/get.js`) had the same N-separate-redis-calls issue as `Tags.list`, which is very likely why re-enabling it previously made things *worse* (~78% average response time increase across all blogs, not just the heavy one) rather than better.

### Fixes landed / in progress

- #1783 (closed, not merged): swapped `moment`/`moment-timezone` for `Intl.DateTimeFormat` in the archives grouping loop. Reverted after review caught a real correctness issue - `Intl`'s ICU timezone data and `moment-timezone`'s separately-bundled data can disagree at DST/policy-change boundaries (confirmed: `America/Mexico_City` around 2023-05-01 diverges by a full hour), which would group a post into a different month on the archives page than the rest of the site shows it in. Left as documentation for the next attempt rather than merged.
- #1784: fixes the N-sequential-round-trips pattern in `Tags.list` and in the dormant `getFromHash` path, using `Promise.all` over direct Redis commands (not `client.multi()/.exec()` - a transaction wrapper turned out to both bypass node-redis's client-side cache and, for one code path, buffer more data in memory at once than the original sequential version did; see the review thread on that PR for the full reasoning).

### Still open / not yet done

- The archives page still does a full, uncached, per-request recompute over every entry in the blog - the field-narrowing fix in #1784 makes that recompute cheaper, but doesn't eliminate it. A real fix likely needs either a precomputed/incrementally-maintained index (the way tags already maintain sorted sets, but archives has no equivalent), or accepting the recompute cost but moving it off the main thread (worker thread) so it can't stall other sites' requests.
- `config.redis.readEntriesFromHash` is still off by default - re-enabling it is a separate, deliberate rollout decision, not something to flip casually given the history above.
- Rate limiting / bot mitigation for the crawling pattern that triggers this was explicitly treated as a later-stage mitigation, not the first fix - the priority was fixing the actual inefficiency first.

## Guidance for future agents investigating similar issues

### Investigating production directly over SSH

The production server has a `~/.bashrc` with helper functions purpose-built for this kind of investigation - read it early with `ssh "cat ~/.bashrc"` rather than reinventing these:

- `slowest` - tails the openresty access log and reports the slowest individual requests, slowest URLs by average response time, slowest domains, and slowest uncached (`cache=MISS`) 200 responses.
- `biggest` - largest individual responses and highest-bandwidth URLs.
- `errors` - tails logs for 500/501/502/504 responses.
- `404s` - most frequent 404'd paths.
- `upstream` - live-tails requests with a non-empty `st=` (upstream response time) field.
- `req ` - greps across access/error logs and all container logs at once for a pattern.
- `live` - live-tails all container logs plus the access log together, prefixed by source.
- `logs [container] [-f]` - fetch or follow logs for one or all `blot-container-*` containers.
- `question ` / `info ` - look up the account/user behind a specific blog URL.
- `stats` - per-container CPU/memory plus a breakdown of the top processes inside each container by memory.

**Always get explicit user confirmation before running commands against production**, and stick to read-only investigation (log tailing, `docker logs`, `docker inspect`, `redis-cli` read-only commands) unless the user has explicitly authorized something that changes state.

### Identifying and investigating Docker restarts

- `docker ps -a --format 'table {{.Names}}\t{{.Status}}\t{{.CreatedAt}}'` - a container "Up 2 minutes" when you'd expect "Up several days" means it restarted recently.
- `~/docker-health-check.log` - the health-check script that auto-restarts unhealthy containers appends here every time it does so, with a timestamp and container name. `tail -50 ~/docker-health-check.log` gives a quick history of recent restarts across all containers.
- `docker inspect --format 'OOMKilled={{.State.OOMKilled}} ExitCode={{.State.ExitCode}} StartedAt={{.State.StartedAt}} RestartCount={{.RestartCount}}'` - `RestartCount` accumulates over the container's lifetime (not just "recently"), and `OOMKilled` reflects the *container's* own docker-level OOM state, which is usually `false` even when the *process inside* the container hit its own memory limit (see below) - don't rely on this field alone.

### Distinguishing why a container restarted

There are at least two distinct failure modes that look similar from `docker ps` alone but have very different causes and fixes:

1. **V8 / Node heap OOM** (an in-process JavaScript error, not a Linux OOM kill): search container logs for `FATAL ERROR` and `JavaScript heap out of memory`. This means the Node process's own heap hit its configured/default limit and V8 crashed itself - the fix is almost always in application code (something is holding too much data in memory, e.g. loading every entry in a large blog for a single request), not a memory-limit tuning problem. Look at the log lines immediately before the crash for the last request(s) being handled - that's usually the trigger. `docker logs --since

Both can plausibly explain a restart, so check both before concluding.

### Finding the actual triggering request

Once you've found a crash/restart, `docker logs --since --until ` gives you the log lines immediately preceding it. Cross-reference the last live request(s) in that window against the openresty access log (`grep /var/instance-ssd/logs/access.log`, request IDs are the 32-character hex string that appears on every log line for a given request) to get the full URL, status code, and timing - this is how the nashp.com archive/tag page pattern was actually identified, not guessed at.

### Local reproduction

For anything beyond a quick log read, reproduce locally rather than experimenting against production. A local clone of a real, large blog running through the normal dev stack (`npm start` / docker-compose) with `toxiproxy` simulating realistic server↔redis latency is far more useful than synthetic test data, and lets you safely use `ab` (ApacheBench) for concurrent-load testing and cross-reference `docker logs` for the same event-loop-blocking / request-queueing signature described above (compare `ab`'s wall-clock mean against what the server's own per-request logs report - a large, growing gap under concurrency is the signature of requests queueing behind blocking work rather than genuinely running in parallel).

🤖 Generated with [Claude Code](https://claude.com/claude-code)

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.