Module: Prosopite

Defined in:
lib/prosopite.rb,
lib/prosopite/version.rb,
lib/prosopite/middleware/rack.rb,
lib/prosopite/middleware/sidekiq.rb

Defined Under Namespace

Modules: Middleware Classes: NPlusOneQueriesError

Constant Summary collapse

DEFAULT_ALLOW_LIST = 
[
  /active_record\/relation.rb.*preload_associations/,
  'active_record/validations/uniqueness'
].freeze
VERSION = 
"2.2.0"

Class Attribute Summary collapse

Class Method Summary collapse

Class Attribute Details

.allow_stack_paths ⇒ Object

Returns the value of attribute allow_stack_paths.



19
20
21
 
# File 'lib/prosopite.rb', line 19

def allow_stack_paths
  @allow_stack_paths
end

.backtrace_cleaner ⇒ Object 



29
30
31
 
# File 'lib/prosopite.rb', line 29

def backtrace_cleaner
  @backtrace_cleaner ||= Rails.backtrace_cleaner
end

.custom_logger=(value) ⇒ Object (writeonly)

Sets the attribute custom_logger

Parameters:

  • value —

    the value to set the attribute custom_logger to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def custom_logger=(value)
  @custom_logger = value
end

.enabled=(value) ⇒ Object (writeonly)

Sets the attribute enabled

Parameters:

  • value —

    the value to set the attribute enabled to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def enabled=(value)
  @enabled = value
end

.ignore_pauses=(value) ⇒ Object (writeonly)

Sets the attribute ignore_pauses

Parameters:

  • value —

    the value to set the attribute ignore_pauses to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def ignore_pauses=(value)
  @ignore_pauses = value
end

.ignore_queries ⇒ Object

Returns the value of attribute ignore_queries.



19
20
21
 
# File 'lib/prosopite.rb', line 19

def ignore_queries
  @ignore_queries
end

.min_n_queries ⇒ Object

Returns the value of attribute min_n_queries.



19
20
21
 
# File 'lib/prosopite.rb', line 19

def min_n_queries
  @min_n_queries
end

.prosopite_logger=(value) ⇒ Object (writeonly)

Sets the attribute prosopite_logger

Parameters:

  • value —

    the value to set the attribute prosopite_logger to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def prosopite_logger=(value)
  @prosopite_logger = value
end

.rails_logger=(value) ⇒ Object (writeonly)

Sets the attribute rails_logger

Parameters:

  • value —

    the value to set the attribute rails_logger to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def rails_logger=(value)
  @rails_logger = value
end

.raise=(value) ⇒ Object (writeonly)

Sets the attribute raise

Parameters:

  • value —

    the value to set the attribute raise to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def raise=(value)
  @raise = value
end

.stderr_logger=(value) ⇒ Object (writeonly)

Sets the attribute stderr_logger

Parameters:

  • value —

    the value to set the attribute stderr_logger to.



10
11
12
 
# File 'lib/prosopite.rb', line 10

def stderr_logger=(value)
  @stderr_logger = value
end

Class Method Details

.allow_list=(value) ⇒ Object 



23
24
25
26
27
 
# File 'lib/prosopite.rb', line 23

def allow_list=(value)
  puts "Prosopite.allow_list= is deprecated. Use Prosopite.allow_stack_paths= instead."

  self.allow_stack_paths = value
end

.create_notifications ⇒ Object 



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
 
# File 'lib/prosopite.rb', line 134

def create_notifications
  tc[:prosopite_notifications] = {}

  tc[:prosopite_query_counter].each do |location_key, count|
    if count >= @min_n_queries
      fingerprints = tc[:prosopite_query_holder][location_key].group_by do |q|
        begin
          fingerprint(q)
        rescue
          raise q
        end
      end

      queries = fingerprints.values.select { |q| q.size >= @min_n_queries }

      next unless queries.any?

      kaller = tc[:prosopite_query_caller][location_key].map(&:to_s)
      allow_list = (@allow_stack_paths + DEFAULT_ALLOW_LIST)
      is_allowed = kaller.any? { |f| allow_list.any? { |s| f.match?(s) } }

      unless is_allowed
        duration_ms = tc[:prosopite_query_duration][location_key]
        queries.each do |q|
          tc[:prosopite_notifications][q] = { kaller: kaller, duration_ms: duration_ms }
        end
      end
    end
  end
end

.disabled? ⇒ Boolean

Returns:

  • (Boolean) 


39
40
41
 
# File 'lib/prosopite.rb', line 39

def disabled?
  !enabled?
end

.enabled? ⇒ Boolean

Returns:

  • (Boolean) 


33
34
35
36
37
 
# File 'lib/prosopite.rb', line 33

def enabled?
  @enabled = true if @enabled.nil?

  @enabled
end

.fingerprint(query) ⇒ Object 



165
166
167
168
169
170
171
172
173
174
175
176
177
178
 
# File 'lib/prosopite.rb', line 165

def fingerprint(query)
  db_adapter = ActiveRecord::Base.connection_db_config.adapter
  if db_adapter.include?('mysql') || db_adapter.include?('trilogy')
    mysql_fingerprint(query)
  else
    begin
      require 'pg_query'
    rescue LoadError => e
      msg = "Could not load the 'pg_query' gem. Add `gem 'pg_query'` to your Gemfile"
      raise LoadError, msg, e.backtrace
    end
    PgQuery.fingerprint(query)
  end
end

.finish ⇒ Object 



104
105
106
107
108
109
110
111
112
113
114
115
116
 
# File 'lib/prosopite.rb', line 104

def finish
  return unless scan?

  tc[:prosopite_scan] = false

  create_notifications
  send_notifications if tc[:prosopite_notifications].present?

  tc[:prosopite_query_counter] = nil
  tc[:prosopite_query_holder] = nil
  tc[:prosopite_query_caller] = nil
  tc[:prosopite_query_duration] = nil
end

.ignore_query?(sql) ⇒ Boolean

Returns:

  • (Boolean) 


273
274
275
276
 
# File 'lib/prosopite.rb', line 273

def ignore_query?(sql)
  @ignore_queries ||= []
  @ignore_queries.any? { |q| q === sql }
end

.local_raise? ⇒ Boolean

Returns:

  • (Boolean) 


126
127
128
 
# File 'lib/prosopite.rb', line 126

def local_raise?
  tc[:prosopite_local_raise] == true
end

.mysql_fingerprint(query) ⇒ Object

Many thanks to github.com/genkami/fluent-plugin-query-fingerprint/



181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
 
# File 'lib/prosopite.rb', line 181

def mysql_fingerprint(query)
  query = query.dup

  return "mysqldump" if query =~ %r#\ASELECT /\*!40001 SQL_NO_CACHE \*/ \* FROM `#
  return "percona-toolkit" if query =~ %r#\*\w+\.\w+:[0-9]/[0-9]\*/#
  if match = /\A\s*(call\s+\S+)\(/i.match(query)
    return match.captures.first.downcase!
  end

  if match = /\A((?:INSERT|REPLACE)(?: IGNORE)?\s+INTO.+?VALUES\s*\(.*?\))\s*,\s*\(/im.match(query)
    query = match.captures.first
  end

  query.gsub!(%r#/\*[^!].*?\*/#m, "")
  query.gsub!(/(?:--|#)[^\r\n]*(?=[\r\n]|\Z)/, "")

  return query if query.gsub!(/\Ause \S+\Z/i, "use ?")

  query.gsub!(/\\["']/, "")
  query.gsub!(/".*?"/m, "?")
  query.gsub!(/'.*?'/m, "?")

  query.gsub!(/\btrue\b|\bfalse\b/i, "?")

  query.gsub!(/[0-9+-][0-9a-f.x+-]*/, "?")
  query.gsub!(/[xb.+-]\?/, "?")

  query.strip!
  query.gsub!(/[ \n\t\r\f]+/, " ")
  query.downcase!

  query.gsub!(/\bnull\b/i, "?")

  query.gsub!(/\b(in|values?)(?:[\s,]*\([\s?,]*\))+/, "\\1(?+)")

  query.gsub!(/(?<!\w)field\s*\(\s*(\S+)\s*,\s*(\?+)(?:\s*,\s*\?+)*\)/, 'field(\1, \2+)')

  query.gsub!(/\b(select\s.*?)(?:(\sunion(?:\sall)?)\s\1)+/, "\\1 /*repeat\\2*/")

  query.gsub!(/\blimit \?(?:, ?\?| offset \?)/, "limit ?")

  if query =~ /\border by/
    query.gsub!(/\G(.+?)\s+asc/, "\\1")
  end

  query
end

.pause ⇒ Object 



77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
 
# File 'lib/prosopite.rb', line 77

def pause
  if @ignore_pauses
    return block_given? ? yield : nil
  end

  if block_given?
    begin
      previous = tc[:prosopite_scan]
      tc[:prosopite_scan] = false
      yield
    ensure
      tc[:prosopite_scan] = previous
    end
  else
    tc[:prosopite_scan] = false
  end
end

.raise? ⇒ Boolean

Returns:

  • (Boolean) 


130
131
132
 
# File 'lib/prosopite.rb', line 130

def raise?
  local_raise? || !!@raise
end

.red(str) ⇒ Object 



269
270
271
 
# File 'lib/prosopite.rb', line 269

def red(str)
  str.split("\n").map { |line| "\e[91m#{line}\e[0m" }.join("\n")
end

.resume ⇒ Object 



95
96
97
 
# File 'lib/prosopite.rb', line 95

def resume
  tc[:prosopite_scan] = true
end

.scan ⇒ Object 



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
 
# File 'lib/prosopite.rb', line 43

def scan
  tc[:prosopite_scan] ||= false
  if scan? || disabled?
    return block_given? ? yield : nil
  end

  subscribe

  tc[:prosopite_query_counter] = Hash.new(0)
  tc[:prosopite_query_holder] = Hash.new { |h, k| h[k] = [] }
  tc[:prosopite_query_caller] = {}
  tc[:prosopite_query_duration] = Hash.new(0.0)

  @allow_stack_paths ||= []
  @ignore_pauses ||= false
  @min_n_queries ||= 2

  tc[:prosopite_scan] = true

  if block_given?
    begin
      block_result = yield
      finish
      block_result
    ensure
      tc[:prosopite_scan] = false
    end
  end
end

.scan? ⇒ Boolean

Returns:

  • (Boolean) 


99
100
101
102
 
# File 'lib/prosopite.rb', line 99

def scan?
  !!(tc[:prosopite_scan] && tc[:prosopite_query_counter] &&
     tc[:prosopite_query_holder] && tc[:prosopite_query_caller])
end

.send_notifications ⇒ Object

Raises:



229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
 
# File 'lib/prosopite.rb', line 229

def send_notifications
  @custom_logger ||= false
  @rails_logger ||= false
  @stderr_logger ||= false
  @prosopite_logger ||= false

  notifications_str = String.new('')

  tc[:prosopite_notifications].each do |queries, info|
    kaller = info[:kaller]
    duration_ms = info[:duration_ms]
    time_str = duration_ms ? " (#{duration_ms.round(1)}ms)" : ''

    notifications_str << "N+1 queries detected#{time_str}:\n"

    queries.each { |q| notifications_str << "  #{q}\n" }

    notifications_str << "Call stack:\n"
    kaller = backtrace_cleaner.clean(kaller)
    kaller.each do |f|
      notifications_str << "  #{f}\n"
    end

    notifications_str << "\n"
  end

  @custom_logger.warn(notifications_str) if @custom_logger

  Rails.logger.warn(red(notifications_str)) if @rails_logger
  $stderr.puts(red(notifications_str)) if @stderr_logger

  if @prosopite_logger
    File.open(File.join(Rails.root, 'log', 'prosopite.log'), 'a') do |f|
      f.puts(notifications_str)
    end
  end

  raise NPlusOneQueriesError.new(notifications_str) if raise?
end

.start_raise ⇒ Object 



118
119
120
 
# File 'lib/prosopite.rb', line 118

def start_raise
  tc[:prosopite_local_raise] = true
end

.stop_raise ⇒ Object 



122
123
124
 
# File 'lib/prosopite.rb', line 122

def stop_raise
  tc[:prosopite_local_raise] = false
end

.subscribe ⇒ Object 



278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
 
# File 'lib/prosopite.rb', line 278

def subscribe
  @subscribed ||= false
  return if @subscribed

  ActiveSupport::Notifications.subscribe 'sql.active_record' do |_, start, finish, _, data|
    sql, name = data[:sql], data[:name]

    if scan? && name != "SCHEMA" && sql.include?('SELECT') && data[:cached].nil? && !ignore_query?(sql)
      query_caller = caller_locations
      # Calculate the location key with as few allocations as possible
      location_key = [].tap do |array|
        query_caller.each do |loc|
          array << loc.path
          array << loc.lineno
        end
      end.hash

      tc[:prosopite_query_counter][location_key] += 1
      tc[:prosopite_query_holder][location_key] << sql
      tc[:prosopite_query_duration][location_key] += (finish - start) * 1000 if tc[:prosopite_query_duration]

      if tc[:prosopite_query_counter][location_key] > 1
        tc[:prosopite_query_caller][location_key] = query_caller
      end
    end
  end

  @subscribed = true
end

.tc ⇒ Object 



73
74
75
 
# File 'lib/prosopite.rb', line 73

def tc
  Thread.current
end