debian-mirror-gitlab/lib/gitlab/profiler.rb

177 lines
6 KiB
Ruby
Raw Normal View History

2018-12-13 13:39:08 +05:30
# frozen_string_literal: true
2018-03-17 18:26:18 +05:30
module Gitlab
module Profiler
2020-04-08 14:13:33 +05:30
extend WithRequestStore
2019-12-04 20:38:33 +05:30
FILTERED_STRING = '[FILTERED]'
2018-03-17 18:26:18 +05:30
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/
2018-11-08 19:23:39 +05:30
ee/lib/gitlab/middleware/
2018-03-17 18:26:18 +05:30
lib/gitlab/performance_bar/
lib/gitlab/request_profiler/
2019-07-31 22:56:46 +05:30
lib/gitlab/query_limiting/
lib/gitlab/tracing/
2018-03-17 18:26:18 +05:30
lib/gitlab/profiler.rb
2019-07-31 22:56:46 +05:30
lib/gitlab/correlation_id.rb
lib/gitlab/webpack/dev_server_middleware.rb
2019-10-12 21:52:04 +05:30
lib/gitlab/sidekiq_status/
lib/gitlab/sidekiq_logging/
lib/gitlab/sidekiq_middleware/
2018-03-17 18:26:18 +05:30
].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.
#
2019-12-21 20:55:43 +05:30
# - user: a user to authenticate as.
2018-03-17 18:26:18 +05:30
#
# - 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
2019-02-15 15:39:39 +05:30
if private_token
headers['Private-Token'] = private_token
user = nil # private_token overrides user
2018-03-17 18:26:18 +05:30
end
logger = create_custom_logger(logger, private_token: private_token)
2020-04-08 14:13:33 +05:30
result = with_request_store do
# 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?
2018-03-17 18:26:18 +05:30
2020-04-08 14:13:33 +05:30
# 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]
2018-03-17 18:26:18 +05:30
2020-04-08 14:13:33 +05:30
# Remove API route mounting from the profile.
app.get('/api/v4/users')
2018-03-17 18:26:18 +05:30
2020-04-08 14:13:33 +05:30
with_custom_logger(logger) do
with_user(user) do
RubyProf.profile { app.public_send(verb, url, params: post_data, headers: headers) } # rubocop:disable GitlabSecurity/PublicSend
end
2019-02-15 15:39:39 +05:30
end
2018-03-17 18:26:18 +05:30
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, *)
2019-12-04 20:38:33 +05:30
message = message.gsub(private_token, FILTERED_STRING) if private_token
2018-03-17 18:26:18 +05:30
_, type, time = *message.match(/(\w+) Load \(([0-9.]+)ms\)/)
if type && time
@load_times_by_model ||= {}
2018-05-09 12:01:36 +05:30
@load_times_by_model[type] ||= []
@load_times_by_model[type] << time.to_f
2018-03-17 18:26:18 +05:30
end
super
2020-03-13 15:44:24 +05:30
Gitlab::BacktraceCleaner.clean_backtrace(caller).each do |caller_line|
2018-03-17 18:26:18 +05:30
stripped_caller_line = caller_line.sub("#{Rails.root}/", '')
super("#{stripped_caller_line}")
end
end
end
end
end
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
2019-02-15 15:39:39 +05:30
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
2018-03-17 18:26:18 +05:30
2019-02-15 15:39:39 +05:30
yield.tap do
remove_method(API::Helpers::CommonHelpers, :find_current_user!)
remove_method(ApplicationController, :current_user)
remove_method(ApplicationController, :authenticate_user!)
end
end
2018-03-17 18:26:18 +05:30
2019-02-15 15:39:39 +05:30
def self.remove_method(klass, meth)
klass.send(:remove_method, meth) if klass.instance_methods(false).include?(meth) # rubocop:disable GitlabSecurity/PublicSend
2018-03-17 18:26:18 +05:30
end
2018-12-05 23:21:45 +05:30
# rubocop: disable CodeReuse/ActiveRecord
2018-03-17 18:26:18 +05:30
def self.log_load_times_by_model(logger)
return unless logger.respond_to?(:load_times_by_model)
2018-05-09 12:01:36 +05:30
summarised_load_times = logger.load_times_by_model.to_a.map do |(model, times)|
[model, times.count, times.sum]
end
2019-10-12 21:52:04 +05:30
summarised_load_times.sort_by(&:last).reverse_each do |(model, query_count, time)|
2018-05-09 12:01:36 +05:30
logger.info("#{model} total (#{query_count}): #{time.round(2)}ms")
2018-03-17 18:26:18 +05:30
end
end
2018-12-05 23:21:45 +05:30
# rubocop: enable CodeReuse/ActiveRecord
2018-11-18 11:00:15 +05:30
def self.print_by_total_time(result, options = {})
2020-04-22 19:07:51 +05:30
default_options = { sort_method: :total_time, filter_by: :total_time }
2018-11-18 11:00:15 +05:30
2020-04-22 19:07:51 +05:30
RubyProf::FlatPrinter.new(result).print(STDOUT, default_options.merge(options))
2018-11-18 11:00:15 +05:30
end
2018-03-17 18:26:18 +05:30
end
end