Merge branch 'master' of gitlab_gitlab:gitlab-org/gitlab-cerunner-metrics-extractor

1 files changed, 51 insertions, 10 deletions

diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb
index fdc0d518c59..48b1524f9c7 100644
--- a/lib/gitlab/sidekiq_logging/structured_logger.rb
+++ b/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(started_at, base_payload)
+        Sidekiq.logger.info log_job_done(job, started_time, base_payload)
       rescue => job_exception
-        Sidekiq.logger.warn log_job_done(started_at, base_payload, job_exception)
+        Sidekiq.logger.warn log_job_done(job, started_time, base_payload, job_exception)
 
         raise
       end
@@ -28,17 +28,29 @@ module Gitlab
         "#{payload['class']} JID-#{payload['jid']}"
       end
 
-      def log_job_start(started_at, payload)
+      def add_instrumentation_keys!(job, output_payload)
+        output_payload.merge!(job.slice(*::Gitlab::InstrumentationHelper::KEYS))
+      end
+
+      def log_job_start(payload)
         payload['message'] = "#{base_message(payload)}: start"
         payload['job_status'] = 'start'
 
+        # Old gitlab-shell messages don't provide enqueued_at/created_at attributes
+        enqueued_at = payload['enqueued_at'] || payload['created_at']
+        if enqueued_at
+          payload['scheduling_latency_s'] = elapsed_by_absolute_time(Time.iso8601(enqueued_at))
+        end
+
         payload
       end
 
-      def log_job_done(started_at, payload, job_exception = nil)
+      def log_job_done(job, started_time, payload, job_exception = nil)
         payload = payload.dup
-        payload['duration'] = elapsed(started_at)
-        payload['completed_at'] = Time.now.utc
+        add_instrumentation_keys!(job, payload)
+
+        elapsed_time = elapsed(started_time)
+        add_time_keys!(elapsed_time, payload)
 
         message = base_message(payload)
 
@@ -58,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
 
@@ -78,8 +98,29 @@ module Gitlab
         end
       end
 
-      def elapsed(start)
-        (current_time - start).round(3)
+      def elapsed_by_absolute_time(start)
+        (Time.now.utc - start).to_f.round(3)
+      end
+
+      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