profiler.rb 6.16 KB
Newer Older
1
# coding: utf-8
2 3
# frozen_string_literal: true

4 5 6 7 8 9 10 11 12 13 14 15
module Gitlab
  module Profiler
    FILTERED_STRING = '[FILTERED]'.freeze

    IGNORE_BACKTRACES = %w[
      lib/gitlab/i18n.rb
      lib/gitlab/request_context.rb
      config/initializers
      lib/gitlab/database/load_balancing/
      lib/gitlab/etag_caching/
      lib/gitlab/metrics/
      lib/gitlab/middleware/
16
      ee/lib/gitlab/middleware/
17 18
      lib/gitlab/performance_bar/
      lib/gitlab/request_profiler/
19 20
      lib/gitlab/query_limiting/
      lib/gitlab/tracing/
21
      lib/gitlab/profiler.rb
22 23
      lib/gitlab/correlation_id.rb
      lib/gitlab/webpack/dev_server_middleware.rb
24 25 26
      lib/gitlab/sidekiq_status/
      lib/gitlab/sidekiq_logging/
      lib/gitlab/sidekiq_middleware/
27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55
    ].freeze

    # Takes a URL to profile (can be a fully-qualified URL, or an absolute path)
    # and returns the ruby-prof profile result. Formatting that result is the
    # caller's responsibility. Requests are GET requests unless post_data is
    # passed.
    #
    # Optional arguments:
    # - logger: will be used for SQL logging, including a summary at the end of
    #   the log file of the total time spent per model class.
    #
    # - post_data: a string of raw POST data to use. Changes the HTTP verb to
    #   POST.
    #
    # - user: a user to authenticate as. Only works if the user has a valid
    #   personal access token.
    #
    # - private_token: instead of providing a user instance, the token can be
    #   given as a string. Takes precedence over the user option.
    def self.profile(url, logger: nil, post_data: nil, user: nil, private_token: nil)
      app = ActionDispatch::Integration::Session.new(Rails.application)
      verb = :get
      headers = {}

      if post_data
        verb = :post
        headers['Content-Type'] = 'application/json'
      end

56 57 58
      if private_token
        headers['Private-Token'] = private_token
        user = nil # private_token overrides user
59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77
      end

      logger = create_custom_logger(logger, private_token: private_token)

      RequestStore.begin!

      # Make an initial call for an asset path in development mode to avoid
      # sprockets dominating the profiler output.
      ActionController::Base.helpers.asset_path('katex.css') if Rails.env.development?

      # Rails loads internationalization files lazily the first time a
      # translation is needed. Running this prevents this overhead from showing
      # up in profiles.
      ::I18n.t('.')[:test_string]

      # Remove API route mounting from the profile.
      app.get('/api/v4/users')

      result = with_custom_logger(logger) do
78
        with_user(user) do
79
          RubyProf.profile { app.public_send(verb, url, params: post_data, headers: headers) } # rubocop:disable GitlabSecurity/PublicSend
80
        end
81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105
      end

      RequestStore.end!

      log_load_times_by_model(logger)

      result
    end

    def self.create_custom_logger(logger, private_token: nil)
      return unless logger

      logger.dup.tap do |new_logger|
        new_logger.instance_variable_set(:@private_token, private_token)

        class << new_logger
          attr_reader :load_times_by_model, :private_token

          def debug(message, *)
            message.gsub!(private_token, FILTERED_STRING) if private_token

            _, type, time = *message.match(/(\w+) Load \(([0-9.]+)ms\)/)

            if type && time
              @load_times_by_model ||= {}
106 107
              @load_times_by_model[type] ||= []
              @load_times_by_model[type] << time.to_f
108 109 110 111
            end

            super

112
            Gitlab::Profiler.clean_backtrace(caller).each do |caller_line|
113 114 115 116 117 118 119 120 121
              stripped_caller_line = caller_line.sub("#{Rails.root}/", '')

              super("  ↳ #{stripped_caller_line}")
            end
          end
        end
      end
    end

122 123 124 125 126 127
    def self.clean_backtrace(backtrace)
      Array(Rails.backtrace_cleaner.clean(backtrace)).reject do |line|
        line.match(Regexp.union(IGNORE_BACKTRACES))
      end
    end

128 129 130 131 132 133 134 135 136 137 138
    def self.with_custom_logger(logger)
      original_colorize_logging = ActiveSupport::LogSubscriber.colorize_logging
      original_activerecord_logger = ActiveRecord::Base.logger
      original_actioncontroller_logger = ActionController::Base.logger

      if logger
        ActiveSupport::LogSubscriber.colorize_logging = false
        ActiveRecord::Base.logger = logger
        ActionController::Base.logger = logger
      end

139 140 141 142 143 144 145 146 147 148 149 150 151
      yield.tap do
        ActiveSupport::LogSubscriber.colorize_logging = original_colorize_logging
        ActiveRecord::Base.logger = original_activerecord_logger
        ActionController::Base.logger = original_actioncontroller_logger
      end
    end

    def self.with_user(user)
      if user
        API::Helpers::CommonHelpers.send(:define_method, :find_current_user!) { user } # rubocop:disable GitlabSecurity/PublicSend
        ApplicationController.send(:define_method, :current_user) { user } # rubocop:disable GitlabSecurity/PublicSend
        ApplicationController.send(:define_method, :authenticate_user!) { } # rubocop:disable GitlabSecurity/PublicSend
      end
152

153 154 155 156 157 158
      yield.tap do
        remove_method(API::Helpers::CommonHelpers, :find_current_user!)
        remove_method(ApplicationController, :current_user)
        remove_method(ApplicationController, :authenticate_user!)
      end
    end
159

160 161
    def self.remove_method(klass, meth)
      klass.send(:remove_method, meth) if klass.instance_methods(false).include?(meth) # rubocop:disable GitlabSecurity/PublicSend
162 163
    end

164
    # rubocop: disable CodeReuse/ActiveRecord
165 166 167
    def self.log_load_times_by_model(logger)
      return unless logger.respond_to?(:load_times_by_model)

168 169 170 171
      summarised_load_times = logger.load_times_by_model.to_a.map do |(model, times)|
        [model, times.count, times.sum]
      end

172
      summarised_load_times.sort_by(&:last).reverse_each do |(model, query_count, time)|
173
        logger.info("#{model} total (#{query_count}): #{time.round(2)}ms")
174 175
      end
    end
176
    # rubocop: enable CodeReuse/ActiveRecord
177 178 179 180 181 182

    def self.print_by_total_time(result, options = {})
      default_options = { sort_method: :total_time }

      Gitlab::Profiler::TotalTimeFlatPrinter.new(result).print(STDOUT, default_options.merge(options))
    end
183 184
  end
end