Standardize Sidekiq/Rails log keys with _s suffix

It makes the decision on how to log timings within
JSON logs based on
https://www.robustperception.io/who-wants-seconds.

app/controllers/application_controller.rb

@@ -150,7 +150,7 @@ class ApplicationController < ActionController::Base
       payload[:username] = logged_user.try(:username)
     end
 
-    payload[:queue_duration] = request.env[::Gitlab::Middleware::RailsQueueDuration::GITLAB_RAILS_QUEUE_DURATION_KEY]
+    payload[:queue_duration_s] = request.env[::Gitlab::Middleware::RailsQueueDuration::GITLAB_RAILS_QUEUE_DURATION_KEY]
   end
 
   ##

config/initializers/lograge.rb

@@ -12,6 +12,10 @@ unless Gitlab::Runtime.sidekiq?
     config.lograge.logger = ActiveSupport::Logger.new(filename)
     config.lograge.before_format = lambda do |data, payload|
       data.delete(:error)
+      data[:db_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:db))
+      data[:view_duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:view))
+      data[:duration_s] = Gitlab::Utils.ms_to_round_sec(data.delete(:duration))
+
       data
     end
 

doc/administration/logs.md

@@ -30,17 +30,21 @@ Line breaks have been added to this example for legibility:
   "controller":"Projects::IssuesController",
   "action":"show",
   "status":200,
-  "duration":229.03,
-  "view":174.07,
-  "db":13.24,
   "time":"2017-08-08T20:15:54.821Z",
   "params":[{"key":"param_key","value":"param_value"}],
   "remote_ip":"18.245.0.1",
   "user_id":1,
   "username":"admin",
-  "gitaly_calls":76,
-  "gitaly_duration":7.41,
-  "queue_duration": 112.47
+  "queue_duration_s":0.0,
+  "gitaly_calls":16,
+  "gitaly_duration_s":0.16,
+  "redis_calls":115,
+  "redis_duration_s":0.13,
+  "correlation_id":"O1SdybnnIq7",
+  "cpu_s":17.50,
+  "db_duration_s":0.08,
+  "view_duration_s":2.39,
+  "duration_s":20.54
 }
 ```
 
@@ -48,12 +52,15 @@ This example was a GET request for a specific
 issue. Each line also contains performance data, with times in
 milliseconds:
 
-1. `duration`: total time taken to retrieve the request
-1. `queue_duration`: total time that the request was queued inside GitLab Workhorse
-1. `view`: total time taken inside the Rails views
-1. `db`: total time to retrieve data from the database
+1. `duration_s`: total time taken to retrieve the request
+1. `queue_duration_s`: total time that the request was queued inside GitLab Workhorse
+1. `view_duration_s`: total time taken inside the Rails views
+1. `db_duration_s`: total time to retrieve data from PostgreSQL
+1. `redis_duration_s`: total time to retrieve data from Redis
+1. `cpu_s`: total time spent on CPU
+1. `gitaly_duration_s`: total time taken by Gitaly calls
 1. `gitaly_calls`: total number of calls made to Gitaly
-1. `gitaly_duration`: total time taken by Gitaly calls
+1. `redis_calls`: total number of calls made to Redis
 
 User clone and fetch activity using HTTP transport appears in this log as `action: git_upload_pack`.
 
@@ -73,9 +80,6 @@ NOTE: **Note:** Starting with GitLab 12.5, if an error occurs, an
   "controller": "Admin::DashboardController",
   "action": "index",
   "status": 500,
-  "duration": 2584.11,
-  "view": 0,
-  "db": 9.21,
   "time": "2019-11-14T13:12:46.156Z",
   "params": [],
   "remote_ip": "127.0.0.1",
@@ -84,7 +88,16 @@ NOTE: **Note:** Starting with GitLab 12.5, if an error occurs, an
   "ua": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:70.0) Gecko/20100101 Firefox/70.0",
   "queue_duration": 274.35,
   "correlation_id": "KjDVUhNvvV3",
-  "cpu_s": 2.837645135999999,
+  "queue_duration_s":0.0,
+  "gitaly_calls":16,
+  "gitaly_duration_s":0.16,
+  "redis_calls":115,
+  "redis_duration_s":0.13,
+  "correlation_id":"O1SdybnnIq7",
+  "cpu_s":17.50,
+  "db_duration_s":0.08,
+  "view_duration_s":2.39,
+  "duration_s":20.54
   "exception.class": "NameError",
   "exception.message": "undefined local variable or method `adsf' for #<Admin::DashboardController:0x00007ff3c9648588>",
   "exception.backtrace": [

doc/development/logging.md

@@ -164,6 +164,14 @@ Resources:
 - [Elasticsearch mapping - avoiding type gotchas](https://www.elastic.co/guide/en/elasticsearch/guide/current/mapping.html#_avoiding_type_gotchas)
 - [Elasticsearch mapping types]( https://www.elastic.co/guide/en/elasticsearch/reference/current/mapping-types.html)
 
+#### Logging durations
+
+Similar to timezones, choosing the right time unit to log can impose avoidable overhead. So, whenever
+challenged to choose between seconds, milliseconds or any other unit, lean towards _seconds_ as float.
+
+In order to make it easier to track timings in the logs, make sure the log key has `_s` as
+suffix and `duration` within its name (e.g., `view_duration_s`).
+
 ## Multi-destination Logging
 
 GitLab is transitioning from unstructured/plaintext logs to structured/JSON logs. During this transition period some logs will be recorded in multiple formats through multi-destination logging.

lib/gitlab/gitaly_client.rb

@@ -216,10 +216,6 @@ module Gitlab
       SafeRequestStore[:gitaly_query_time] = duration
     end
 
-    def self.query_time_ms
-      (self.query_time * 1000).round(2)
-    end
-
     def self.current_transaction_labels
       Gitlab::Metrics::Transaction.current&.labels || {}
     end

lib/gitlab/grape_logging/formatters/lograge_with_timestamp.rb

@@ -15,9 +15,9 @@ module Gitlab
           attributes = {
             time: datetime.utc.iso8601(3),
             severity: severity,
-            duration: time[:total],
-            db: time[:db],
-            view: time[:view]
+            duration_s: Gitlab::Utils.ms_to_round_sec(time[:total]),
+            db_duration_s: Gitlab::Utils.ms_to_round_sec(time[:db]),
+            view_duration_s: Gitlab::Utils.ms_to_round_sec(time[:view])
           }.merge!(data)
 
           ::Lograge.formatter.call(attributes) << "\n"

lib/gitlab/grape_logging/loggers/queue_duration_logger.rb

@@ -18,9 +18,9 @@ module Gitlab
           return {} unless proxy_start && start_time
 
           # Time in milliseconds since gitlab-workhorse started the request
-          duration = (start_time.to_f * 1_000 - proxy_start.to_f / 1_000_000).round(2)
+          duration = start_time.to_f * 1_000 - proxy_start.to_f / 1_000_000
 
-          { 'queue_duration': duration }
+          { 'queue_duration_s': Gitlab::Utils.ms_to_round_sec(duration) }
         end
       end
     end

lib/gitlab/instrumentation/redis.rb

@@ -37,10 +37,6 @@ module Gitlab
         ::RequestStore[REDIS_CALL_DETAILS] ||= []
       end
 
-      def self.query_time_ms
-        (self.query_time * 1000).round(2)
-      end
-
       def self.query_time
         ::RequestStore[REDIS_CALL_DURATION] || 0
       end

lib/gitlab/instrumentation_helper.rb

@@ -4,28 +4,28 @@ module Gitlab
   module InstrumentationHelper
     extend self
 
-    KEYS = %i(gitaly_calls gitaly_duration rugged_calls rugged_duration_ms redis_calls redis_duration_ms).freeze
+    KEYS = %i(gitaly_calls gitaly_duration_s rugged_calls rugged_duration_s redis_calls redis_duration_s).freeze
 
     def add_instrumentation_data(payload)
       gitaly_calls = Gitlab::GitalyClient.get_request_count
 
       if gitaly_calls > 0
         payload[:gitaly_calls] = gitaly_calls
-        payload[:gitaly_duration] = Gitlab::GitalyClient.query_time_ms
+        payload[:gitaly_duration_s] = Gitlab::GitalyClient.query_time.round(2)
       end
 
       rugged_calls = Gitlab::RuggedInstrumentation.query_count
 
       if rugged_calls > 0
         payload[:rugged_calls] = rugged_calls
-        payload[:rugged_duration_ms] = Gitlab::RuggedInstrumentation.query_time_ms
+        payload[:rugged_duration_s] = Gitlab::RuggedInstrumentation.query_time.round(2)
       end
 
       redis_calls = Gitlab::Instrumentation::Redis.get_request_count
 
       if redis_calls > 0
         payload[:redis_calls] = redis_calls
-        payload[:redis_duration_ms] = Gitlab::Instrumentation::Redis.query_time_ms
+        payload[:redis_duration_s] = Gitlab::Instrumentation::Redis.query_time.round(2)
       end
     end
 
@@ -47,7 +47,7 @@ module Gitlab
       # Its possible that if theres clock-skew between two nodes
       # this value may be less than zero. In that event, we record the value
       # as zero.
-      [elapsed_by_absolute_time(enqueued_at_time), 0].max
+      [elapsed_by_absolute_time(enqueued_at_time), 0].max.round(2)
     end
 
     # Calculates the time in seconds, as a float, from

lib/gitlab/lograge/custom_options.rb

@@ -18,7 +18,7 @@ module Gitlab
           user_id: event.payload[:user_id],
           username: event.payload[:username],
           ua: event.payload[:ua],
-          queue_duration: event.payload[:queue_duration]
+          queue_duration_s: event.payload[:queue_duration_s]
         }
 
         ::Gitlab::InstrumentationHelper.add_instrumentation_data(payload)
@@ -28,7 +28,7 @@ module Gitlab
         payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
 
         if cpu_s = Gitlab::Metrics::System.thread_cpu_duration(::Gitlab::RequestContext.instance.start_thread_cpu_time)
-          payload[:cpu_s] = cpu_s
+          payload[:cpu_s] = cpu_s.round(2)
         end
 
         # https://github.com/roidrage/lograge#logging-errors--exceptions

lib/gitlab/middleware/rails_queue_duration.rb

@@ -20,8 +20,10 @@ module Gitlab
           # Time in milliseconds since gitlab-workhorse started the request
           duration = Time.now.to_f * 1_000 - proxy_start.to_f / 1_000_000
           trans.set(:rails_queue_duration, duration)
-          metric_rails_queue_duration_seconds.observe(trans.labels, duration / 1_000)
-          env[GITLAB_RAILS_QUEUE_DURATION_KEY] = duration.round(2)
+
+          duration_s = Gitlab::Utils.ms_to_round_sec(duration)
+          metric_rails_queue_duration_seconds.observe(trans.labels, duration_s)
+          env[GITLAB_RAILS_QUEUE_DURATION_KEY] = duration_s
         end
 
         @app.call(env)

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -50,27 +50,27 @@ module Gitlab
         message = base_message(payload)
 
         if job_exception
-          payload['message'] = "#{message}: fail: #{payload['duration']} sec"
+          payload['message'] = "#{message}: fail: #{payload['duration_s']} sec"
           payload['job_status'] = 'fail'
           payload['error_message'] = job_exception.message
           payload['error_class'] = job_exception.class.name
         else
-          payload['message'] = "#{message}: done: #{payload['duration']} sec"
+          payload['message'] = "#{message}: done: #{payload['duration_s']} sec"
           payload['job_status'] = 'done'
         end
 
-        payload['db_duration'] = ActiveRecord::LogSubscriber.runtime
-        payload['db_duration_s'] = payload['db_duration'] / 1000
+        db_duration = ActiveRecord::LogSubscriber.runtime
+        payload['db_duration_s'] = Gitlab::Utils.ms_to_round_sec(db_duration)
 
         payload
       end
 
       def add_time_keys!(time, payload)
-        payload['duration'] = time[:duration].round(6)
+        payload['duration_s'] = time[:duration].round(2)
 
         # ignore `cpu_s` if the platform does not support Process::CLOCK_THREAD_CPUTIME_ID (time[:cputime] == 0)
         # supported OS version can be found at: https://www.rubydoc.info/stdlib/core/2.1.6/Process:clock_gettime
-        payload['cpu_s'] = time[:cputime].round(6) if time[:cputime] > 0
+        payload['cpu_s'] = time[:cputime].round(2) if time[:cputime] > 0
         payload['completed_at'] = Time.now.utc.to_f
       end
 

lib/gitlab/sidekiq_middleware/server_metrics.rb

@@ -71,7 +71,7 @@ module Gitlab
       end
 
       def get_gitaly_time(job)
-        job.fetch(:gitaly_duration, 0) / 1000.0
+        job.fetch(:gitaly_duration_s, 0)
       end
     end
   end

lib/gitlab/utils.rb

@@ -122,6 +122,10 @@ module Gitlab
       bytes.to_f / Numeric::MEGABYTE
     end
 
+    def ms_to_round_sec(ms)
+      (ms.to_f / 1000).round(2)
+    end
+
     # Used in EE
     # Accepts either an Array or a String and returns an array
     def ensure_array_from_string(string_or_array)

spec/initializers/lograge_spec.rb

@@ -64,11 +64,11 @@ describe 'lograge', type: :request do
         )
 
       expect(Lograge.formatter).to receive(:call)
-        .with(a_hash_including(cpu_s: 0.1111115))
+        .with(a_hash_including(cpu_s: 0.11))
         .and_call_original
 
       expect(Lograge.logger).to receive(:send)
-        .with(anything, include('"cpu_s":0.1111115'))
+        .with(anything, include('"cpu_s":0.11'))
         .and_call_original
 
       subject

spec/lib/gitlab/gitaly_client_spec.rb

@@ -19,6 +19,15 @@ describe Gitlab::GitalyClient do
     })
   end
 
+  describe '.query_time', :request_store do
+    it 'increments query times' do
+      subject.query_time += 0.451
+      subject.query_time += 0.322
+
+      expect(subject.query_time).to eq(0.773)
+    end
+  end
+
   describe '.long_timeout' do
     context 'default case' do
       it { expect(subject.long_timeout).to eq(6.hours) }

spec/lib/gitlab/grape_logging/loggers/perf_logger_spec.rb

@@ -21,7 +21,7 @@ describe Gitlab::GrapeLogging::Loggers::PerfLogger do
         payload = subject.parameters(mock_request, nil)
 
         expect(payload[:redis_calls]).to eq(1)
-        expect(payload[:redis_duration_ms]).to be >= 0
+        expect(payload[:redis_duration_s]).to be >= 0
       end
     end
   end

spec/lib/gitlab/grape_logging/loggers/queue_duration_logger_spec.rb

@@ -25,11 +25,11 @@ describe Gitlab::GrapeLogging::Loggers::QueueDurationLogger do
         )
       end
 
-      it 'returns the correct duration in ms' do
+      it 'returns the correct duration in seconds' do
         Timecop.freeze(start_time) do
           subject.before
 
-          expect(subject.parameters(mock_request, nil)).to eq( { 'queue_duration': 1.hour.to_f * 1000 })
+          expect(subject.parameters(mock_request, nil)).to eq( { 'queue_duration_s': 1.hour.to_f })
         end
       end
     end

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -26,7 +26,7 @@ describe Gitlab::InstrumentationHelper do
         subject
 
         expect(payload[:gitaly_calls]).to eq(1)
-        expect(payload[:gitaly_duration]).to be >= 0
+        expect(payload[:gitaly_duration_s]).to be >= 0
         expect(payload[:redis_calls]).to be_nil
         expect(payload[:redis_duration_ms]).to be_nil
       end
@@ -39,7 +39,7 @@ describe Gitlab::InstrumentationHelper do
         subject
 
         expect(payload[:redis_calls]).to eq(1)
-        expect(payload[:redis_duration_ms]).to be >= 0
+        expect(payload[:redis_duration_s]).to be >= 0
         expect(payload[:gitaly_calls]).to be_nil
         expect(payload[:gitaly_duration]).to be_nil
       end
@@ -49,12 +49,12 @@ describe Gitlab::InstrumentationHelper do
   describe '.queue_duration_for_job' do
     where(:enqueued_at, :created_at, :time_now, :expected_duration) do
       "2019-06-01T00:00:00.000+0000" | nil                            | "2019-06-01T02:00:00.000+0000" | 2.hours.to_f
-      "2019-06-01T02:00:00.000+0000" | nil                            | "2019-06-01T02:00:00.001+0000" | 0.001
+      "2019-06-01T02:00:00.000+0000" | nil                            | "2019-06-01T02:00:00.001+0000" | 0.0
       "2019-06-01T02:00:00.000+0000" | "2019-05-01T02:00:00.000+0000" | "2019-06-01T02:00:01.000+0000" | 1
-      nil                            | "2019-06-01T02:00:00.000+0000" | "2019-06-01T02:00:00.001+0000" | 0.001
+      nil                            | "2019-06-01T02:00:00.000+0000" | "2019-06-01T02:00:00.001+0000" | 0.0
       nil                            | nil                            | "2019-06-01T02:00:00.001+0000" | nil
       "2019-06-01T02:00:00.000+0200" | nil                            | "2019-06-01T02:00:00.000-0200" | 4.hours.to_f
-      1571825569.998168              | nil                            | "2019-10-23T12:13:16.000+0200" | 26.001832
+      1571825569.998168              | nil                            | "2019-10-23T12:13:16.000+0200" | 26.00
       1571825569                     | nil                            | "2019-10-23T12:13:16.000+0200" | 27
       "invalid_date"                 | nil                            | "2019-10-23T12:13:16.000+0200" | nil
       ""                             | nil                            | "2019-10-23T12:13:16.000+0200" | nil

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -42,11 +42,10 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       start_payload.merge(
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
         'job_status' => 'done',
-        'duration' => 0.0,
+        'duration_s' => 0.0,
         'completed_at' => timestamp.to_f,
-        'cpu_s' => 1.111112,
-        'db_duration' => 0,
-        'db_duration_s' => 0
+        'cpu_s' => 1.11,
+        'db_duration_s' => 0.0
       )
     end
     let(:exception_payload) do
@@ -160,11 +159,11 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       let(:timing_data) do
         {
           gitaly_calls: 10,
-          gitaly_duration: 10000,
+          gitaly_duration_s: 10000,
           rugged_calls: 1,
-          rugged_duration_ms: 5000,
+          rugged_duration_s: 5000,
           redis_calls: 3,
-          redis_duration_ms: 1234
+          redis_duration_s: 1234
         }
       end
 
@@ -193,12 +192,11 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
       let(:expected_start_payload) { start_payload.except('args') }
 
       let(:expected_end_payload) do
-        end_payload.except('args').merge('cpu_s' => a_value > 0)
+        end_payload.except('args').merge('cpu_s' => a_value >= 0)
       end
 
       let(:expected_end_payload_with_db) do
         expected_end_payload.merge(
-          'db_duration' => a_value >= 100,
           'db_duration_s' => a_value >= 0.1
         )
       end
@@ -226,7 +224,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
     let(:time) { { duration: 0.1231234, cputime: 1.2342345 } }
     let(:payload) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status' } }
     let(:current_utc_time) { Time.now.utc }
-    let(:payload_with_time_keys) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status', 'duration' => 0.123123, 'cpu_s' => 1.234235, 'completed_at' => current_utc_time.to_f } }
+    let(:payload_with_time_keys) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status', 'duration_s' => 0.12, 'cpu_s' => 1.23, 'completed_at' => current_utc_time.to_f } }
 
     subject { described_class.new }
 

spec/lib/gitlab/utils_spec.rb

@@ -5,7 +5,7 @@ require 'spec_helper'
 describe Gitlab::Utils do
   delegate :to_boolean, :boolean_to_yes_no, :slugify, :random_string, :which,
            :ensure_array_from_string, :to_exclusive_sentence, :bytes_to_megabytes,
-           :append_path, :check_path_traversal!, to: :described_class
+           :append_path, :check_path_traversal!, :ms_to_round_sec, to: :described_class
 
   describe '.check_path_traversal!' do
     it 'detects path traversal at the start of the string' do
@@ -55,6 +55,22 @@ describe Gitlab::Utils do
     end
   end
 
+  describe '.ms_to_round_sec' do
+    using RSpec::Parameterized::TableSyntax
+
+    where(:original, :expected) do
+      1999.8999 | 2
+      12384     | 12.38
+      333       | 0.33
+    end
+
+    with_them do
+      it "returns rounded seconds" do
+        expect(ms_to_round_sec(original)).to eq(expected)
+      end
+    end
+  end
+
   describe '.to_exclusive_sentence' do
     it 'calls #to_sentence on the array' do
       array = double