From f4e23651b75d9f3fc581b8a21c04d1064f75568e Mon Sep 17 00:00:00 2001
From: Vojta Drbohlav <vojta.d@gmail.com>
Date: Mon, 18 Aug 2025 22:58:00 +0200
Subject: [PATCH] Fix activejob_latency metric for jobs scheduled to run in the
 future

- Job latency is now measured as a difference between scheduled and running time.
- Tests are included.

Fix #21
---
 Gemfile.lock                  |  1 +
 lib/yabeda/activejob.rb       | 10 +++---
 spec/yabeda/activejob_spec.rb | 58 ++++++++++++++++++++++++++++++-----
 3 files changed, 56 insertions(+), 13 deletions(-)

diff --git a/Gemfile.lock b/Gemfile.lock
index f9d6cf2..4b56955 100644
--- a/Gemfile.lock
+++ b/Gemfile.lock
@@ -211,6 +211,7 @@ GEM
 
 PLATFORMS
   arm64-darwin-23
+  arm64-darwin-24
   x86_64-darwin-21
   x86_64-linux
 
diff --git a/lib/yabeda/activejob.rb b/lib/yabeda/activejob.rb
index 670f847..5bd57bd 100644
--- a/lib/yabeda/activejob.rb
+++ b/lib/yabeda/activejob.rb
@@ -33,7 +33,7 @@ def self.install!
                             tags: %i[queue activejob executions],
                             buckets: LONG_RUNNING_JOB_RUNTIME_BUCKETS
 
-        histogram :latency, comment: "The job latency, the difference in seconds between enqueued and running time",
+        histogram :latency, comment: "The job latency, the difference in seconds between scheduled and running time",
                             unit: :seconds, per: :activejob,
                             tags: %i[queue activejob executions],
                             buckets: LONG_RUNNING_JOB_RUNTIME_BUCKETS
@@ -93,13 +93,13 @@ def self.install!
     # rubocop: enable Metrics/MethodLength, Metrics/BlockLength, Metrics/AbcSize
 
     def self.job_latency(event)
-      enqueue_time = event.payload[:job].enqueued_at
-      return nil unless enqueue_time.present?
+      scheduled_time = event.payload[:job].scheduled_at || event.payload[:job].enqueued_at
+      return nil unless scheduled_time.present?
 
-      enqueue_time = parse_event_time(enqueue_time)
+      scheduled_time = parse_event_time(scheduled_time)
       perform_at_time = parse_event_time(event.end)
 
-      perform_at_time - enqueue_time
+      perform_at_time - scheduled_time
     end
 
     def self.ms2s(milliseconds)
diff --git a/spec/yabeda/activejob_spec.rb b/spec/yabeda/activejob_spec.rb
index 0ac269e..c72330c 100644
--- a/spec/yabeda/activejob_spec.rb
+++ b/spec/yabeda/activejob_spec.rb
@@ -57,10 +57,10 @@
 
     describe "#job_latency" do
       # Rails 7.1.4 and above
-      it "returns the correct latency from end_time in seconds" do
-        start_time = Time.now
+      it "returns the correct latency from end_time in seconds for job without a wait time" do
+        enqueued_time = Time.now
         job = HelloJob.new
-        job.enqueued_at = start_time
+        job.enqueued_at = enqueued_time
         event = ActiveSupport::Notifications::Event.new(
           "perform_start.active_job",
           nil,
@@ -68,17 +68,59 @@
           1,
           { job: job },
         )
-        end_time_in_s = 1.minute.from_now(start_time).to_f
+        end_time_in_s = 1.minute.from_now(enqueued_time).to_f
         allow(event).to receive(:end).and_return(end_time_in_s)
 
         expect(described_class.job_latency(event)).to be_within(0.1).of(60.0)
       end
 
+      # Rails 7.1.4 and above
+      it "returns the correct latency from end_time in seconds for job with wait time" do
+        enqueued_time = Time.now
+        wait = 1.minute
+        scheduled_time = enqueued_time + wait
+        job = HelloJob.new
+        job.enqueued_at = enqueued_time
+        job.scheduled_at = scheduled_time
+        event = ActiveSupport::Notifications::Event.new(
+          "perform_start.active_job",
+          nil,
+          nil,
+          1,
+          { job: job },
+        )
+        end_time_in_s = 1.minute.from_now(scheduled_time).to_f
+        allow(event).to receive(:end).and_return(end_time_in_s)
+
+        expect(described_class.job_latency(event)).to be_within(0.1).of(60.0)
+      end
+
+      # Rails 7.1.3 and below
+      it "returns the correct latency from end_time in milliseconds for job without a wait time" do
+        enqueued_time = Time.now
+        job = HelloJob.new
+        job.enqueued_at = enqueued_time
+        event = ActiveSupport::Notifications::Event.new(
+          "perform_start.active_job",
+          nil,
+          nil,
+          1,
+          { job: job },
+        )
+        end_time_in_ms = 1.minute.from_now(enqueued_time).to_f * 1000
+        allow(event).to receive(:end).and_return(end_time_in_ms)
+
+        expect(described_class.job_latency(event)).to be_within(0.1).of(60.0)
+      end
+
       # Rails 7.1.3 and below
-      it "returns the correct latency from end_time in milliseconds" do
-        start_time = Time.now
+      it "returns the correct latency from end_time in milliseconds for job with a wait time" do
+        enqueued_time = Time.now
+        wait = 1.minute
+        scheduled_time = enqueued_time + wait
         job = HelloJob.new
-        job.enqueued_at = start_time
+        job.enqueued_at = enqueued_time
+        job.scheduled_at = scheduled_time
         event = ActiveSupport::Notifications::Event.new(
           "perform_start.active_job",
           nil,
@@ -86,7 +128,7 @@
           1,
           { job: job },
         )
-        end_time_in_ms = 1.minute.from_now(start_time).to_f * 1000
+        end_time_in_ms = 1.minute.from_now(scheduled_time).to_f * 1000
         allow(event).to receive(:end).and_return(end_time_in_ms)
 
         expect(described_class.job_latency(event)).to be_within(0.1).of(60.0)