Adding enque time tracking and logging #35238

gwincr11 · 2019-02-12T18:59:04Z

Motivation:

Currently we have 2 separate monkey patches in place for tracking
enqueued time for 2 separate workers. It seems that activejob could be
a source of truth for how long an item has been enqueued 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 enqueued at attribute and serialization tooling.
Add a method to get how long a job has been enqueued for.
Add a logging item to show how long a job was enqueued prior to the
perform method firing.

Summary

Other Information

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.

rafaelfranca · 2019-02-12T19:13:10Z

Should we take retries in consideration? Let say a job needs to be retried 10 times, is the time on queue the same as the difference between the first time it was enqueued and the time it is being executed or should we just consider the last time it was retried?

rafaelfranca · 2019-02-12T19:16:26Z

activejob/lib/active_job/core.rb

@@ -97,7 +100,8 @@ def serialize
        "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


Maybe we should use the UTC time?

rafaelfranca · 2019-02-12T19:21:20Z

I just checked our application and we don't take in consideration retries, so this is enough for me.

tenderlove · 2019-02-12T19:24:07Z

activejob/lib/active_job/logging.rb

            "Performing #{job.class.name} (Job ID: #{job.job_id}) from #{queue_name(event)}" + args_info(job)
          end
+          info do
+            "#{job.class.name} (Job ID: #{job.job_id}) waited in the queue for #{job.enqueded_for}ms"
+          end


Can we make the wait time part of the other log message? Then we don't need to have two info blocks.

I believe the job = event... line was moved inside the info block for performance (so it doesn't get executed unless the logger is in info mode).

tenderlove · 2019-02-12T19:28:55Z

activejob/lib/active_job/core.rb

+    end
+
+    def enqueded_for
+      Time.now - enqueued_at


Do we actually need to calculate how long the job has been in the queue? I would expect the log messages to have a timestamp. If the log message has a time stamp, we can just log the "enqueued time" and whatever reads the log messages can calculate how long the message sat in the queue. Logging just the duration means that we lose the "enqueued_at" information (or we have to take the log timestamp and subtract the duration to back in to the value).

In our application we only lock the enqueued_at.

rafaelfranca · 2019-02-12T19:35:02Z

activejob/test/cases/job_serialization_test.rb

+  test "serialize stores the enqueued_at time" do
+    job = HelloJob.new
+    type = job.serialize["enqueued_at"].class
+    assert_equal Time, type


Not sure if returning a Time object from serialize is a good idea. It will work in JSON-based adapters but the problem is that the roundtrip of this value will return a String, so maybe it better to be explicit about the string conversion we want to do?

Is there a Rails preferred format for this sort of data?

I changed it to be a string then added a test to make sure it could be parsed.

rafaelfranca · 2019-02-12T19:37:35Z

activejob/lib/active_job/core.rb

+    end
+
+    def enqueded_for
+      Time.now.utc - enqueued_at


Is this working? enqueued_at will be a string and when I try Time.now.utc - JSON.load(JSON.dump(Time.now.utc)) I get an error.

I think I will remove it per @tenderlove's suggestion.

…g, and serialize the timestamp as a string

kaspth · 2019-02-12T21:06:48Z

activejob/test/cases/logging_test.rb

@@ -115,6 +115,8 @@ def test_perform_job_logging
    perform_enqueued_jobs do
      LoggingJob.perform_later "Dummy"
      assert_match(/Performing LoggingJob \(Job ID: .*?\) from .*? with arguments:.*Dummy/, @logger.messages)
+
+      assert_match(/added to queue at /, @logger.messages)


Let’s just say “enqueued at”, so we keep the language the same.

rafaelfranca · 2019-02-12T21:32:22Z

activejob/lib/active_job/core.rb

@@ -97,7 +100,8 @@ def serialize
        "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.to_s


mayb Time.now.utc.iso8601?

gwincr11 · 2019-02-13T18:29:47Z

I am not sure how to get the test to rebuild, it looks like it just failed to start?

rafaelfranca · 2019-02-14T00:21:38Z

Thanks! Merged in ac68550

Adding enque time tracking and logging

Adding enque time tracking and logging rails/rails#35238

rails-bot bot added the activejob label Feb 12, 2019

spelling

63630e2

rafaelfranca reviewed Feb 12, 2019

View reviewed changes

eileencodes added this to the 6.0.0 milestone Feb 12, 2019

utc time

54ff030

tenderlove reviewed Feb 12, 2019

View reviewed changes

rafaelfranca reviewed Feb 12, 2019

View reviewed changes

remove the enqueded_for logic, add enqueued at to existing perform lo…

50595ff

…g, and serialize the timestamp as a string

kaspth reviewed Feb 12, 2019

View reviewed changes

logging language

e18a321

rafaelfranca reviewed Feb 12, 2019

View reviewed changes

date format

47eaf99

rafaelfranca closed this Feb 14, 2019

rafaelfranca added a commit that referenced this pull request Feb 14, 2019

Merge pull request #35238 from gwincr11/cg-active-job-queue-time

ac68550

Adding enque time tracking and logging

suketa added a commit to suketa/rails_sandbox that referenced this pull request Aug 16, 2019

try075

150c632

Adding enque time tracking and logging rails/rails#35238

bensheldon mentioned this pull request Apr 26, 2023

Set, serialize, and deserialize Active Job scheduled_at as Time; deserialize enqueued_at as Time; deprecate setting scheduled_at= with numeric/epoch #48066

Merged

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adding enque time tracking and logging #35238

Adding enque time tracking and logging #35238

gwincr11 commented Feb 12, 2019 •

edited

rafaelfranca commented Feb 12, 2019

rafaelfranca Feb 12, 2019

rafaelfranca commented Feb 12, 2019

tenderlove Feb 12, 2019

tenderlove Feb 12, 2019

rafaelfranca Feb 12, 2019

rafaelfranca Feb 12, 2019

gwincr11 Feb 12, 2019

gwincr11 Feb 12, 2019

rafaelfranca Feb 12, 2019

gwincr11 Feb 12, 2019

kaspth Feb 12, 2019

rafaelfranca Feb 12, 2019

gwincr11 Feb 12, 2019

gwincr11 commented Feb 13, 2019

rafaelfranca commented Feb 14, 2019

Adding enque time tracking and logging #35238

Adding enque time tracking and logging #35238

Conversation

gwincr11 commented Feb 12, 2019 • edited

Summary

Other Information

rafaelfranca commented Feb 12, 2019

Choose a reason for hiding this comment

rafaelfranca commented Feb 12, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gwincr11 commented Feb 13, 2019

rafaelfranca commented Feb 14, 2019

gwincr11 commented Feb 12, 2019 •

edited