Adding enque time tracking and logging

Motivation:
  - Currently we have 2 seperate monkey patches in place for tracking
  enqueded time for 2 seperate workers. It seems that activejob could be
  a source of truth for how long an item has been enqued so that we can
  easily use it for consistent monitoring across workers/apps to ensure
  that jobs are running at an acceptable speed.

Changes:
  - Add an enqueded at attribute and serilization tooling.
  - Add a method to get how long a job has been enqueded for.
  - Add a logging item to show how long a job was enqued prior to the
  perform method firing.

4 files changed, 20 insertions, 2 deletions

diff --git a/activejob/lib/active_job/core.rb b/activejob/lib/active_job/core.rb
index 487cdd6d38..2ce008e3da 100644
--- a/activejob/lib/active_job/core.rb
+++ b/activejob/lib/active_job/core.rb
@@ -40,6 +40,9 @@ module ActiveJob
     # Timezone to be used during the job.
     attr_accessor :timezone
 
+    # Track when a job was enqueded
+    attr_accessor :enqueued_at
+
     # These methods will be included into any Active Job object, adding
     # helpers for de/serialization and creation of job instances.
     module ClassMethods
@@ -97,7 +100,8 @@ module ActiveJob
         "executions" => executions,
         "exception_executions" => exception_executions,
         "locale"     => I18n.locale.to_s,
-        "timezone"   => Time.zone.try(:name)
+        "timezone"   => Time.zone.try(:name),
+        "enqueued_at" => Time.now.utc.iso8601
       }
     end
 
@@ -137,6 +141,7 @@ module ActiveJob
       self.exception_executions = job_data["exception_executions"]
       self.locale               = job_data["locale"] || I18n.locale.to_s
       self.timezone             = job_data["timezone"] || Time.zone.try(:name)
+      self.enqueued_at          = job_data["enqueued_at"]
     end
 
     private
diff --git a/activejob/lib/active_job/logging.rb b/activejob/lib/active_job/logging.rb
index 416be83c24..1134e718a8 100644
--- a/activejob/lib/active_job/logging.rb
+++ b/activejob/lib/active_job/logging.rb
@@ -70,7 +70,7 @@ module ActiveJob
         def perform_start(event)
           info do
             job = event.payload[:job]
-            "Performing #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)}" + args_info(job)
+            "Performing #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)} enqueued at #{job.enqueued_at}" + args_info(job)
           end
         end
 
diff --git a/activejob/test/cases/job_serialization_test.rb b/activejob/test/cases/job_serialization_test.rb
index 86f3651564..c1cec1f1d6 100644
--- a/activejob/test/cases/job_serialization_test.rb
+++ b/activejob/test/cases/job_serialization_test.rb
@@ -61,4 +61,15 @@ class JobSerializationTest < ActiveSupport::TestCase
       assert_equal "Hawaii", job.serialize["timezone"]
     end
   end
+
+  test "serialize stores the enqueued_at time" do
+    h1 = HelloJob.new
+    type = h1.serialize["enqueued_at"].class
+    assert_equal String, type
+
+    h2 = HelloJob.deserialize(h1.serialize)
+    # We should be able to parse a timestamp
+    type = Time.parse(h2.enqueued_at).class
+    assert_equal Time, type
+  end
 end
diff --git a/activejob/test/cases/logging_test.rb b/activejob/test/cases/logging_test.rb
index 6154ba301d..acd37456c9 100644
--- a/activejob/test/cases/logging_test.rb
+++ b/activejob/test/cases/logging_test.rb
@@ -115,6 +115,8 @@ class LoggingTest < ActiveSupport::TestCase
     perform_enqueued_jobs do
       LoggingJob.perform_later "Dummy"
       assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
+
+      assert_match(/enqueued at /, @logger.messages)
       assert_match(/Dummy, here is it: Dummy/, @logger.messages)
       assert_match(/Performed LoggingJob \(Job ID: .*?\) from .*? in .*ms/, @logger.messages)
     end