Commit 5c2a5394 authored by Oswaldo Ferreira's avatar Oswaldo Ferreira

Use microseconds precision for log timings

We have 6 (microsecond) precision for a few Go service
timings, so making all existing *_duration_s on
Rails/API/Sidekiq use a 6 decimal precision instead of 2
would make more sense, and that's what we accomplish here.
parent bf0e5999
......@@ -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`).
......
......@@ -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)
......
......@@ -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)
......
......@@ -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
......
......@@ -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)
......
......@@ -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
......
......@@ -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
......
......@@ -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
......
......@@ -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 }
......
......@@ -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
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment