aboutsummaryrefslogtreecommitdiffstats
path: root/activesupport/lib/active_support/notifications/instrumenter.rb
blob: 00a57c38c94e9449b3dfff410f8b2dbafad0c32d (plain) (blame)
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
# frozen_string_literal: true

require "securerandom"

module ActiveSupport
  module Notifications
    # Instrumenters are stored in a thread local.
    class Instrumenter
      attr_reader :id

      def initialize(notifier)
        @id       = unique_id
        @notifier = notifier
      end

      # Instrument the given block by measuring the time taken to execute it
      # and publish it. Notice that events get sent even if an error occurs
      # in the passed-in block.
      def instrument(name, payload = {})
        # some of the listeners might have state
        listeners_state = start name, payload
        begin
          yield payload
        rescue Exception => e
          payload[:exception] = [e.class.name, e.message]
          payload[:exception_object] = e
          raise e
        ensure
          finish_with_state listeners_state, name, payload
        end
      end

      # Send a start notification with +name+ and +payload+.
      def start(name, payload)
        @notifier.start name, @id, payload
      end

      # Send a finish notification with +name+ and +payload+.
      def finish(name, payload)
        @notifier.finish name, @id, payload
      end

      def finish_with_state(listeners_state, name, payload)
        @notifier.finish name, @id, payload, listeners_state
      end

      private

        def unique_id
          SecureRandom.hex(10)
        end
    end

    class Event
      attr_reader :name, :time, :end, :transaction_id, :payload, :children

      def self.clock_gettime_supported? # :nodoc:
        defined?(Process::CLOCK_PROCESS_CPUTIME_ID) &&
          !Gem.win_platform?
      end
      private_class_method :clock_gettime_supported?

      def initialize(name, start, ending, transaction_id, payload)
        @name           = name
        @payload        = payload.dup
        @time           = start
        @transaction_id = transaction_id
        @end            = ending
        @children       = []
        @duration       = nil
        @cpu_time_start = nil
        @cpu_time_finish = nil
        @allocation_count_start = 0
        @allocation_count_finish = 0
      end

      # Record information at the time this event starts
      def start!
        @time = now
        @cpu_time_start = now_cpu
        @allocation_count_start = now_allocations
      end

      # Record information at the time this event finishes
      def finish!
        @cpu_time_finish = now_cpu
        @end = now
        @allocation_count_finish = now_allocations
      end

      def end=(ending)
        ActiveSupport::Deprecation.deprecation_warning(:end=, :finish!)
        @end = ending
      end

      # Returns the CPU time (in milliseconds) passed since the call to
      # +start!+ and the call to +finish!+
      def cpu_time
        (@cpu_time_finish - @cpu_time_start) * 1000
      end

      # Returns the idle time time (in milliseconds) passed since the call to
      # +start!+ and the call to +finish!+
      def idle_time
        duration - cpu_time
      end

      # Returns the number of allocations made since the call to +start!+ and
      # the call to +finish!+
      def allocations
        @allocation_count_finish - @allocation_count_start
      end

      # Returns the difference in milliseconds between when the execution of the
      # event started and when it ended.
      #
      #   ActiveSupport::Notifications.subscribe('wait') do |*args|
      #     @event = ActiveSupport::Notifications::Event.new(*args)
      #   end
      #
      #   ActiveSupport::Notifications.instrument('wait') do
      #     sleep 1
      #   end
      #
      #   @event.duration # => 1000.138
      def duration
        @duration ||= 1000.0 * (self.end - time)
      end

      def <<(event)
        @children << event
      end

      def parent_of?(event)
        @children.include? event
      end

      private
        def now
          Concurrent.monotonic_time
        end

        if clock_gettime_supported?
          def now_cpu
            Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID)
          end
        else
          def now_cpu
            0
          end
        end

        if defined?(JRUBY_VERSION)
          def now_allocations
            0
          end
        else
          def now_allocations
            GC.stat :total_allocated_objects
          end
        end
    end
  end
end