Log time spent on CPU to sidekiq.log

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -8,16 +8,16 @@ module Gitlab
       MAXIMUM_JOB_ARGUMENTS_LENGTH = 10.kilobytes
 
       def call(job, queue)
-        started_at = current_time
+        started_time = get_time
         base_payload = parse_job(job)
 
-        Sidekiq.logger.info log_job_start(started_at, base_payload)
+        Sidekiq.logger.info log_job_start(base_payload)
 
         yield
 
-        Sidekiq.logger.info log_job_done(job, started_at, base_payload)
+        Sidekiq.logger.info log_job_done(job, started_time, base_payload)
       rescue => job_exception
-        Sidekiq.logger.warn log_job_done(job, started_at, base_payload, job_exception)
+        Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception)
 
         raise
       end
@@ -32,7 +32,7 @@ module Gitlab
         output_payload.merge!(job.slice(*::Gitlab::InstrumentationHelper::KEYS))
       end
 
-      def log_job_start(started_at, payload)
+      def log_job_start(payload)
         payload['message'] = "#{base_message(payload)}: start"
         payload['job_status'] = 'start'
 
@@ -45,11 +45,12 @@ module Gitlab
         payload
       end
 
-      def log_job_done(job, started_at, payload, job_exception = nil)
+      def log_job_done(job, started_time, payload, job_exception = nil)
         payload = payload.dup
         add_instrumentation_keys!(job, payload)
-        payload['duration'] = elapsed(started_at)
-        payload['completed_at'] = Time.now.utc
+
+        elapsed_time = elapsed(started_time)
+        add_time_keys!(elapsed_time, payload)
 
         message = base_message(payload)
 
@@ -69,6 +70,14 @@ module Gitlab
         payload
       end
 
+      def add_time_keys!(time, payload)
+        payload['duration'] = time[:duration].round(3)
+        payload['system_s'] = time[:stime].round(3)
+        payload['user_s'] = time[:utime].round(3)
+        payload['child_s'] = time[:ctime].round(3) if time[:ctime] > 0
+        payload['completed_at'] = Time.now.utc
+      end
+
       def parse_job(job)
         job = job.dup
 
@@ -93,8 +102,25 @@ module Gitlab
         (Time.now.utc - start).to_f.round(3)
       end
 
-      def elapsed(start)
-        (current_time - start).round(3)
+      def elapsed(t0)
+        t1 = get_time
+        {
+          duration: t1[:now] - t0[:now],
+          stime: t1[:times][:stime] - t0[:times][:stime],
+          utime: t1[:times][:utime] - t0[:times][:utime],
+          ctime: ctime(t1[:times]) - ctime(t0[:times])
+        }
+      end
+
+      def get_time
+        {
+          now: current_time,
+          times: Process.times
+        }
+      end
+
+      def ctime(times)
+        times[:cstime] + times[:cutime]
       end
 
       def current_time

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -36,7 +36,9 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
         'job_status' => 'done',
         'duration' => 0.0,
-        "completed_at" => timestamp.iso8601(3)
+        "completed_at" => timestamp.iso8601(3),
+        "system_s" => 0.0,
+        "user_s" => 0.0
       )
     end
     let(:exception_payload) do
@@ -52,6 +54,13 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       allow(Sidekiq).to receive(:logger).and_return(logger)
 
       allow(subject).to receive(:current_time).and_return(timestamp.to_f)
+
+      allow(Process).to receive(:times).and_return(
+        stime:  0.0,
+        utime:  0.0,
+        cutime: 0.0,
+        cstime: 0.0
+      )
     end
 
     subject { described_class.new }
@@ -177,5 +186,31 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         end
       end
     end
+
+    def ctime(times)
+      times[:cstime] + times[:cutime]
+    end
+
+    context 'with ctime value greater than 0' do
+      let(:times_start) { { stime: 0.04999, utime: 0.0483, cstime: 0.0188, cutime: 0.0188 } }
+      let(:times_end)   { { stime: 0.0699, utime: 0.0699, cstime: 0.0399, cutime: 0.0399 } }
+
+      before do
+        end_payload['system_s'] = 0.02
+        end_payload['user_s'] = 0.022
+        end_payload['child_s'] = 0.042
+
+        allow(Process).to receive(:times).and_return(times_start, times_end)
+      end
+
+      it 'logs with ctime data and other cpu data' do
+        Timecop.freeze(timestamp) do
+          expect(logger).to receive(:info).with(start_payload.except('args')).ordered
+          expect(logger).to receive(:info).with(end_payload.except('args')).ordered
+
+          subject.call(job, 'test_queue') { }
+        end
+      end
+    end
   end
 end