Queue visibility before queue complexity

Name what each clock value means

The payload hook records wall-clock milliseconds when Laravel creates the payload. The dispatch_age_ms field means that initial stamp to the start of a worker attempt. It can include publishing, deliberate delay and time in previous attempts or backoff. It is not pure ready-queue wait, and the stamp is not reset when Redis releases this payload for retry.

Attempt duration uses hrtime within the same worker process. PHP documents that clock as monotonic with an arbitrary origin. The helper converts nanoseconds to whole milliseconds. Its event boundaries include some framework and logging overhead, so duration_ms is not CPU time or an isolated measurement of the job’s handle method.

With injected inputs, an initial payload stamp of 1000 ms and a start at 1040 ms give an age of 40 ms. Separate monotonic inputs give a 7 ms attempt. A retry starting at 1090 ms has an age of 90 ms but its own 3 ms duration. The fixture verifies these calculations. They are controlled examples, not observed Redis response times.

Missing metadata or a missing timer stays unknown. If the wall clock appears earlier than the payload stamp, age is null with clock_skew set. Positive clock skew can still look like age, so this flag does not establish synchronization across machines. Do not turn missing or contradictory timing into a reassuring zero.

I recommend retaining both values when the operator needs to distinguish an old request from a slow current attempt. I would reject one unlabeled “job duration” field because, after a retry, its reader cannot tell whether it starts at the original payload stamp or at the latest attempt. Separate names make that choice inspectable.

<?php
namespace Fixture;

final class AttemptTimes
{
    private array $starts = [];

    public function begin(string $key, int $wallMs, int $monotonicNs, ?int $enqueuedMs): array
    {
        $this->starts[$key] = $monotonicNs;
        $skew = $enqueuedMs !== null && $wallMs < $enqueuedMs;
        return [
            'dispatch_age_ms' => $enqueuedMs === null || $skew ? null : $wallMs - $enqueuedMs,
            'clock_skew' => $skew,
        ];
    }

    public function elapsed(string $key, int $monotonicNs): ?int
    {
        $start = $this->starts[$key] ?? null;
        return $start === null || $monotonicNs < $start
            ? null : intdiv($monotonicNs - $start, 1_000_000);
    }

    public function forget(string $key): void
    {
        unset($this->starts[$key]);
    }
}

Correlate attempts without copying the payload

The provider registers Laravel queue callbacks and keys the local timer by job UUID plus attempt number. Start records carry initial age. Return and exception records carry elapsed duration. The terminal JobFailed callback is separate from JobExceptionOccurred. A job explicitly released back to Redis is labelled released when its processing callback finishes, rather than being labelled successful.

The selected telemetry context contains connection, queue and job type alongside the correlation ID and attempt. Failures record the exception class, without its message or serialized payload. The fixture checks the field allowlist and owner-only permissions on its JSON log file. This does not sanitize Laravel’s other logs or Horizon’s job records.

I recommend keeping individual IDs in access-controlled logs and using bounded dimensions such as queue and job type for aggregate metrics. Prometheus’s instrumentation guidance warns about high-cardinality labels. This example writes logs only; it does not install a metrics exporter or implement a production retention policy.

<?php
namespace Fixture;
use Illuminate\Queue\Events\JobExceptionOccurred;
use Illuminate\Queue\Events\JobFailed;
use Illuminate\Queue\Events\JobProcessed;
use Illuminate\Queue\Events\JobProcessing;
use Illuminate\Support\Facades\Log;
use Illuminate\Support\Facades\Queue;
use Illuminate\Support\ServiceProvider;

final class QueueTelemetryProvider extends ServiceProvider
{
    public function boot(): void
    {
        $times = new AttemptTimes;
        Queue::createPayloadUsing(fn () => [
            'telemetry' => ['enqueued_at_ms' => (int) floor(microtime(true) * 1000)],
        ]);
        $context = function ($event): array {
            return [
                'connection' => $event->connectionName,
                'queue' => $event->job->getQueue(),
                'job_id' => $event->job->uuid(),
                'job_type' => $event->job->resolveName(),
                'attempt' => $event->job->attempts(),
            ];
        };
        $key = fn ($event) => $event->job->uuid().':'.$event->job->attempts();
        Queue::before(function (JobProcessing $event) use ($times, $context, $key): void {
            $enqueued = $event->job->payload()['telemetry']['enqueued_at_ms'] ?? null;
            $age = $times->begin($key($event), (int) floor(microtime(true) * 1000), hrtime(true),
                is_int($enqueued) ? $enqueued : null);
            Log::channel('queue_telemetry')->info('queue.attempt_started', $context($event) + $age);
        });
        Queue::after(function (JobProcessed $event) use ($times, $context, $key): void {
            $data = $context($event) + [
                'duration_ms' => $times->elapsed($key($event), hrtime(true)),
                'outcome' => $event->job->isReleased() ? 'released' : 'returned',
            ];
            Log::channel('queue_telemetry')->info('queue.attempt_finished', $data);
            $times->forget($key($event));
        });
        Queue::failing(function (JobFailed $event) use ($times, $context, $key): void {
            Log::channel('queue_telemetry')->error('queue.job_failed', $context($event) + [
                'duration_ms' => $times->elapsed($key($event), hrtime(true)),
                'exception_class' => get_class($event->exception),
            ]);
        });
        Queue::exceptionOccurred(function (JobExceptionOccurred $event) use ($times, $context, $key): void {
            Log::channel('queue_telemetry')->warning('queue.attempt_exception', $context($event) + [
                'duration_ms' => $times->elapsed($key($event), hrtime(true)),
                'exception_class' => get_class($event->exception),
            ]);
            $times->forget($key($event));
        });
    }
}

Read the observed outcomes separately

The normal fixture passes 43 named clock, queue and snapshot observations. Six separate worker processes handle a successful job, two failed attempts, an explicit release followed by a return, and a return without output. The successful job’s file is checked separately. The no-output job produces a processing-finished record while its expected file remains absent, demonstrating why that record is not a business receipt.

For the failing job, the first exception produces an attempt_exception record with no job_failed record. The next attempt uses the same UUID and original payload stamp, then exhausts the configured attempts. The trace contains two attempt exceptions and one terminal failure. Those are different event counts for one job, not three failed jobs.

Eight actual source mutations change the age origin, duration units, clock-skew handling, message logging, payload logging, terminal listener, released outcome or schedule interval. Each fails at its intended assertion with the exact preceding normal observations and the executed-source hashes. The source bundle records the runtime versions and actual traces; no fixed production timings are inferred from them.

Verify the snapshot, not just the command exit

Horizon requires Redis queues. Its Laravel 12 guidance asks for horizon:snapshot every five minutes. The registered console entry below is exercised in the fixture, and real worker metrics reach Horizon. Adding the entry does not start the application scheduler or verify its operational availability.

In Horizon 5.50.1, the snapshot command only writes when it acquires its metrics lock. The test observes a first stored snapshot, then a successful command exit while the lock is still held with no additional row. Exit zero alone therefore does not establish that this invocation wrote a snapshot.

The fixture then accelerates only its disposable Redis instance’s snapshot-lock expiry and invokes the command after expiry. It stores a further row using an injected PHP snapshot instant five minutes after the first. This verifies command and lock behavior, not five minutes of real scheduler operation or the dashboard UI. No production lock is changed.

<?php
use Illuminate\Support\Facades\Schedule;

Schedule::command('horizon:snapshot')->everyFiveMinutes();

Use the distinction to choose the next investigation

I recommend checking intended delays and prior attempts before interpreting rising dispatch age as a worker shortage. If the ready backlog grows while per-attempt duration stays stable, capacity or scheduling becomes a useful lead. If attempt duration grows, inspect work inside the attempt and its dependencies. These are investigation paths, not proof of a cause or permission to replay an external effect.

Laravel’s queue guidance requires worker timeouts to be several seconds shorter than retry_after on connections using that setting. SQS visibility needs its own configuration review. The fixture does not simulate timeouts or establish duplicate-effect safety. A forced kill can skip callbacks, so missing completions also need independent worker-health and output checks.

The example is sequential and local, with a disposable Redis socket and no external network. It does not test distributed clocks, concurrent consumers, crash recovery or production logging failures. For a real export, retain a business operation reference and verify the usable result independently of attempt logs before declaring the user’s task complete.