diff --git a/app/workers/all_queues.yml b/app/workers/all_queues.yml index 416c10e46fe607e5022332a248488c999843d1d2..de0016f64d6649fbca5e5ed941cd33273dae02b9 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 0000000000000000000000000000000000000000..d63f81118642486e21c613c85f22319b394e1db9 --- /dev/null +++ b/app/workers/gitlab_performance_bar_stats_worker.rb @@ -0,0 +1,34 @@ +# 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(redis) + + request_ids.each do |id| + stats.process(id) + 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 0000000000000000000000000000000000000000..79315050c58569b9b29b85b623bf0c0bd3db520e --- /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 74a20970079910d802becf704b497d446e070733..f964ac8957f70d98dde2ec9bc6a7929f9c9157a9 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/doc/administration/logs.md b/doc/administration/logs.md index 167e5a6d2d8e803b95456978a72dc64f79f4c9e9..d4876adb0d0d7df1333e9920bbc2683c26d85bc7 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 0000000000000000000000000000000000000000..a8e2f7d2d4ee0cc7f175887439d514b82556b673 --- /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 805283b0f93b5d4c779f152725fa423edc71fa7c..bf8d4b202b607db98b7f319ffa99a2d291dd0efd 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 adds them + # to a structured log + 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 0000000000000000000000000000000000000000..d1504d8831553fd65f59319499b5570bdb4bbfa5 --- /dev/null +++ b/lib/gitlab/performance_bar/stats.rb @@ -0,0 +1,60 @@ +# frozen_string_literal: true + +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 initialize(redis) + @redis = redis + end + + def process(id) + data = request(id) + return unless data + + log_sql_queries(id, data) + rescue => err + logger.error(message: "failed to process request id #{id}: #{err.message}") + end + + private + + 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 do |query| + next unless location = parse_backtrace(query['backtrace']) + + log_info = location.merge( + type: :sql, + request_id: id, + duration_ms: query['duration'].to_f + ) + + logger.info(log_info) + end + end + + def parse_backtrace(backtrace) + return unless match = /(?.*):(?\d+):in `(?.*)'/.match(backtrace.first) + + { + filename: match[:filename], + filenum: match[:filenum].to_i, + method: match[:method] + } + end + + def logger + @logger ||= Gitlab::PerformanceBar::Logger.build + 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 0000000000000000000000000000000000000000..8e207b69ecb528821363895c77cb5286f72410ba --- /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 0000000000000000000000000000000000000000..bbc8b0d67e0de84b5a289cde6329dbca0e075f21 --- /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 0000000000000000000000000000000000000000..c34c6f7b31f24b3d87f8a4b9d02211658dc467c9 --- /dev/null +++ b/spec/lib/gitlab/performance_bar/stats_spec.rb @@ -0,0 +1,42 @@ +# 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(:redis) { double(Gitlab::Redis::SharedState) } + let(:logger) { double(Gitlab::PerformanceBar::Logger) } + let(:request_id) { 'foo' } + let(:stats) { described_class.new(redis) } + + describe '#process' do + subject(:process) { stats.process(request_id) } + + 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 + + subject + end + + 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 new file mode 100644 index 0000000000000000000000000000000000000000..367003dd1ad7458fb42e9684e4b69cf2cd68bc8e --- /dev/null +++ b/spec/workers/gitlab_performance_bar_stats_worker_spec.rb @@ -0,0 +1,30 @@ +# 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_next_instance_of(Gitlab::PerformanceBar::Stats) do |stats| + expect(stats).to receive(:process).with(1) + expect(stats).to receive(:process).with(2) + end + + worker.perform(uuid) + end + end +end