Capture job dispatch duration (#106)

Author: avosalmon

src/Hooks/JobQueuedListener.php src/Hooks/QueuedJobListener.php

@@ -3,6 +3,7 @@
 namespace Laravel\Nightwatch\Hooks;
 
 use Illuminate\Queue\Events\JobQueued;
+use Illuminate\Queue\Events\JobQueueing;
 use Laravel\Nightwatch\Core;
 use Laravel\Nightwatch\State\CommandState;
 use Laravel\Nightwatch\State\RequestState;
@@ -11,7 +12,7 @@
 /**
  * @internal
  */
-final class JobQueuedListener
+final class QueuedJobListener
 {
     /**
      * @param  Core<RequestState|CommandState>  $nightwatch
@@ -22,7 +23,7 @@ public function __construct(
         //
     }
 
-    public function __invoke(JobQueued $event): void
+    public function __invoke(JobQueueing|JobQueued $event): void
     {
         try {
             $this->nightwatch->sensor->queuedJob($event);

src/NightwatchServiceProvider.php

@@ -34,6 +34,7 @@
 use Illuminate\Notifications\Events\NotificationSending;
 use Illuminate\Notifications\Events\NotificationSent;
 use Illuminate\Queue\Events\JobQueued;
+use Illuminate\Queue\Events\JobQueueing;
 use Illuminate\Routing\Events\PreparingResponse;
 use Illuminate\Routing\Events\ResponsePrepared;
 use Illuminate\Routing\Events\RouteMatched;
@@ -54,12 +55,12 @@
 use Laravel\Nightwatch\Hooks\ExceptionHandlerResolvedHandler;
 use Laravel\Nightwatch\Hooks\HttpClientFactoryResolvedHandler;
 use Laravel\Nightwatch\Hooks\HttpKernelResolvedHandler;
-use Laravel\Nightwatch\Hooks\JobQueuedListener;
 use Laravel\Nightwatch\Hooks\LogoutListener;
 use Laravel\Nightwatch\Hooks\MailListener;
 use Laravel\Nightwatch\Hooks\NotificationListener;
 use Laravel\Nightwatch\Hooks\PreparingResponseListener;
 use Laravel\Nightwatch\Hooks\QueryExecutedListener;
+use Laravel\Nightwatch\Hooks\QueuedJobListener;
 use Laravel\Nightwatch\Hooks\RequestBootedHandler;
 use Laravel\Nightwatch\Hooks\RequestHandledListener;
 use Laravel\Nightwatch\Hooks\ResponsePreparedListener;
@@ -264,7 +265,7 @@ private function registerHooks(): void
         /**
          * @see \Laravel\Nightwatch\Records\QueuedJob
          */
-        $events->listen(JobQueued::class, (new JobQueuedListener($core))(...));
+        $events->listen([JobQueueing::class, JobQueued::class], (new QueuedJobListener($core))(...));
 
         /**
          * @see \Laravel\Nightwatch\Records\Notification

src/SensorManager.php

@@ -15,6 +15,7 @@
 use Illuminate\Notifications\Events\NotificationSent;
 use Illuminate\Queue\Events\JobAttempted;
 use Illuminate\Queue\Events\JobQueued;
+use Illuminate\Queue\Events\JobQueueing;
 use Laravel\Nightwatch\Sensors\CacheEventSensor;
 use Laravel\Nightwatch\Sensors\CommandSensor;
 use Laravel\Nightwatch\Sensors\ExceptionSensor;
@@ -179,7 +180,7 @@ public function log(LogRecord $record): void
         $sensor($record);
     }
 
-    public function queuedJob(JobQueued $event): void
+    public function queuedJob(JobQueueing|JobQueued $event): void
     {
         $sensor = $this->queuedJobSensor ??= new QueuedJobSensor(
             executionState: $this->executionState,

src/Sensors/MailSensor.php

@@ -21,8 +21,6 @@ final class MailSensor
 {
     private ?float $startTime = null;
 
-    private ?int $duration = null;
-
     public function __construct(
         private RequestState|CommandState $executionState,
         private Clock $clock,
@@ -40,7 +38,6 @@ public function __invoke(MessageSending|MessageSent $event): void
 
         if ($event instanceof MessageSending) {
             $this->startTime = $now;
-            $this->duration = null;
 
             return;
         }
@@ -51,7 +48,6 @@ public function __invoke(MessageSending|MessageSent $event): void
             throw new RuntimeException("No start time found for [{$class}].");
         }
 
-        $this->duration = (int) round(($now - $this->startTime) * 1_000_000);
         $this->executionState->mail++;
 
         $this->executionState->records->write(new Mail(
@@ -71,7 +67,7 @@ class: $class,
             cc: count($event->message->getCc()),
             bcc: count($event->message->getBcc()),
             attachments: count($event->message->getAttachments()),
-            duration: $this->duration,
+            duration: (int) round(($now - $this->startTime) * 1_000_000),
             failed: false, // TODO: The framework doesn't dispatch a failed event.
         ));
     }

src/Sensors/NotificationSensor.php

@@ -22,8 +22,6 @@ final class NotificationSensor
 {
     private ?float $startTime = null;
 
-    private ?int $duration = null;
-
     public function __construct(
         private RequestState|CommandState $executionState,
         private Clock $clock,
@@ -37,7 +35,6 @@ public function __invoke(NotificationSending|NotificationSent $event): void
 
         if ($event instanceof NotificationSending) {
             $this->startTime = $now;
-            $this->duration = null;
 
             return;
         }
@@ -52,7 +49,6 @@ public function __invoke(NotificationSending|NotificationSent $event): void
             $class = $event->notification::class;
         }
 
-        $this->duration = (int) round(($now - $this->startTime) * 1_000_000);
         $this->executionState->notifications++;
 
         $this->executionState->records->write(new Notification(
@@ -67,7 +63,7 @@ public function __invoke(NotificationSending|NotificationSent $event): void
             user: $this->executionState->user->id(),
             channel: $event->channel,
             class: $class,
-            duration: $this->duration,
+            duration: (int) round(($now - $this->startTime) * 1_000_000),
             failed: false, // TODO: The framework doesn't dispatch the `NotificationFailed` event.
         ));
     }

src/Sensors/QueuedJobSensor.php

@@ -4,18 +4,21 @@
 
 use Illuminate\Events\CallQueuedListener;
 use Illuminate\Queue\Events\JobQueued;
+use Illuminate\Queue\Events\JobQueueing;
 use Laravel\Nightwatch\Clock;
 use Laravel\Nightwatch\Concerns\NormalizesQueue;
 use Laravel\Nightwatch\Records\QueuedJob;
 use Laravel\Nightwatch\State\CommandState;
 use Laravel\Nightwatch\State\RequestState;
 use ReflectionClass;
+use RuntimeException;
 
 use function hash;
 use function is_object;
 use function is_string;
 use function method_exists;
 use function property_exists;
+use function round;
 
 /**
  * @internal
@@ -24,6 +27,8 @@ final class QueuedJobSensor
 {
     use NormalizesQueue;
 
+    private ?float $startTime = null;
+
     /**
      * @param  array<string, array{ queue?: string, driver?: string, prefix?: string, suffix?: string }>  $connectionConfig
      */
@@ -35,19 +40,30 @@ public function __construct(
         //
     }
 
-    public function __invoke(JobQueued $event): void
+    public function __invoke(JobQueueing|JobQueued $event): void
     {
-        $nowMicrotime = $this->clock->microtime();
+        $now = $this->clock->microtime();
+
+        if ($event instanceof JobQueueing) {
+            $this->startTime = $now;
+
+            return;
+        }
+
         $name = match (true) {
             is_string($event->job) => $event->job,
             method_exists($event->job, 'displayName') => $event->job->displayName(),
             default => $event->job::class,
         };
 
+        if ($this->startTime === null) {
+            throw new RuntimeException("No start time found for [{$name}].");
+        }
+
         $this->executionState->jobsQueued++;
 
         $this->executionState->records->write(new QueuedJob(
-            timestamp: $nowMicrotime,
+            timestamp: $now,
             deploy: $this->executionState->deploy,
             server: $this->executionState->server,
             _group: hash('md5', $name),
@@ -60,7 +76,7 @@ public function __invoke(JobQueued $event): void
             name: $name,
             connection: $event->connectionName,
             queue: $this->normalizeQueue($event->connectionName, $this->resolveQueue($event)),
-            duration: 0, // TODO
+            duration: (int) round(($now - $this->startTime) * 1_000_000)
         ));
     }
 

tests/Feature/Sensors/QueuedJobSensorTest.php

@@ -7,6 +7,7 @@
 use Illuminate\Foundation\Bus\Dispatchable;
 use Illuminate\Foundation\Testing\RefreshDatabaseState;
 use Illuminate\Queue\Events\JobQueued;
+use Illuminate\Queue\Events\JobQueueing;
 use Illuminate\Queue\InteractsWithQueue;
 use Illuminate\Queue\SerializesModels;
 use Illuminate\Support\Facades\Bus;
@@ -74,7 +75,7 @@
             'name' => 'MyJob',
             'connection' => 'database',
             'queue' => 'default',
-            'duration' => 0,
+            'duration' => 5200,
         ],
     ]);
 });
@@ -184,6 +185,14 @@
         'suffix' => '-production',
     ]);
 
+    nightwatch()->sensor->queuedJob(new JobQueueing(
+        connectionName: 'my-sqs-queue',
+        queue: 'https://sqs.us-east-1.amazonaws.com/your-account-id/queue-name-production',
+        job: 'MyJobClass',
+        payload: '{"uuid":"00000000-0000-0000-0000-000000000000"}',
+        delay: 0,
+    ));
+
     nightwatch()->sensor->queuedJob(new JobQueued(
         connectionName: 'my-sqs-queue',
         queue: 'https://sqs.us-east-1.amazonaws.com/your-account-id/queue-name-production',

tests/Unit/Hooks/JobQueuedListenerTest.php tests/Unit/Hooks/QueuedJobListenerTest.php

@@ -1,7 +1,8 @@
 <?php
 
 use Illuminate\Queue\Events\JobQueued;
-use Laravel\Nightwatch\Hooks\JobQueuedListener;
+use Illuminate\Queue\Events\JobQueueing;
+use Laravel\Nightwatch\Hooks\QueuedJobListener;
 use Laravel\Nightwatch\SensorManager;
 
 it('gracefully handles exceptions', function () {
@@ -11,14 +12,14 @@
 
         public function __construct() {}
 
-        public function queuedJob(JobQueued $event): void
+        public function queuedJob(JobQueueing|JobQueued $event): void
         {
             $this->thrown = true;
 
             throw new RuntimeException('Whoops!');
         }
     });
-    $handler = new JobQueuedListener($nightwatch);
+    $handler = new QueuedJobListener($nightwatch);
 
     $handler(new JobQueued('redis', 'default', '1', fn () => null, '{}', 0));