From 01686c5e25dd83ab89c6d85b36feec26e203e81b Mon Sep 17 00:00:00 2001
From: Mike Perham <mperham@gmail.com>
Date: Wed, 26 Jan 2022 16:57:43 -0800
Subject: [PATCH] Tweak job logger to reduce overhead, 3-4% speedup

---
 bin/sidekiqload           |  2 +-
 lib/sidekiq/job_logger.rb | 42 ++++++++++++++-------------------------
 lib/sidekiq/logger.rb     |  4 ++++
 3 files changed, 20 insertions(+), 28 deletions(-)

diff --git a/bin/sidekiqload b/bin/sidekiqload
index 63015db5..026c2903 100755
--- a/bin/sidekiqload
+++ b/bin/sidekiqload
@@ -86,7 +86,7 @@ def Process.rss
   `ps -o rss= -p #{Process.pid}`.chomp.to_i
 end
 
-iter = 10
+iter = 50
 count = 10_000
 
 iter.times do
diff --git a/lib/sidekiq/job_logger.rb b/lib/sidekiq/job_logger.rb
index eb789e39..91be17b1 100644
--- a/lib/sidekiq/job_logger.rb
+++ b/lib/sidekiq/job_logger.rb
@@ -12,46 +12,34 @@ module Sidekiq
 
       yield
 
-      with_elapsed_time_context(start) do
-        @logger.info("done")
-      end
+      Sidekiq::Context.add(:elapsed, elapsed(start))
+      @logger.info("done")
     rescue Exception
-      with_elapsed_time_context(start) do
-        @logger.info("fail")
-      end
+      Sidekiq::Context.add(:elapsed, elapsed(start))
+      @logger.info("fail")
 
       raise
     end
 
     def prepare(job_hash, &block)
-      level = job_hash["log_level"]
-      if level
-        @logger.log_at(level) do
-          Sidekiq::Context.with(job_hash_context(job_hash), &block)
-        end
-      else
-        Sidekiq::Context.with(job_hash_context(job_hash), &block)
-      end
-    end
-
-    def job_hash_context(job_hash)
       # If we're using a wrapper class, like ActiveJob, use the "wrapped"
       # attribute to expose the underlying thing.
       h = {
         class: job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"],
         jid: job_hash["jid"]
       }
-      h[:bid] = job_hash["bid"] if job_hash["bid"]
-      h[:tags] = job_hash["tags"] if job_hash["tags"]
-      h
-    end
+      h[:bid] = job_hash["bid"] if job_hash.has_key?("bid")
+      h[:tags] = job_hash["tags"] if job_hash.has_key?("tags")
 
-    def with_elapsed_time_context(start, &block)
-      Sidekiq::Context.with(elapsed_time_context(start), &block)
-    end
-
-    def elapsed_time_context(start)
-      {elapsed: elapsed(start).to_s}
+      Thread.current[:sidekiq_context] = h
+      level = job_hash["log_level"]
+      if level
+        @logger.log_at(level, &block)
+      else
+        yield
+      end
+    ensure
+      Thread.current[:sidekiq_context] = nil
     end
 
     private
diff --git a/lib/sidekiq/logger.rb b/lib/sidekiq/logger.rb
index 035f2a34..49d435a1 100644
--- a/lib/sidekiq/logger.rb
+++ b/lib/sidekiq/logger.rb
@@ -16,6 +16,10 @@ module Sidekiq
     def self.current
       Thread.current[:sidekiq_context] ||= {}
     end
+
+    def self.add(k, v)
+      Thread.current[:sidekiq_context][k] = v
+    end
   end
 
   module LoggingUtils