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
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
|
# coding: utf-8
# frozen_string_literal: true
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/
ee/lib/gitlab/middleware/
lib/gitlab/performance_bar/
lib/gitlab/request_profiler/
lib/gitlab/query_limiting/
lib/gitlab/tracing/
lib/gitlab/profiler.rb
lib/gitlab/correlation_id.rb
lib/gitlab/webpack/dev_server_middleware.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 private_token
headers['Private-Token'] = private_token
user = nil # private_token overrides user
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
with_user(user) do
RubyProf.profile { app.public_send(verb, url, params: post_data, headers: headers) } # rubocop:disable GitlabSecurity/PublicSend
end
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] ||= []
@load_times_by_model[type] << time.to_f
end
super
Gitlab::Profiler.clean_backtrace(caller).each do |caller_line|
stripped_caller_line = caller_line.sub("#{Rails.root}/", '')
super(" ↳ #{stripped_caller_line}")
end
end
end
end
end
def self.clean_backtrace(backtrace)
Array(Rails.backtrace_cleaner.clean(backtrace)).reject do |line|
line.match(Regexp.union(IGNORE_BACKTRACES))
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
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
yield.tap do
remove_method(API::Helpers::CommonHelpers, :find_current_user!)
remove_method(ApplicationController, :current_user)
remove_method(ApplicationController, :authenticate_user!)
end
end
def self.remove_method(klass, meth)
klass.send(:remove_method, meth) if klass.instance_methods(false).include?(meth) # rubocop:disable GitlabSecurity/PublicSend
end
# rubocop: disable CodeReuse/ActiveRecord
def self.log_load_times_by_model(logger)
return unless logger.respond_to?(:load_times_by_model)
summarised_load_times = logger.load_times_by_model.to_a.map do |(model, times)|
[model, times.count, times.sum]
end
summarised_load_times.sort_by(&:last).reverse.each do |(model, query_count, time)|
logger.info("#{model} total (#{query_count}): #{time.round(2)}ms")
end
end
# rubocop: enable CodeReuse/ActiveRecord
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
end
end
|
