Commit 090ca4f7 authored by Douglas Barbosa Alexandre's avatar Douglas Barbosa Alexandre

Merge branch 'sh-add-rugged-logs' into 'master'

Add Rugged calls and duration to API and Rails logs

Closes #64676

See merge request gitlab-org/gitlab-ce!30871
parents 2044473d 1136c0c8
---
title: Add Rugged calls and duration to API and Rails logs
merge_request: 30871
author:
type: other
......@@ -34,6 +34,13 @@ unless Sidekiq.server?
payload[:gitaly_duration] = Gitlab::GitalyClient.query_time_ms
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
end
payload[:response] = event.payload[:response] if event.payload[:response]
payload[Labkit::Correlation::CorrelationId::LOG_KEY] = Labkit::Correlation::CorrelationId.current_id
......
......@@ -13,7 +13,18 @@ module Gitlab
def wrap_rugged_call(&block)
Gitlab::GitalyClient::StorageSettings.allow_disk_access do
yield
start = Gitlab::Metrics::System.monotonic_time
result = yield
duration = Gitlab::Metrics::System.monotonic_time - start
if Gitlab::RuggedInstrumentation.active?
Gitlab::RuggedInstrumentation.increment_query_count
Gitlab::RuggedInstrumentation.query_time += duration
end
result
end
end
end
......
......@@ -6,11 +6,30 @@ module Gitlab
module Loggers
class PerfLogger < ::GrapeLogging::Loggers::Base
def parameters(_, _)
gitaly_data.merge(rugged_data)
end
def gitaly_data
gitaly_calls = Gitlab::GitalyClient.get_request_count
return {} if gitaly_calls.zero?
{
gitaly_calls: Gitlab::GitalyClient.get_request_count,
gitaly_duration: Gitlab::GitalyClient.query_time_ms
}
end
def rugged_data
rugged_calls = Gitlab::RuggedInstrumentation.query_count
return {} if rugged_calls.zero?
{
rugged_calls: rugged_calls,
rugged_duration_ms: Gitlab::RuggedInstrumentation.query_time_ms
}
end
end
end
end
......
# frozen_string_literal: true
module Gitlab
module RuggedInstrumentation
def self.query_time
SafeRequestStore[:rugged_query_time] ||= 0
end
def self.query_time=(duration)
SafeRequestStore[:rugged_query_time] = duration
end
def self.query_time_ms
(self.query_time * 1000).round(2)
end
def self.query_count
SafeRequestStore[:rugged_call_count] ||= 0
end
def self.increment_query_count
SafeRequestStore[:rugged_call_count] ||= 0
SafeRequestStore[:rugged_call_count] += 1
end
def self.active?
Gitlab::SafeRequestStore.active?
end
end
end
......@@ -10,7 +10,12 @@ ALLOWED = [
# Reverted Rugged calls due to Gitaly atop NFS performance
# See https://docs.gitlab.com/ee/development/gitaly.html#legacy-rugged-code.
'lib/gitlab/git/rugged_impl/',
'lib/gitlab/gitaly_client/storage_settings.rb'
'lib/gitlab/gitaly_client/storage_settings.rb',
# Needed for logging
'config/initializers/lograge.rb',
'lib/gitlab/grape_logging/loggers/perf_logger.rb',
'lib/gitlab/rugged_instrumentation.rb'
].freeze
rugged_lines = IO.popen(%w[git grep -i -n rugged -- app config lib], &:read).lines
......
# frozen_string_literal: true
require 'spec_helper'
describe Gitlab::RuggedInstrumentation, :request_store do
subject { described_class }
describe '.query_time' do
it 'increments query times' do
subject.query_time += 0.451
subject.query_time += 0.322
expect(subject.query_time).to be_within(0.001).of(0.773)
expect(subject.query_time_ms).to eq(773.0)
end
end
context '.increment_query_count' do
it 'tracks query counts' do
expect(subject.query_count).to eq(0)
2.times { subject.increment_query_count }
expect(subject.query_count).to eq(2)
end
end
end
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