Asynchronously process peek stats

Adds a worker which asynchronously builds prometheus stats
from Peek profiling data.

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:

app/workers/gitlab_performance_bar_stats_worker.rb

+# 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

config/feature_flags/development/performance_bar_stats.yml

+---
+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

config/sidekiq_queues.yml

@@ -142,6 +142,8 @@
   - 1
 - - github_importer
   - 1
+- - gitlab_performance_bar_stats
+  - 1
 - - gitlab_shell
   - 2
 - - group_destroy

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

lib/gitlab/performance_bar/logger.rb

+# frozen_string_literal: true
+
+module Gitlab
+  module PerformanceBar
+    class Logger < ::Gitlab::JsonLogger
+      def self.file_name_noext
+        'performance_bar_json'
+      end
+    end
+  end
+end

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

lib/gitlab/performance_bar/stats.rb

+# 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 = /(?<filename>.*):(?<filenum>\d+):in `(?<method>.*)'/.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

spec/fixtures/lib/gitlab/performance_bar/peek_data.json

+{
+  "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 <class:Badges>'",
+            "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 <class:Badges>'",
+            "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 <class:Badges>'",
+            "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 <class:Badges>'",
+            "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
+}
+

spec/lib/gitlab/performance_bar/redis_adapter_when_peek_enabled_spec.rb

+# 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

spec/lib/gitlab/performance_bar/stats_spec.rb

+# 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

spec/workers/gitlab_performance_bar_stats_worker_spec.rb

+# 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