diff --git a/lib/gitlab/sidekiq_logging/structured_logger.rb b/lib/gitlab/sidekiq_logging/structured_logger.rb index 60782306adee26df11117c7b39283667fa350b59..48b1524f9c770f3ccba07581a61399172b76aa29 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(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 diff --git a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb b/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb index 5621d3d17d18273d7442f496843ca936163d2440..c09db4af8d8145fe3ff157177edd8e1d42fc2ee6 100644 --- a/spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb +++ b/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