From 093419e50a8700e6a2ab9bd9fa357b8eaa3cffbc Mon Sep 17 00:00:00 2001 From: Jan Provaznik Date: Mon, 9 Nov 2020 09:06:29 +0100 Subject: [PATCH 1/2] Asynchronously process peek stats Adds a worker which asynchronously builds prometheus stats from Peek profiling data. --- app/workers/all_queues.yml | 8 ++ .../gitlab_performance_bar_stats_worker.rb | 36 ++++++ .../development/performance_bar_stats.yml | 8 ++ config/sidekiq_queues.yml | 2 + .../redis_adapter_when_peek_enabled.rb | 28 ++++- lib/gitlab/performance_bar/stats.rb | 61 ++++++++++ .../lib/gitlab/performance_bar/peek_data.json | 104 ++++++++++++++++++ .../redis_adapter_when_peek_enabled_spec.rb | 64 +++++++++++ spec/lib/gitlab/performance_bar/stats_spec.rb | 45 ++++++++ ...itlab_performance_bar_stats_worker_spec.rb | 31 ++++++ 10 files changed, 386 insertions(+), 1 deletion(-) create mode 100644 app/workers/gitlab_performance_bar_stats_worker.rb create mode 100644 config/feature_flags/development/performance_bar_stats.yml create mode 100644 lib/gitlab/performance_bar/stats.rb create mode 100644 spec/fixtures/lib/gitlab/performance_bar/peek_data.json create mode 100644 spec/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled_spec.rb create mode 100644 spec/lib/gitlab/performance_bar/stats_spec.rb create mode 100644 spec/workers/gitlab_performance_bar_stats_worker_spec.rb diff --git a/app/workers/all_queues.yml b/app/workers/all_queues.yml index 416c10e46fe6..de0016f64d66 100644 --- a/app/workers/all_queues.yml +++ b/app/workers/all_queues.yml @@ -1610,6 +1610,14 @@ :weight: 1 :idempotent: :tags: [] +- :name: gitlab_performance_bar_stats + :feature_category: :metrics + :has_external_dependencies: + :urgency: :low + :resource_boundary: :unknown + :weight: 1 + :idempotent: true + :tags: [] - :name: gitlab_shell :feature_category: :source_code_management :has_external_dependencies: diff --git a/app/workers/gitlab_performance_bar_stats_worker.rb b/app/workers/gitlab_performance_bar_stats_worker.rb new file mode 100644 index 000000000000..df62c816fb9e --- /dev/null +++ b/app/workers/gitlab_performance_bar_stats_worker.rb @@ -0,0 +1,36 @@ +# frozen_string_literal: true + +class GitlabPerformanceBarStatsWorker + include ApplicationWorker + + LEASE_KEY = 'gitlab:performance_bar_stats' + LEASE_TIMEOUT = 600 + WORKER_DELAY = 120 + STATS_KEY = 'performance_bar_stats:pending_request_ids' + + feature_category :metrics + idempotent! + + def perform(lease_uuid) + Gitlab::Redis::SharedState.with do |redis| + request_ids = fetch_request_ids(redis, lease_uuid) + stats = Gitlab::PerformanceBar::Stats.new + + request_ids.each do |id| + # Peek gem stores request data under peek:requests:request_id key + request = redis.get("peek:requests:#{id}") + stats.process(request) + end + end + end + + private + + def fetch_request_ids(redis, lease_uuid) + ids = redis.smembers(STATS_KEY) + redis.del(STATS_KEY) + Gitlab::ExclusiveLease.cancel(LEASE_KEY, lease_uuid) + + ids + end +end diff --git a/config/feature_flags/development/performance_bar_stats.yml b/config/feature_flags/development/performance_bar_stats.yml new file mode 100644 index 000000000000..79315050c585 --- /dev/null +++ b/config/feature_flags/development/performance_bar_stats.yml @@ -0,0 +1,8 @@ +--- +name: performance_bar_stats +introduced_by_url: https://gitlab.com/gitlab-org/gitlab/-/merge_requests/48149 +rollout_issue_url: https://gitlab.com/gitlab-org/gitlab/-/issues/285480 +milestone: '13.7' +type: development +group: group::product_planning +default_enabled: false diff --git a/config/sidekiq_queues.yml b/config/sidekiq_queues.yml index 74a209700799..f964ac8957f7 100644 --- a/config/sidekiq_queues.yml +++ b/config/sidekiq_queues.yml @@ -142,6 +142,8 @@ - 1 - - github_importer - 1 +- - gitlab_performance_bar_stats + - 1 - - gitlab_shell - 2 - - group_destroy diff --git a/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb b/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb index 805283b0f93b..ac9d0267d08a 100644 --- a/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb +++ b/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb @@ -5,7 +5,33 @@ module Gitlab module PerformanceBar module RedisAdapterWhenPeekEnabled def save(request_id) - super if ::Gitlab::PerformanceBar.enabled_for_request? + return unless ::Gitlab::PerformanceBar.enabled_for_request? + return if request_id.blank? + + super + + enqueue_stats_job(request_id) + end + + # schedules a job which parses peek profile data and updates + # related prometheus metrics + def enqueue_stats_job(request_id) + return unless gather_stats? + + @client.sadd(GitlabPerformanceBarStatsWorker::STATS_KEY, request_id) # rubocop:disable Gitlab/ModuleWithInstanceVariables + + return unless uuid = Gitlab::ExclusiveLease.new( + GitlabPerformanceBarStatsWorker::LEASE_KEY, + timeout: GitlabPerformanceBarStatsWorker::LEASE_TIMEOUT + ).try_obtain + + GitlabPerformanceBarStatsWorker.perform_in(GitlabPerformanceBarStatsWorker::WORKER_DELAY, uuid) + end + + def gather_stats? + return unless Feature.enabled?(:performance_bar_stats) + + Gitlab.com? || !Rails.env.production? end end end diff --git a/lib/gitlab/performance_bar/stats.rb b/lib/gitlab/performance_bar/stats.rb new file mode 100644 index 000000000000..aac6e7854d6a --- /dev/null +++ b/lib/gitlab/performance_bar/stats.rb @@ -0,0 +1,61 @@ +# frozen_string_literal: true + +module Gitlab + module PerformanceBar + class Stats + def process(request) + return unless request + + data = Gitlab::Json.parse(request) + queries = sql_queries(data) + + queries.each do |query| + duration = query.delete(:duration) + duration_histogram.observe(query, duration) + end + + group_by = [:filename, :method] + grouped_queries = queries.group_by { |q| q.slice(*group_by) } + grouped_queries.each do |key, same_queries| + frequency_histogram.observe(key, same_queries.size) + end + end + + private + + def sql_queries(data) + return [] unless queries = data.dig('data', 'active-record', 'details') + + queries.each_with_object([]) do |query, locations| + next unless location = parse_backtrace(query['backtrace']) + + location[:duration] = query['duration'].to_f + locations << location + end + end + + def parse_backtrace(backtrace) + return unless match = /(?.*):(?\d+):in `(?.*)'/.match(backtrace.first) + + { + filename: match[:filename], + method: match[:method] + } + end + + def duration_histogram + @duration_histogram ||= Gitlab::Metrics.histogram( + :performance_bar_stats_sql_query_duration, + 'SQL query duration gathered by performance bar' + ) + end + + def frequency_histogram + @frequency_histogram ||= Gitlab::Metrics.histogram( + :performance_bar_stats_sql_query_frequency, + 'How many times an SQL query is called per one request' + ) + end + end + end +end diff --git a/spec/fixtures/lib/gitlab/performance_bar/peek_data.json b/spec/fixtures/lib/gitlab/performance_bar/peek_data.json new file mode 100644 index 000000000000..8e207b69ecb5 --- /dev/null +++ b/spec/fixtures/lib/gitlab/performance_bar/peek_data.json @@ -0,0 +1,104 @@ +{ + "context": {}, + "data": { + "host": { + "hostname": "pc", + "canary": null + }, + "active-record": { + "duration": "6ms", + "calls": "7 (0 cached)", + "details": [ + { + "duration": 1.096, + "sql": "SELECT COUNT(*) FROM ((SELECT \"badges\".* FROM \"badges\" WHERE \"badges\".\"type\" = 'ProjectBadge' AND \"badges\".\"project_id\" = 8)\nUNION\n(SELECT \"badges\".* FROM \"badges\" WHERE \"badges\".\"type\" = 'GroupBadge' AND \"badges\".\"group_id\" IN (SELECT \"namespaces\".\"id\" FROM \"namespaces\" WHERE \"namespaces\".\"type\" = 'Group' AND \"namespaces\".\"id\" = 28))) badges", + "backtrace": [ + "lib/gitlab/pagination/offset_pagination.rb:53:in `add_pagination_headers'", + "lib/gitlab/pagination/offset_pagination.rb:15:in `block in paginate'", + "lib/gitlab/pagination/offset_pagination.rb:14:in `tap'", + "lib/gitlab/pagination/offset_pagination.rb:14:in `paginate'", + "lib/api/helpers/pagination.rb:7:in `paginate'", + "lib/api/badges.rb:42:in `block (3 levels) in '", + "ee/lib/gitlab/ip_address_state.rb:10:in `with'", + "lib/api/api_guard.rb:208:in `call'", + "lib/gitlab/jira/middleware.rb:19:in `call'" + ], + "cached": "", + "warnings": [] + }, + { + "duration": 0.817, + "sql": "SELECT \"projects\".* FROM \"projects\" WHERE \"projects\".\"pending_delete\" = $1 AND \"projects\".\"id\" = $2 LIMIT $3", + "backtrace": [ + "lib/api/helpers.rb:112:in `find_project'", + "ee/lib/ee/api/helpers.rb:88:in `find_project!'", + "lib/api/helpers/members_helpers.rb:14:in `public_send'", + "lib/api/helpers/members_helpers.rb:14:in `find_source'", + "lib/api/badges.rb:36:in `block (3 levels) in '", + "ee/lib/gitlab/ip_address_state.rb:10:in `with'", + "lib/api/api_guard.rb:208:in `call'", + "lib/gitlab/jira/middleware.rb:19:in `call'" + ], + "cached": "", + "warnings": [] + }, + { + "duration": 0.817, + "sql": "SELECT \"projects\".* FROM \"projects\" WHERE \"projects\".\"pending_delete\" = $1 AND \"projects\".\"id\" = $2 LIMIT $3", + "backtrace": [ + "lib/api/helpers.rb:112:in `find_project'", + "ee/lib/ee/api/helpers.rb:88:in `find_project!'", + "lib/api/helpers/members_helpers.rb:14:in `public_send'", + "lib/api/helpers/members_helpers.rb:14:in `find_source'", + "lib/api/badges.rb:36:in `block (3 levels) in '", + "ee/lib/gitlab/ip_address_state.rb:10:in `with'", + "lib/api/api_guard.rb:208:in `call'", + "lib/gitlab/jira/middleware.rb:19:in `call'" + ], + "cached": "", + "warnings": [] + } + ], + "warnings": [] + }, + "gitaly": { + "duration": "0ms", + "calls": 0, + "details": [], + "warnings": [] + }, + "redis": { + "duration": "0ms", + "calls": 1, + "details": [ + { + "cmd": "get cache:gitlab:flipper/v1/feature/api_kaminari_count_with_limit", + "duration": 0.155, + "backtrace": [ + "lib/gitlab/instrumentation/redis_interceptor.rb:30:in `call'", + "lib/feature.rb:81:in `enabled?'", + "lib/gitlab/pagination/offset_pagination.rb:30:in `paginate_with_limit_optimization'", + "lib/gitlab/pagination/offset_pagination.rb:14:in `paginate'", + "lib/api/helpers/pagination.rb:7:in `paginate'", + "lib/api/badges.rb:42:in `block (3 levels) in '", + "ee/lib/gitlab/ip_address_state.rb:10:in `with'", + "lib/api/api_guard.rb:208:in `call'", + "lib/gitlab/jira/middleware.rb:19:in `call'" + ], + "storage": "Cache", + "warnings": [], + "instance": "Cache" + } + ], + "warnings": [] + }, + "es": { + "duration": "0ms", + "calls": 0, + "details": [], + "warnings": [] + } + }, + "has_warnings": false +} + diff --git a/spec/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled_spec.rb b/spec/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled_spec.rb new file mode 100644 index 000000000000..bbc8b0d67e0d --- /dev/null +++ b/spec/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled_spec.rb @@ -0,0 +1,64 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Gitlab::PerformanceBar::RedisAdapterWhenPeekEnabled do + include ExclusiveLeaseHelpers + + let(:peek_adapter) do + Class.new do + prepend Gitlab::PerformanceBar::RedisAdapterWhenPeekEnabled + + def initialize(client) + @client = client + end + + def save(id) + # no-op + end + end + end + + describe '#save' do + let(:client) { double } + let(:uuid) { 'foo' } + + before do + allow(Gitlab::PerformanceBar).to receive(:enabled_for_request?).and_return(true) + end + + it 'stores request id and enqueues stats job' do + expect_to_obtain_exclusive_lease(GitlabPerformanceBarStatsWorker::LEASE_KEY, uuid) + expect(GitlabPerformanceBarStatsWorker).to receive(:perform_in).with(GitlabPerformanceBarStatsWorker::WORKER_DELAY, uuid) + expect(client).to receive(:sadd).with(GitlabPerformanceBarStatsWorker::STATS_KEY, uuid) + + peek_adapter.new(client).save('foo') + end + + context 'when performance_bar_stats is disabled' do + before do + stub_feature_flags(performance_bar_stats: false) + end + + it 'ignores stats processing for the request' do + expect(GitlabPerformanceBarStatsWorker).not_to receive(:perform_in) + expect(client).not_to receive(:sadd) + + peek_adapter.new(client).save('foo') + end + end + + context 'when exclusive lease has been already taken' do + before do + stub_exclusive_lease_taken(GitlabPerformanceBarStatsWorker::LEASE_KEY) + end + + it 'stores request id but does not enqueue any job' do + expect(GitlabPerformanceBarStatsWorker).not_to receive(:perform_in) + expect(client).to receive(:sadd).with(GitlabPerformanceBarStatsWorker::STATS_KEY, uuid) + + peek_adapter.new(client).save('foo') + end + end + end +end diff --git a/spec/lib/gitlab/performance_bar/stats_spec.rb b/spec/lib/gitlab/performance_bar/stats_spec.rb new file mode 100644 index 000000000000..411467967db8 --- /dev/null +++ b/spec/lib/gitlab/performance_bar/stats_spec.rb @@ -0,0 +1,45 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe Gitlab::PerformanceBar::Stats do + describe '#process' do + let(:request) { fixture_file('lib/gitlab/performance_bar/peek_data.json') } + let(:duration_histogram) { double(:histogram) } + let(:frequency_histogram) { double(:histogram) } + + subject(:process) { described_class.new.process(request) } + + before do + allow(Gitlab::Metrics).to receive(:histogram).with(:performance_bar_stats_sql_query_duration, anything) { duration_histogram } + allow(Gitlab::Metrics).to receive(:histogram).with(:performance_bar_stats_sql_query_frequency, anything) { frequency_histogram } + end + + it 'measures each SQL query duration and frequency' do + expected_calls = [ + { + labels: { + filename: 'lib/gitlab/pagination/offset_pagination.rb', + method: 'add_pagination_headers' + }, + duration: 1.096, + frequency: 1 + }, { + labels: { + filename: 'lib/api/helpers.rb', + method: 'find_project' + }, + duration: 0.817, + frequency: 2 + } + ] + + expected_calls.each do |call| + expect(duration_histogram).to receive(:observe).with(call[:labels], call[:duration]).exactly(call[:frequency]).times + expect(frequency_histogram).to receive(:observe).with(call[:labels], call[:frequency]) + end + + subject + end + end +end diff --git a/spec/workers/gitlab_performance_bar_stats_worker_spec.rb b/spec/workers/gitlab_performance_bar_stats_worker_spec.rb new file mode 100644 index 000000000000..4f7665dca715 --- /dev/null +++ b/spec/workers/gitlab_performance_bar_stats_worker_spec.rb @@ -0,0 +1,31 @@ +# frozen_string_literal: true + +require 'spec_helper' + +RSpec.describe GitlabPerformanceBarStatsWorker do + include ExclusiveLeaseHelpers + + subject(:worker) { described_class.new } + + describe '#perform' do + let(:redis) { double(Gitlab::Redis::SharedState) } + let(:uuid) { 1 } + + before do + expect(Gitlab::Redis::SharedState).to receive(:with).and_yield(redis) + expect_to_cancel_exclusive_lease(GitlabPerformanceBarStatsWorker::LEASE_KEY, uuid) + end + + it 'fetches list of request ids and processes them' do + expect(redis).to receive(:smembers).with(GitlabPerformanceBarStatsWorker::STATS_KEY).and_return([1, 2]) + expect(redis).to receive(:del).with(GitlabPerformanceBarStatsWorker::STATS_KEY) + expect(redis).to receive(:get).with('peek:requests:1') + expect(redis).to receive(:get).with('peek:requests:2') + expect_next_instance_of(Gitlab::PerformanceBar::Stats) do |stats| + expect(stats).to receive(:process).twice + end + + worker.perform(uuid) + end + end +end -- GitLab From 9ee0ac10cda07274f947bb5110622c5b069b01ca Mon Sep 17 00:00:00 2001 From: Jan Provaznik Date: Fri, 4 Dec 2020 11:16:05 +0100 Subject: [PATCH 2/2] Log stats instead of prometheus metrics Because generating metrics would add to big cardinality (if we involve file and method for each added metric), we rather use structured logfile and then we will analyze these in Kibana. --- .../gitlab_performance_bar_stats_worker.rb | 6 +- doc/administration/logs.md | 16 +++++ lib/gitlab/performance_bar/logger.rb | 11 ++++ .../redis_adapter_when_peek_enabled.rb | 4 +- lib/gitlab/performance_bar/stats.rb | 59 +++++++++---------- spec/lib/gitlab/performance_bar/stats_spec.rb | 57 +++++++++--------- ...itlab_performance_bar_stats_worker_spec.rb | 5 +- 7 files changed, 89 insertions(+), 69 deletions(-) create mode 100644 lib/gitlab/performance_bar/logger.rb diff --git a/app/workers/gitlab_performance_bar_stats_worker.rb b/app/workers/gitlab_performance_bar_stats_worker.rb index df62c816fb9e..d63f81118642 100644 --- a/app/workers/gitlab_performance_bar_stats_worker.rb +++ b/app/workers/gitlab_performance_bar_stats_worker.rb @@ -14,12 +14,10 @@ class GitlabPerformanceBarStatsWorker def perform(lease_uuid) Gitlab::Redis::SharedState.with do |redis| request_ids = fetch_request_ids(redis, lease_uuid) - stats = Gitlab::PerformanceBar::Stats.new + stats = Gitlab::PerformanceBar::Stats.new(redis) request_ids.each do |id| - # Peek gem stores request data under peek:requests:request_id key - request = redis.get("peek:requests:#{id}") - stats.process(request) + stats.process(id) end end end diff --git a/doc/administration/logs.md b/doc/administration/logs.md index 167e5a6d2d8e..d4876adb0d0d 100644 --- a/doc/administration/logs.md +++ b/doc/administration/logs.md @@ -998,6 +998,22 @@ For Omnibus GitLab installations, GitLab Exporter logs reside in `/var/log/gitla For Omnibus GitLab installations, GitLab Kubernetes Agent Server logs reside in `/var/log/gitlab/gitlab-kas/`. +## Performance bar stats + +> [Introduced](https://gitlab.com/gitlab-org/gitlab/-/merge_requests/48149) in GitLab 13.7. + +This file lives in `/var/log/gitlab/gitlab-rails/performance_bar_json.log` for +Omnibus GitLab packages or in `/home/git/gitlab/log/performance_bar_json.log` for +installations from source. + +Performance bar statistics (currently only duration of SQL queries) are recorded in that file. For example: + +```json +{"severity":"INFO","time":"2020-12-04T09:29:44.592Z","correlation_id":"33680b1490ccd35981b03639c406a697","filename":"app/models/ci/pipeline.rb","filenum":"395","method":"each_with_object","request_id":"rYHomD0VJS4","duration_ms":26.889,"type": "sql"} +``` + +These statistics are logged on .com only, disabled on self-deployments. + ## Gathering logs When [troubleshooting](troubleshooting/index.md) issues that aren't localized to one of the diff --git a/lib/gitlab/performance_bar/logger.rb b/lib/gitlab/performance_bar/logger.rb new file mode 100644 index 000000000000..a8e2f7d2d4ee --- /dev/null +++ b/lib/gitlab/performance_bar/logger.rb @@ -0,0 +1,11 @@ +# frozen_string_literal: true + +module Gitlab + module PerformanceBar + class Logger < ::Gitlab::JsonLogger + def self.file_name_noext + 'performance_bar_json' + end + end + end +end diff --git a/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb b/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb index ac9d0267d08a..bf8d4b202b60 100644 --- a/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb +++ b/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled.rb @@ -13,8 +13,8 @@ def save(request_id) enqueue_stats_job(request_id) end - # schedules a job which parses peek profile data and updates - # related prometheus metrics + # schedules a job which parses peek profile data and adds them + # to a structured log def enqueue_stats_job(request_id) return unless gather_stats? diff --git a/lib/gitlab/performance_bar/stats.rb b/lib/gitlab/performance_bar/stats.rb index aac6e7854d6a..d1504d883155 100644 --- a/lib/gitlab/performance_bar/stats.rb +++ b/lib/gitlab/performance_bar/stats.rb @@ -2,35 +2,43 @@ module Gitlab module PerformanceBar + # This class fetches Peek stats stored in redis and logs them in a + # structured log (so these can be then analyzed in Kibana) class Stats - def process(request) - return unless request - - data = Gitlab::Json.parse(request) - queries = sql_queries(data) + def initialize(redis) + @redis = redis + end - queries.each do |query| - duration = query.delete(:duration) - duration_histogram.observe(query, duration) - end + def process(id) + data = request(id) + return unless data - group_by = [:filename, :method] - grouped_queries = queries.group_by { |q| q.slice(*group_by) } - grouped_queries.each do |key, same_queries| - frequency_histogram.observe(key, same_queries.size) - end + log_sql_queries(id, data) + rescue => err + logger.error(message: "failed to process request id #{id}: #{err.message}") end private - def sql_queries(data) + def request(id) + # Peek gem stores request data under peek:requests:request_id key + json_data = @redis.get("peek:requests:#{id}") + Gitlab::Json.parse(json_data) + end + + def log_sql_queries(id, data) return [] unless queries = data.dig('data', 'active-record', 'details') - queries.each_with_object([]) do |query, locations| + queries.each do |query| next unless location = parse_backtrace(query['backtrace']) - location[:duration] = query['duration'].to_f - locations << location + log_info = location.merge( + type: :sql, + request_id: id, + duration_ms: query['duration'].to_f + ) + + logger.info(log_info) end end @@ -39,22 +47,13 @@ def parse_backtrace(backtrace) { filename: match[:filename], + filenum: match[:filenum].to_i, method: match[:method] } end - def duration_histogram - @duration_histogram ||= Gitlab::Metrics.histogram( - :performance_bar_stats_sql_query_duration, - 'SQL query duration gathered by performance bar' - ) - end - - def frequency_histogram - @frequency_histogram ||= Gitlab::Metrics.histogram( - :performance_bar_stats_sql_query_frequency, - 'How many times an SQL query is called per one request' - ) + def logger + @logger ||= Gitlab::PerformanceBar::Logger.build end end end diff --git a/spec/lib/gitlab/performance_bar/stats_spec.rb b/spec/lib/gitlab/performance_bar/stats_spec.rb index 411467967db8..c34c6f7b31f2 100644 --- a/spec/lib/gitlab/performance_bar/stats_spec.rb +++ b/spec/lib/gitlab/performance_bar/stats_spec.rb @@ -5,41 +5,38 @@ RSpec.describe Gitlab::PerformanceBar::Stats do describe '#process' do let(:request) { fixture_file('lib/gitlab/performance_bar/peek_data.json') } - let(:duration_histogram) { double(:histogram) } - let(:frequency_histogram) { double(:histogram) } + let(:redis) { double(Gitlab::Redis::SharedState) } + let(:logger) { double(Gitlab::PerformanceBar::Logger) } + let(:request_id) { 'foo' } + let(:stats) { described_class.new(redis) } - subject(:process) { described_class.new.process(request) } + describe '#process' do + subject(:process) { stats.process(request_id) } - before do - allow(Gitlab::Metrics).to receive(:histogram).with(:performance_bar_stats_sql_query_duration, anything) { duration_histogram } - allow(Gitlab::Metrics).to receive(:histogram).with(:performance_bar_stats_sql_query_frequency, anything) { frequency_histogram } - end + before do + allow(stats).to receive(:logger).and_return(logger) + end + + it 'logs each SQL query including its duration' do + allow(redis).to receive(:get).and_return(request) + + expect(logger).to receive(:info) + .with({ duration_ms: 1.096, filename: 'lib/gitlab/pagination/offset_pagination.rb', + filenum: 53, method: 'add_pagination_headers', request_id: 'foo', type: :sql }) + expect(logger).to receive(:info) + .with({ duration_ms: 0.817, filename: 'lib/api/helpers.rb', + filenum: 112, method: 'find_project', request_id: 'foo', type: :sql }).twice - it 'measures each SQL query duration and frequency' do - expected_calls = [ - { - labels: { - filename: 'lib/gitlab/pagination/offset_pagination.rb', - method: 'add_pagination_headers' - }, - duration: 1.096, - frequency: 1 - }, { - labels: { - filename: 'lib/api/helpers.rb', - method: 'find_project' - }, - duration: 0.817, - frequency: 2 - } - ] - - expected_calls.each do |call| - expect(duration_histogram).to receive(:observe).with(call[:labels], call[:duration]).exactly(call[:frequency]).times - expect(frequency_histogram).to receive(:observe).with(call[:labels], call[:frequency]) + subject end - subject + it 'logs an error when the request could not be processed' do + allow(redis).to receive(:get).and_return(nil) + + expect(logger).to receive(:error).with(message: anything) + + subject + end end end end diff --git a/spec/workers/gitlab_performance_bar_stats_worker_spec.rb b/spec/workers/gitlab_performance_bar_stats_worker_spec.rb index 4f7665dca715..367003dd1ad7 100644 --- a/spec/workers/gitlab_performance_bar_stats_worker_spec.rb +++ b/spec/workers/gitlab_performance_bar_stats_worker_spec.rb @@ -19,10 +19,9 @@ it 'fetches list of request ids and processes them' do expect(redis).to receive(:smembers).with(GitlabPerformanceBarStatsWorker::STATS_KEY).and_return([1, 2]) expect(redis).to receive(:del).with(GitlabPerformanceBarStatsWorker::STATS_KEY) - expect(redis).to receive(:get).with('peek:requests:1') - expect(redis).to receive(:get).with('peek:requests:2') expect_next_instance_of(Gitlab::PerformanceBar::Stats) do |stats| - expect(stats).to receive(:process).twice + expect(stats).to receive(:process).with(1) + expect(stats).to receive(:process).with(2) end worker.perform(uuid) -- GitLab