Class: MethodProfiler

Inherits:
Object
  • Object
show all
Defined in:
lib/method_profiler.rb

Overview

see samsaffron.com/archive/2017/10/18/fastest-way-to-profile-a-method-in-ruby

Class Method Summary collapse

Class Method Details

.clear ⇒ Object 



96
97
98
 
# File 'lib/method_profiler.rb', line 96

def self.clear
  Thread.current[:_method_profiler] = nil
end

.ensure_discourse_instrumentation! ⇒ Object 



135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
 
# File 'lib/method_profiler.rb', line 135

def self.ensure_discourse_instrumentation!
  @@instrumentation_setup ||=
    begin
      MethodProfiler.patch(
        PG::Connection,
        %i[exec async_exec exec_prepared send_query_prepared query exec_params],
        :sql,
      )

      MethodProfiler.patch(Redis::Client, %i[call call_pipeline], :redis)

      MethodProfiler.patch(Net::HTTP, [:request], :net, no_recurse: true)

      MethodProfiler.patch(Excon::Connection, [:request], :net)
      true
    end
end

.output_sql_to_stderr!(filter_transactions: false) ⇒ Object

This is almost the same as ensure_discourse_instrumentation! but should not be used in production. This logs all SQL queries run and their durations between start and stop.

filter_transactions - When true, we do not record timings of transaction related commits (BEGIN, COMMIT, ROLLBACK)



119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
 
# File 'lib/method_profiler.rb', line 119

def self.output_sql_to_stderr!(filter_transactions: false)
  Rails.logger.warn(
    "Stop! This instrumentation is not intended for use in production outside of debugging scenarios. Please be sure you know what you are doing when enabling this instrumentation.",
  )
  @@instrumentation_debug_sql_filter_transactions = filter_transactions
  @@instrumentation_setup_debug_sql ||=
    begin
      MethodProfiler.patch_with_debug_sql(
        PG::Connection,
        %i[exec async_exec exec_prepared send_query_prepared query exec_params],
        :sql,
      )
      true
    end
end

.patch(klass, methods, name, no_recurse: false) ⇒ Object 



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

def self.patch(klass, methods, name, no_recurse: false)
  patches =
    methods
      .map do |method_name|
        recurse_protection = ""
        recurse_protection = <<~RUBY if no_recurse
        return #{method_name}__mp_unpatched(*args, &blk) if @mp_recurse_protect_#{method_name}
        @mp_recurse_protect_#{method_name} = true
      RUBY

        <<~RUBY
    unless defined?(#{method_name}__mp_unpatched)
      alias_method :#{method_name}__mp_unpatched, :#{method_name}
      def #{method_name}(*args, &blk)
        unless prof = Thread.current[:_method_profiler]
          return #{method_name}__mp_unpatched(*args, &blk)
        end
        #{recurse_protection}
        begin
          start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
          #{method_name}__mp_unpatched(*args, &blk)
        ensure
          data = (prof[:#{name}] ||= {duration: 0.0, calls: 0})
          data[:duration] += Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
          data[:calls] += 1
          #{"@mp_recurse_protect_#{method_name} = false" if no_recurse}
        end
      end
    end
    RUBY
      end
      .join("\n")

  klass.class_eval patches
end

.patch_with_debug_sql(klass, methods, name, no_recurse: false) ⇒ Object 



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

def self.patch_with_debug_sql(klass, methods, name, no_recurse: false)
  patches =
    methods
      .map do |method_name|
        recurse_protection = ""
        recurse_protection = <<~RUBY if no_recurse
        return #{method_name}__mp_unpatched_debug_sql(*args, &blk) if @mp_recurse_protect_#{method_name}
        @mp_recurse_protect_#{method_name} = true
      RUBY

        <<~RUBY
    unless defined?(#{method_name}__mp_unpatched_debug_sql)
      alias_method :#{method_name}__mp_unpatched_debug_sql, :#{method_name}
      def #{method_name}(*args, &blk)
        #{recurse_protection}

        query = args[0]
        should_filter = #{@@instrumentation_debug_sql_filter_transactions} &&
                          (query == "COMMIT" || query == "BEGIN" || query == "ROLLBACK")
        if !should_filter
          STDERR.puts "debugsql (sql): " + query
        end

        begin
          start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
          #{method_name}__mp_unpatched_debug_sql(*args, &blk)
        ensure
          duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start

          if !should_filter
            STDERR.puts "debugsql (sec): " + duration.round(3).to_s
          end

          #{"@mp_recurse_protect_#{method_name} = false" if no_recurse}
        end
      end
    end
    RUBY
      end
      .join("\n")

  klass.class_eval patches
end

.start(transfer = nil) ⇒ Object 



91
92
93
94
 
# File 'lib/method_profiler.rb', line 91

def self.start(transfer = nil)
  Thread.current[:_method_profiler] = transfer ||
    { __start: Process.clock_gettime(Process::CLOCK_MONOTONIC) }
end

.stop ⇒ Object 



100
101
102
103
104
105
106
107
108
109
110
 
# File 'lib/method_profiler.rb', line 100

def self.stop
  finish = Process.clock_gettime(Process::CLOCK_MONOTONIC)

  if data = Thread.current[:_method_profiler]
    Thread.current[:_method_profiler] = nil
    start = data.delete(:__start)
    data[:total_duration] = finish - start
  end

  data
end

.transfer ⇒ Object 



85
86
87
88
89
 
# File 'lib/method_profiler.rb', line 85

def self.transfer
  result = Thread.current[:_method_profiler]
  Thread.current[:_method_profiler] = nil
  result
end