86,359 Queries in One Request: An Outage Where Every Dashboard Was Green

← all writing

The failure was inside the Ruby process: requests executing tens of thousands of cached ActiveRecord queries, occupying enough Puma threads for the health check to time out. The watchdog saw an unresponsive process, assumed it was dead, and restarted it.

It took four plausible but wrong diagnoses to get there. I am including them because the refutations are the useful part.

Client IPs are redacted and long lines are trimmed for width. Every command, value and stack frame is real output from the box.

---

The symptom that was not the problem

It started with a deploy that appeared to hang:

➜ games.directory git:(master) ✗ RAILS_ENV=production bin/dev --force-deploy
[2026-07-31 08:01:36] Deploying branch master..
[2026-07-31 08:01:38] Gemfile.lock unchanged — skipping bundle install.
[2026-07-31 08:01:46] ✓ Boot gates passed.
[2026-07-31 08:01:46] No db/ changes — skipping migrations.
[2026-07-31 08:01:48] No supervisor running — becoming the resident supervisor (pid 25075)..
[2026-07-31 08:01:48] WARNING: supervisor is attached to a terminal. Prefer launchd or nohup.
[2026-07-31 08:01:53] Starting web..
[2026-07-31 08:01:53] Starting sidekiq-regular..
[2026-07-31 08:01:53] Starting sidekiq-splash..
[2026-07-31 08:02:01] Web is answering http://127.0.0.1:1337/up — stack is up.

Then nothing. No prompt.

That part was expected. `bin/dev` is both the deploy tool and the process supervisor. The first production invocation becomes the resident supervisor: it starts Puma and both Sidekiq processes under respawn loops, then remains in the foreground so launchd has one process to watch.

become_supervisor() {
  # ...
  watchdog $$ &
  release_watcher $$ &
  while :; do
    wait 2>/dev/null || true
    sleep 1
  done
}

Later invocations take the deploy path, cut over the release and exit. The entire fork is one predicate:

supervisor_running() {
  local pid
  pid=$(cat "$SUPERVISOR_PIDFILE" 2>/dev/null || true)
  if alive_matching "$pid" 'bin/dev'; then
    return 0
  fi
  rm -f "$SUPERVISOR_PIDFILE"
  return 1
}

Alive means deploy and exit. Not alive means take over and stay resident.

I got the second branch, so the previous resident supervisor had disappeared. The first question was why.

---

Act I: launchd was pointing at a deleted file

➜ sudo launchctl print system/directory.games.supervisor
system/directory.games.supervisor = {
    active count = 0
    path = /Library/LaunchDaemons/directory.games.supervisor.plist
    state = spawn scheduled
    program = /Users/studio51/Projects/games.directory/daemon_start.sh

`active count = 0`, `state = spawn scheduled`, and a program path I did not recognise.

`daemon_start.sh` was no longer in the repository:

➜ git log --oneline --date=short --pretty='%h %ad %s' -- daemon_start.sh
0c8a930fc 2026-07-07 chore: delete dead app plumbing
a5c71ace9 2026-07-05 fix(deploy): repair daemon_start.sh launcher bugs
d6966b5e4 2026-07-05 chore: fix issue with ruby version when running daemon

The same commit deleted the launcher and rewrote the repository copy of the plist:

<key>ProgramArguments</key>
   <array>
   <string>/Users/studio51/Projects/games.directory/daemon_start.sh</string>
+    <string>/bin/zsh</string>
+    <string>-lc</string>
+    <string>export PATH="$HOME/.asdf/shims:…:$PATH"; … RAILS_ENV=production exec bin/dev</string>
   </array>

The repository version was correct. The live definition was not.

launchd was using the copy in `/Library/LaunchDaemons`, and that definition remains loaded until it is explicitly removed and bootstrapped again. Production pulled the commit, deleted `daemon_start.sh`, and left launchd trying to execute that path forever.

The failure stayed latent for three weeks because the supervisor started before 7 July was still alive. A running process does not care that its launcher has been deleted. The problem only appeared when the supervisor needed to start again.

Lesson 1. Configuration outside the repository that points to files inside it creates restart-time failures. The deploy that introduces the fault and the incident that reveals it can be weeks apart.

Fixing it was mechanical: copy the current plist, `bootout`, release the stale pidfile, then `bootstrap` again.

But this was not the outage. It only explained why launchd failed to bring the supervisor back after something else had killed it.

---

Act II: the Sidekiq backlog looked guilty

The Sidekiq dashboard showed:

316,395,584  Processed
    505,619  Failed
         19  Busy
    613,238  Enqueued
        144  Retries
      1,309  Dead

There were two processes: `sidekiq-regular` at concurrency 15 and `sidekiq-splash` at 25.

The first correction was interpretive. `Processed` and `Failed` are lifetime cumulative counters, not current gauges. 505,619 failures against 316 million processed is about 0.16% over the application’s history. The live error indicators were `Retries: 144` and `Dead: 1,309`, neither of which described an active failure storm.

The queue distribution was more interesting:

➜ bin/rails runner 'Sidekiq::Queue.all.each { |q| puts "#{q.name}: #{q.size}" }'
default: 536542
splash:  53096
cache: 0        cex_api: 0     gaming_api: 0
psn_api: 0      stm_api: 0     xbx_api: 0
active_storage_analysis: 0     active_storage_purge: 0

Almost everything was in `default`, and a sample came back 100% `GeneralPurposeJob`: a router that accepts `(path, identifier_gid, data)` and dispatches to the correct service.

Fifteen threads, more than half a million jobs, and a queue topology that appeared to be doing nothing for this workload. It looked like the obvious place to start.

It was not.

---

Act III: four plausible wrong answers

Wrong answer #1: database connection exhaustion

`config/database.yml` sets `pool: 25`. `sidekiq-splash` runs at concurrency 25, leaving no headroom inside that process. Add Puma’s three workers, each with its own pool, and the theoretical total approaches 115 connections.

That fit the symptom: Sidekiq consumes the pool, Puma cannot check out a connection, health checks fail.

Then production contradicted the theory:

➜ mysql -e "SHOW VARIABLES LIKE 'max_connections';
            SHOW STATUS LIKE 'Threads_connected';
            SHOW STATUS LIKE 'Max_used_connections';"
+-----------------+-------+
| max_connections | 10000 |
+-----------------+-------+
| Threads_connected | 54  |
+-------------------+-----+
| Max_used_connections | 56 |
+----------------------+----+

`max_connections` was 10,000, not MySQL’s default. Peak usage was 56.

Dead.

The mistake was not merely “failing to check an assumption.” I had reasoned from a default value that had been overridden years earlier.

Wrong answer #2: hot-row lock contention

`GeneralPurposeJob` reports every item’s outcome to the run that created it:

def absorb(outcome, error = nil, **options)
  outcome.to_sym == :synced ? synced!(1) : failed!(error, **options)
  reload
  settle! if running? && !awaiting_items?
end
def synced!(count = 1)
  self.class.update_counters(id, synced: count, touch: true)
end

All 536,542 jobs belonged to one run, so every job updated the same `waypoint_id`:

UPDATE waypoints
SET synced = synced + 1, updated_at = NOW()
WHERE id = <the same id>

That looked like a classic hot row. Fifteen threads would serialise behind the same exclusive lock, making throughput dependent on lock duration rather than thread count.

Production disproved it:

➜ mysql -e "SHOW STATUS LIKE 'Innodb_row_lock%'; SHOW STATUS LIKE 'Threads_running';"
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 0     |
| Innodb_row_lock_time          | 21126 |
| Innodb_row_lock_time_avg      | 13    |
| Innodb_row_lock_time_max      | 174   |
| Innodb_row_lock_waits         | 1512  |
+-------------------------------+-------+
| Threads_running | 2 |
+-----------------+---+

Zero current waits. Only 21 seconds of cumulative row-lock time across the server’s entire uptime.

The shared counter update was still wasteful, but it was not the bottleneck. Wasteful and slow are different claims.

The more important clue was `Threads_running = 2`: Sidekiq said all 15 threads were busy while MySQL was barely executing anything.

Wrong answer #3: Redis head-of-line blocking

Redis is single-threaded, and the router’s uniqueness configuration was expensive:

sidekiq_options queue: :default, retry: 3,
  lock: :until_and_while_executing,
  lock_info: true,
  lock_ttl: 30.minutes.to_i,
  lock_limit: 1

`until_and_while_executing` creates enqueue-side and runtime locks. `lock_info: true` adds metadata writes. With more than half a million jobs and a 30-minute TTL, it was easy to imagine Redis spending its time maintaining `uniquejobs:*` keys.

The slowlog made the theory look stronger:

➜ redis-cli slowlog get 25
 4) 1) (integer) 73082
    2) (integer) 1785503746
    3) (integer) 23476
    4) 1) "EVALSHA" ... "throttled:ImageProcessorJob:concurrency.v2:store-images.s-microsoft.com"
25) 1) (integer) 73061
    2) (integer) 1785501124
    3) (integer) 53271
    4) 1) "HEXISTS" "general_image_cache:...:LOCKED"

Commands were taking 10–57 milliseconds.

Then I calculated utilisation instead of staring at the worst cases:

➜ redis-cli info commandstats | grep -E 'evalsha|brpop'
cmdstat_evalsha:calls=10656631,usec=2241501448,usec_per_call=210.34
cmdstat_brpop:calls=7013407,usec=496994087,usec_per_call=70.86

Total CPU time for those commands was about 2,738 seconds. Redis had been up for 35,820 seconds.

2,738 / 35,820 = 7.6% utilised

The 25 slowlog entries also spanned about 3.3 hours: roughly seven slow commands per hour, not a systemic stall.

Lesson 2. A slowlog shows the worst commands, not how often they occur. `usec / uptime` turns latency samples into utilisation, which is what tells you whether a component is actually constrained.

Wrong answer #4: vendor rate limits and queue topology

At this point I proposed routing work onto per-vendor queues so each upstream could be throttled independently.

The objection was immediate and correct: `GeneralPurposeJob` is intentionally vendor-agnostic, and the single queue is the control point it was designed around. Splitting it would add complexity without addressing the failure.

Per-vendor throttling already existed at the job-class level:

ImageProcessorJob                 concurrency: { limit: 8 }, key_suffix: → host(url)
Network::PlayStation::ServiceJob                   limit: 25
Network::Steam::Base                               limit: 5
Network::Xbox::BaseJob                             limit: 3
Scraper::PulseJob                                  limit: 5
VideoProcessorJob                                  limit: 2

The dashboard was confirming that it worked. `sidekiq-splash` reported 8 of 25 threads busy, and `ImageProcessorJob` was limited to exactly 8 per host. The other 17 threads were not stranded; they were being held back by design.

---

The elimination

Four hypotheses were gone:

| Component | Measurement | Verdict | | ----------------- | ---------------------------------------- | --------------- | | MySQL connections | 54 of 10,000; peak 56 | Not constrained | | MySQL locks | 0 current waits; 21s lifetime | Not constrained | | MySQL execution | Threads\_running = 2 | Mostly idle | | Redis | 7.6% utilisation; \~7 slow commands/hour | Not constrained | | CPU | load 3.32 on 8 cores | Not saturated |

Fifteen Sidekiq threads reported busy, but nothing on the box was saturated. When every downstream component is quiet, the work is happening somewhere else.

Two measurements found it.

First: Sidekiq was draining normally

➜ grep -oE 'elapsed=[0-9.]+' log/sidekiq.regular.log | tail -5000 | \
    awk -F= '{s+=$2; n++} END {print "mean", s/n "s over", n, "jobs →", 15/(s/n), "jobs/s"}'
mean 0.266392s over 5000 jobs → 56.308 jobs/s

At about 56 jobs per second, 536,542 jobs represented roughly 2.6 hours of work.

Sidekiq was not struggling. It was processing the backlog at exactly the rate fifteen threads and the observed job latency predicted.

The queue depth I had spent an hour explaining was not the outage.

Second: the watchdog had recorded the real symptom

➜ grep -E 'WATCHDOG' log/daemon.log
08:40:30 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
08:57:22 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
09:18:14 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
09:37:00 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
10:12:45 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
10:31:52 WATCHDOG: [web] health check failed 3x in a row — hot-restarting puma (pid 32815)
10:35:48 WATCHDOG: [web] recent hot restart didn't cure it; full graceful bounce (pid 32815)

Seven failures in two hours, with the same master PID throughout. Each hot restart bought about twenty minutes.

`/up` is a trivial endpoint. It does not touch MySQL, Redis or any external service. If it cannot answer three consecutive 30-second probes while the process is still alive, request capacity is the first thing to inspect.

---

Act IV: 86,359 queries in one request

The Puma log contained the answer:

➜ grep -E 'Completed [0-9]{3} .* in [0-9]{5,}ms' log/puma.log
Completed 200 OK in 34032ms (Views: 379.5ms | ActiveRecord: 7201.6ms (24154 queries, 23499 cached) | GC: 5414.8ms)
Completed 200 OK in 15596ms (Views: 100.9ms | ActiveRecord: 3004.8ms (59349 queries, 58591 cached) | GC: 2838.1ms)
Completed 200 OK in 14467ms (Views:  59.1ms | ActiveRecord: 2191.3ms (86359 queries, 84079 cached) | GC: 1834.6ms)
Completed 200 OK in 29177ms (Views:  94.5ms | ActiveRecord: 4433.2ms (42165 queries, 41262 cached) | GC: 3871.4ms)

One request executed 86,359 ActiveRecord queries.

Of those, 84,079 hit the query cache. MySQL barely saw them.

That was why every infrastructure dashboard was green. The repeated lookups were being absorbed inside the Rails process, where the cost appeared as Ruby work: constructing and hashing SQL strings, instantiating ActiveRecord objects, and garbage-collecting the resulting allocations.

The database was quiet because most of the repeated lookups never reached it.

`Threads_running = 2` was not an alibi for MySQL. It was a fingerprint of the actual failure mode.

Puma was running with its defaults:

threads_count = Integer(ENV.fetch("RAILS_MAX_THREADS", 5))
workers Integer(ENV["WEB_CONCURRENCY"] || 3)

Neither environment variable was set, so the public site had fifteen request threads in total.

With only five threads per worker, a handful of 10–35 second requests alongside normal traffic could consume a worker’s capacity and leave `/up` waiting. Once enough workers were saturated, the watchdog interpreted the delay as a dead web process and restarted Puma. That dropped the slow in-flight requests, health recovered, and the same routes were crawled again around twenty minutes later.

The application was not crashing. It was being restarted for looking dead.

The traffic was mostly bots: one address walking achievement pages across Steam, PlayStation and Xbox, with other datacenter addresses crawling profile pages. Identical query counts repeating across requests — 59,349 several times, then 86,359 several times — showed the same expensive routes being revisited.

There was also a separate slow-request shape:

14:02:12 Completed 200 OK in 29691ms (ActiveRecord: 29593.7ms (52 queries, 15 cached))
14:02:12 Completed 200 OK in 21333ms (ActiveRecord: 21238.5ms (52 queries, 15 cached))
14:02:19 Completed 200 OK in 20619ms (ActiveRecord: 20499.5ms (52 queries, 15 cached))

Only 52 queries, but nearly thirty seconds spent in ActiveRecord. That was not the same repeated-query problem. It pointed to one genuinely slow statement, allowed to run because `max_execution_time` was 60 seconds.

The two signatures needed different fixes, but both consumed the same scarce resource: Puma request threads.

Lesson 3. ActiveRecord’s query cache can hide repeated-query problems from database monitoring. When request latency is high, database execution is low, and cached query counts are enormous, the cost may be inside Ruby rather than MySQL.

---

The fixes

1. Give Puma a real thread budget

The values belong in `bin/dev`, where the supervisor applies them:

WEB_THREADS="${RAILS_MAX_THREADS:-16}"
WEB_WORKERS="${WEB_CONCURRENCY:-4}"

RUBY_YJIT_ENABLE=1 RAILS_ENV=production PORT=$WEB_PORT \
+          RAILS_MAX_THREADS=$WEB_THREADS WEB_CONCURRENCY=$WEB_WORKERS \
           OBJC_DISABLE_INITIALIZE_FORK_SAFETY=YES \
           bundle exec puma -C config/puma.rb >> "$LOG_DIR/puma.log" 2>&1 &

Sixteen threads remain below the database pool of 25 available to each worker. Four workers limit the number of preloaded application copies on a machine that also runs MySQL, Redis and both Sidekiq processes.

Deploying the change had one trap. `bin/dev` only performs a full Puma bounce when selected files change:

elif changed_since_last_deploy '^(Gemfile|Gemfile\.lock|config/puma\.rb)'; then
  log "[web] Gemfile.lock or puma config changed — full graceful restart.."

Changing `bin/dev` triggers a hot restart instead. A hot restart re-execs Puma with its original environment, while the new values live inside the supervisor’s updated script. The supervisor itself therefore had to restart before the new thread budget could take effect.

2. Bound crawler traffic

`rack-attack` was already protecting authentication endpoints. The expensive reads needed the same treatment:

Rack::Attack.throttle("expensive reads/ip", limit: 60, period: 60.seconds) do |request|
  next unless request.get?
  expensive = %r{\A/u/[^/]+/(?:shelf|c/|t/|d\z|tracker|providers)|\A/[a-z_]+/achievements/}
  request.ip if expensive.match?(request.path)
end

Sixty requests per minute is several times normal human browsing speed. It limits the damage from one crawler, but it is not the root fix. A distributed crawl still gets through, and the underlying cost remains the number of queries per page.

3. Instrument before guessing at the query fix

The repeated-query defect was the root cause, but the logs did not yet correlate the 86,359-query requests to an exact route and request ID.

Rather than guess at an `includes`, the next step was to add route-level and request-level query-count instrumentation, identify the exact code path, then fix the repeated lookups where they originate.

The outage was contained through more request capacity and crawler throttling. The application-level query defect still needed a precise fix.

---

What I would take from this

Lifetime counters are not gauges. Half a million historical failures sent me looking for an error storm that was not happening. `Retries: 144` described the present.

Compute utilisation; do not eyeball latency. `usec / uptime` demolished the Redis theory in two divisions. A slowlog shows the worst cases and hides their frequency.

Reasoning from defaults is reasoning from fiction. I built a causal chain around a default `max_connections` value. Production was configured for 10,000. One query would have ended that theory immediately.

Query count belongs beside query time. MySQL was quiet because 84,079 repeated lookups never reached it. Database duration alone would never have exposed the request that exhausted Puma.

Health checks need capacity to answer. A trivial liveness endpoint still competes for a request thread. If every thread is occupied, the process can be alive and healthy enough to continue working while appearing dead from outside.

A watchdog must distinguish saturation from death. Ours treated “not answering” as “not alive” and restarted a healthy process seven times. The restarts briefly cleared the symptom and made the outage look intermittent.

Elimination is cheaper than intuition. Four wrong hypotheses cost about forty minutes of measurements. Acting on the first one — increasing pools and concurrency — would have taken longer and likely made the system worse.

The important step was not finding a clever theory. It was measuring until there was only one place left for the work to be.