The queue worker that leaked, and the memory limit that hid it

The queue was healthy by every measure anybody looked at: depth near zero, no failures, the supervisor reporting all four workers running. What nobody had noticed was that the four workers had restarted 187 times that day, and that jobs took longer the older a worker got.

The symptom

$ supervisorctl status
worker:worker_00  RUNNING   pid 28841, uptime 0:04:12
worker:worker_01  RUNNING   pid 28903, uptime 0:09:44
worker:worker_02  RUNNING   pid 28712, uptime 0:02:08
worker:worker_03  RUNNING   pid 28855, uptime 0:07:31

$ grep -c 'exited: worker' /var/log/supervisor/supervisord.log
187

$ grep 'job.completed' /var/log/app/queue.json 
  | jq -r '[.context.worker_uptime_s, .context.duration_ms] | @tsv' | tail -5
42      118
318     140
594     198
641     241     ← same job type, slower as the process ages

Uptimes of a few minutes on processes that should run for days, and a duration that climbs with process age. Nothing alerted because the supervisor was doing exactly what it was configured to do, and a restarted worker is a running worker as far as any check was concerned.

Why it happens

A PHP web request is a fresh process and everything it allocates is released when it ends, which is why PHP developers rarely think about memory. A queue worker is a long-running process running the same framework code thousands of times, and anything the framework retains between jobs accumulates.

The three usual causes, in order of likelihood: a static property that grows, an event listener registered per job and never removed, and the container resolving singletons that hold references to per-job state. All three are invisible in a web request and all three are unbounded in a worker.

The fix

Finding it, which is not the same as bounding it

// the measurement that turns a suspicion into a graph
Queue::after(function (JobProcessed $event) {
    Log::channel('worker')->info('job.completed', [
        'job'        => get_class($event->job),
        'memory_mb'  => round(memory_get_usage(true) / 1048576, 1),
        'peak_mb'    => round(memory_get_peak_usage(true) / 1048576, 1),
        'jobs_since_boot' => ++$GLOBALS['td_jobs'],
    ]);
});

$ jq -r '[.context.jobs_since_boot, .context.memory_mb, .context.job] | @tsv' 
    /var/log/app/queue.json | awk 'NR % 50 == 0'
50   42.0   AppJobsSendReceipt
100  44.0   AppJobsSendReceipt
150  46.0   AppJobsRebuildIndex
200  71.0   AppJobsRebuildIndex     ← the slope changes here
250  96.0   AppJobsRebuildIndex

Grouping memory by job class is what turns “the worker leaks” into “RebuildIndex leaks about half a megabyte per run”. Without that split the graph is a single line going up and every theory is equally plausible; with it the search is confined to one class.

Static properties, listeners and the container

// 1. a static cache that never evicts. the most common cause.
final class SkuLookup
{
    private static $cache = [];        // grows forever in a worker

    public static function find(string $sku): ?Product
    {
        return self::$cache[$sku] ??= Product::whereSku($sku)->first();
    }
}

// 2. a listener registered per job, never removed
Event::listen(ProductSaved::class, function ($e) use ($context) { /* ... */ });

// 3. the query log, which is on whenever debugging is
DB::connection()->disableQueryLog();

The static cache is the one to look for first and it is almost always written by somebody optimising a web request, where it is correct and bounded by the request. In a worker it is a memory leak with a helpful name. Bounding it — an LRU with a size limit — is usually better than removing it, because the original optimisation was real.

The closure listener is the subtlest: it captures $context, which holds a reference to the job, which holds the models it loaded. Ten thousand registrations later the worker is holding ten thousand jobs’ worth of models and the listener list itself is being walked on every event, which is where the slowdown comes from.

Confirming it with a real measurement

# run one job type in a loop, in isolation, and watch
$ php artisan tinker
>>> for ($i = 0; $i < 500; $i++) {
...   (new AppJobsRebuildIndex($ids[$i]))->handle();
...   if ($i % 100 === 0) echo $i, ' ', memory_get_usage(true) / 1048576, "MBn";
... }
0    38MB
100  61MB
200  84MB
300  107MB      # 230 kB per job, linear

# and after the fix
0    38MB
300  39MB

Running one job type in a loop outside the worker is the cheapest possible isolation and it removes every variable the queue introduces. A linear slope is a leak; a step function that plateaus is a cache filling up, which is different and may be fine. Distinguishing those two before changing anything saves a day.

The seatbelt, which is not the fix

; supervisor
[program:worker]
command=php /app/artisan queue:work redis --max-jobs=1000 --max-time=3600
  --memory=128 --tries=3 --sleep=3
numprocs=4
autorestart=true
stopwaitsecs=3600

The three limits are worth having permanently and they are a seatbelt rather than a repair: a worker that restarts every thousand jobs cannot leak enough to matter, and it also cannot tell you that it is leaking. Setting them and considering the problem solved is how the next leak stays hidden for a year.

stopwaitsecs matching the longest possible job is the setting people miss. The default is ten seconds, after which supervisor sends SIGKILL — which kills a worker mid-job, and mid-job means mid-transaction on anything that is not carefully written.

The other half is a restart that is actually visible: logging a line on boot with the reason, and alerting when the restart rate exceeds a threshold. A worker restarting every eleven minutes is a fact somebody should have to acknowledge rather than one buried in a supervisor log.

Verifying it worked

$ supervisorctl status
worker:worker_00  RUNNING   pid 31204, uptime 18:42:11
worker:worker_01  RUNNING   pid 31205, uptime 18:42:11

$ grep -c 'exited: worker' /var/log/supervisor/supervisord.log
4                          # was 187, and these are the --max-jobs recycles

$ jq -r '[.context.jobs_since_boot, .context.memory_mb] | @tsv' 
    /var/log/app/queue.json | awk 'NR % 200 == 0'
200  39.0
400  39.0
800  40.0

$ jq -r '.context.duration_ms' /var/log/app/queue.json 
  | awk '{s+=$1; n++} END {print s/n}'
121                        # was climbing to 241

Flat memory over eight hundred jobs is the assertion, and the average duration coming back down is the one that matters to whoever is waiting for the jobs. The four remaining restarts are the deliberate recycles, which is the correct number rather than zero — a worker that never restarts is one whose seatbelt is not fastened.

What this costs

A restart policy that hides the next leak too. That is the uncomfortable conclusion: the same mechanism that keeps a leaking worker serviceable is what stopped anybody noticing for months, and there is no configuration that has one property without the other. The only real mitigation is monitoring the restart rate as a first-class signal rather than as something visible in a log — a graph of worker uptime is a leak detector, and it costs one metric.

The broader cost is that long-running PHP requires a discipline the language does not encourage. Every static property, every listener registration and every container binding has to be considered in a context where the process outlives the work, and none of the tooling helps — there is no equivalent of a heap dump that anybody uses routinely. Keeping worker code deliberately boring, with no statics and no closures capturing job state, is a rule worth writing down because the alternative is finding out one job type at a time.