Merge branch 'osw-use-microseconds-precision-for-logs' into 'master'

Use microseconds precision for timings log

See merge request gitlab-org/gitlab!30417

doc/development/logging.md

@@ -167,7 +167,8 @@ Resources:
 #### 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.
+challenged to choose between seconds, milliseconds or any other unit, lean towards _seconds_ as float
+(with microseconds precision, i.e. `Gitlab::InstrumentationHelper::DURATION_PRECISION`).
 
 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`).

lib/gitlab/gitaly_client.rb

@@ -209,7 +209,8 @@ module Gitlab
     end
 
     def self.query_time
-      SafeRequestStore[:gitaly_query_time] ||= 0
+      query_time = SafeRequestStore[:gitaly_query_time] ||= 0
+      query_time.round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
     end
 
     def self.query_time=(duration)

lib/gitlab/instrumentation/redis.rb

@@ -38,7 +38,8 @@ module Gitlab
       end
 
       def self.query_time
-        ::RequestStore[REDIS_CALL_DURATION] || 0
+        query_time = ::RequestStore[REDIS_CALL_DURATION] || 0
+        query_time.round(::Gitlab::InstrumentationHelper::DURATION_PRECISION)
       end
 
       def self.add_duration(duration)

lib/gitlab/instrumentation_helper.rb

@@ -5,27 +5,28 @@ module Gitlab
     extend self
 
     KEYS = %i(gitaly_calls gitaly_duration_s rugged_calls rugged_duration_s redis_calls redis_duration_s).freeze
+    DURATION_PRECISION = 6 # microseconds
 
     def add_instrumentation_data(payload)
       gitaly_calls = Gitlab::GitalyClient.get_request_count
 
       if gitaly_calls > 0
         payload[:gitaly_calls] = gitaly_calls
-        payload[:gitaly_duration_s] = Gitlab::GitalyClient.query_time.round(2)
+        payload[:gitaly_duration_s] = Gitlab::GitalyClient.query_time
       end
 
       rugged_calls = Gitlab::RuggedInstrumentation.query_count
 
       if rugged_calls > 0
         payload[:rugged_calls] = rugged_calls
-        payload[:rugged_duration_s] = Gitlab::RuggedInstrumentation.query_time.round(2)
+        payload[:rugged_duration_s] = Gitlab::RuggedInstrumentation.query_time
       end
 
       redis_calls = Gitlab::Instrumentation::Redis.get_request_count
 
       if redis_calls > 0
         payload[:redis_calls] = redis_calls
-        payload[:redis_duration_s] = Gitlab::Instrumentation::Redis.query_time.round(2)
+        payload[:redis_duration_s] = Gitlab::Instrumentation::Redis.query_time
       end
     end
 
@@ -47,7 +48,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.round(2)
+      [elapsed_by_absolute_time(enqueued_at_time), 0].max.round(DURATION_PRECISION)
     end
 
     # Calculates the time in seconds, as a float, from

lib/gitlab/rugged_instrumentation.rb

@@ -3,7 +3,8 @@
 module Gitlab
   module RuggedInstrumentation
     def self.query_time
-      SafeRequestStore[:rugged_query_time] ||= 0
+      query_time = SafeRequestStore[:rugged_query_time] ||= 0
+      query_time.round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
     end
 
     def self.query_time=(duration)

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -66,11 +66,11 @@ module Gitlab
       end
 
       def add_time_keys!(time, payload)
-        payload['duration_s'] = time[:duration].round(2)
+        payload['duration_s'] = time[:duration].round(Gitlab::InstrumentationHelper::DURATION_PRECISION)
 
         # 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(2) if time[:cputime] > 0
+        payload['cpu_s'] = time[:cputime].round(Gitlab::InstrumentationHelper::DURATION_PRECISION) if time[:cputime] > 0
         payload['completed_at'] = Time.now.utc.to_f
       end
 

lib/gitlab/utils.rb

@@ -123,7 +123,7 @@ module Gitlab
     end
 
     def ms_to_round_sec(ms)
-      (ms.to_f / 1000).round(2)
+      (ms.to_f / 1000).round(6)
     end
 
     # Used in EE

spec/lib/gitlab/instrumentation_helper_spec.rb

@@ -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.0
+      "2019-06-01T02:00:00.000+0000" | nil                            | "2019-06-01T02:00:00.001+0000" | 0.001
       "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.0
+      nil                            | "2019-06-01T02:00:00.000+0000" | "2019-06-01T02:00:00.001+0000" | 0.001
       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.00
+      1571825569.998168              | nil                            | "2019-10-23T12:13:16.000+0200" | 26.001832
       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

@@ -44,7 +44,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'job_status' => 'done',
         'duration_s' => 0.0,
         'completed_at' => timestamp.to_f,
-        'cpu_s' => 1.11,
+        'cpu_s' => 1.111112,
         'db_duration_s' => 0.0
       )
     end
@@ -224,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_s' => 0.12, 'cpu_s' => 1.23, '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.123123, 'cpu_s' => 1.234235, 'completed_at' => current_utc_time.to_f } }
 
     subject { described_class.new }
 

spec/lib/gitlab/utils_spec.rb

@@ -59,9 +59,10 @@ describe Gitlab::Utils do
     using RSpec::Parameterized::TableSyntax
 
     where(:original, :expected) do
-      1999.8999 | 2
-      12384     | 12.38
-      333       | 0.33
+      1999.8999     | 1.9999
+      12384         | 12.384
+      333           | 0.333
+      1333.33333333 | 1.333333
     end
 
     with_them do