1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
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
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
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
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
|
# coding: utf-8
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/
lib/gitlab/performance_bar/
lib/gitlab/request_profiler/
lib/gitlab/profiler.rb
].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
if user
private_token ||= user.personal_access_tokens.active.pluck(:token).first
raise 'Your user must have a personal_access_token' unless private_token
end
headers['Private-Token'] = private_token if private_token
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
RubyProf.profile { app.public_send(verb, url, post_data, headers) } # rubocop:disable GitlabSecurity/PublicSend
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 ||= {}
@load_times_by_model[type] ||= 0
@load_times_by_model[type] += time.to_f
end
super
backtrace = Rails.backtrace_cleaner.clean(caller)
backtrace.each do |caller_line|
next if caller_line.match(Regexp.union(IGNORE_BACKTRACES))
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
result = yield
ActiveSupport::LogSubscriber.colorize_logging = original_colorize_logging
ActiveRecord::Base.logger = original_activerecord_logger
ActionController::Base.logger = original_actioncontroller_logger
result
end
def self.log_load_times_by_model(logger)
return unless logger.respond_to?(:load_times_by_model)
logger.load_times_by_model.to_a.sort_by(&:last).reverse.each do |(model, time)|
logger.info("#{model} total: #{time.round(2)}ms")
end
end
end
end
|
