Class: Timify

Inherits:
Object
  • Object
show all
Defined in:
lib/timify.rb,
lib/timify/span.rb,
lib/timify/trace.rb,
lib/timify/report.rb,
lib/timify/version.rb,
lib/timify/registry.rb,
lib/timify/recording.rb

Overview

Measures elapsed time between points in Ruby code.

#measure blocks nest. A parent span's inclusive time is the whole block, and its secs (self time) is what the children did not already take. #add marks the time since the previous mark on this thread. Intervals use a monotonic clock. #totals still reports started and finished as Time objects.

Each thread has its own cursor and span stack. Totals are shared and guarded by a mutex, so two threads can mark the same timer. total_time is the sum of self time and can exceed wall_time when threads overlap.

Timify.enabled is a process-wide switch. When it is false, every timer is a no-op: #add and #measure record nothing, and #initialize does not print. The default comes from TIMIFY_DISABLE (+1+, true, or on, case insensitive). Setting Timify.enabled= overrides that for the rest of the process.

Examples:

Time a few nested steps without printing

timer = Timify.new(:create_user, show: false)
timer.measure(:request) do
  timer.measure(:database) { :saved }
  timer.add(:mail)
end
timer.totals

Defined Under Namespace

Classes: Event, Span, Trace

Constant Summary collapse

VERSION = 
"1.0.0"
REGISTRY_MUTEX = 
Mutex.new
MAX_SAMPLES =

Retained samples per bucket. min, max, count, and the sums stay exact after this cap; percentiles then use the retained prefix.

10_000
THREAD_STATE_KEY = 
:__timify_thread_state__

Class Attribute Summary collapse

Instance Attribute Summary collapse

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(name, min_time_to_show: 0, show: true, output: $stdout) ⇒ Timify

Returns a new instance of Timify.

Parameters:

  • name (Object) —

    name included in reports and printed lines

  • min_time_to_show (Numeric) (defaults to: 0) —

    shortest segment that should be printed

  • show (Boolean) (defaults to: true) —

    whether to print the init line, segments, and summaries

  • output (#puts, #info) (defaults to: $stdout) —

    destination for printed lines



101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
 
# File 'lib/timify.rb', line 101

def initialize(name, min_time_to_show: 0, show: true, output: $stdout)
  @name = name
  @min_time_to_show = min_time_to_show
  @show = show
  @output = output
  @mutex = Mutex.new
  @generation = 0
  @slow_handlers = []
  @share_handlers = []
  @resume_at = nil
  @pause_started = nil
  @paused_monotonic = 0.0
  reset
  emit("<#{@name}> Timify init:<#{@initial_time}>. Location: #{caller_location}") if self.class.enabled?
end

Class Attribute Details

.enabled ⇒ Boolean

Process-wide recording switch. When false, every timer is a no-op. Defaults from TIMIFY_DISABLE when the class loads; enabled= overrides that for the rest of the process.

Returns:

  • (Boolean) 


41
42
43
 
# File 'lib/timify.rb', line 41

def enabled
  @enabled
end

Instance Attribute Details

#initial_time ⇒ Time (readonly)

Returns wall-clock time when the timer was created or last #reset.

Returns:

  • (Time) —

    wall-clock time when the timer was created or last #reset



70
71
72
 
# File 'lib/timify.rb', line 70

def initial_time
  @initial_time
end

#max_time_spent ⇒ Float (readonly)

Returns longest single self-time segment since creation or #reset.

Returns:

  • (Float) —

    longest single self-time segment since creation or #reset



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

def max_time_spent
  @max_time_spent
end

#min_time_to_show ⇒ Numeric

Minimum segment length, in seconds, required before #add or #measure prints. Shorter segments are still recorded. Defaults to 0.

Returns:

  • (Numeric) 


82
83
84
 
# File 'lib/timify.rb', line 82

def min_time_to_show
  @min_time_to_show
end

#name ⇒ Object (readonly)

Returns name given when the timer was created.

Returns:

  • (Object) —

    name given when the timer was created



64
65
66
 
# File 'lib/timify.rb', line 64

def name
  @name
end

#output ⇒ #puts, #info

Where printed lines are sent. An object that responds to puts is written with puts. An object that responds to info and not puts, such as a Logger, is written with info. Defaults to $stdout.

Returns:

  • (#puts, #info) 


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

def output
  @output
end

#show ⇒ Boolean

When false, the timer stays silent. Segments are still recorded. Defaults to true.

Returns:

  • (Boolean) 


88
89
90
 
# File 'lib/timify.rb', line 88

def show
  @show
end

#status ⇒ Symbol

Returns :on while the timer is recording, :off while it is paused.

Returns:

  • (Symbol) —

    :on while the timer is recording, :off while it is paused



76
77
78
 
# File 'lib/timify.rb', line 76

def status
  @status
end

#total ⇒ Float (readonly)

Returns self time recorded so far, excluding paused time.

Returns:

  • (Float) —

    self time recorded so far, excluding paused time



67
68
69
 
# File 'lib/timify.rb', line 67

def total
  @total
end

Class Method Details

.[](name) ⇒ Timify

Returns the timer registered under name, creating it on first use. Registered timers start with show: false so fetching one does not print.

Parameters:

  • name (Object)

Returns:



11
12
13
14
15
 
# File 'lib/timify/registry.rb', line 11

def self.[](name)
  REGISTRY_MUTEX.synchronize do
    registry[name] ||= new(name, show: false)
  end
end

.clear! ⇒ void

This method returns an undefined value.

Drops every timer created through [].



20
21
22
 
# File 'lib/timify/registry.rb', line 20

def self.clear!
  REGISTRY_MUTEX.synchronize { @registry = {} }
end

.enabled? ⇒ Boolean

Returns whether recording is currently enabled.

Returns:

  • (Boolean) —

    whether recording is currently enabled



44
45
46
 
# File 'lib/timify.rb', line 44

def enabled?
  !!@enabled
end

.env_disabled? ⇒ Boolean

Whether TIMIFY_DISABLE is set to a disabling value (+1+, true, or on, case insensitive). Used as the default for enabled when the class loads.

Returns:

  • (Boolean) 


53
54
55
56
57
58
 
# File 'lib/timify.rb', line 53

def env_disabled?
  value = ENV["TIMIFY_DISABLE"]
  return false if value.nil?

  %w[1 true on].include?(value.to_s.strip.downcase)
end

.measure(name, **options) {|timer| ... } ⇒ Timify

Creates a timer, yields it, and returns it after the block finishes. The block's return value is not returned; use #measure on the yielded timer when you need that value, or use trace to keep both. If the block raises, the exception propagates and the timer is not returned.

Parameters:

  • name (Object)
  • options (Hash) —

    keyword arguments accepted by #initialize

Yields:

  • (timer) —

    the new timer

Yield Parameters:

Returns:

Raises:

  • (ArgumentError) —

    when no block is given



128
129
130
131
132
133
134
 
# File 'lib/timify.rb', line 128

def self.measure(name, **options)
  raise ArgumentError, "measure requires a block" unless block_given?

  timer = new(name, **options)
  yield timer
  timer
end

.trace(name, **options) {|timer| ... } ⇒ Timify::Trace

Creates a timer, yields it, and returns a Trace with the block's value and the timer. If the block raises, the exception propagates and no Trace is returned.

Parameters:

  • name (Object)
  • options (Hash) —

    keyword arguments accepted by #initialize

Yields:

  • (timer) —

    the new timer

Yield Parameters:

Returns:

Raises:

  • (ArgumentError) —

    when no block is given



146
147
148
149
150
151
152
 
# File 'lib/timify.rb', line 146

def self.trace(name, **options)
  raise ArgumentError, "trace requires a block" unless block_given?

  timer = new(name, **options)
  value = yield timer
  Trace.new(value: value, timer: timer)
end

Instance Method Details

#add(label = nil) ⇒ Float

Records the time elapsed since the previous mark on this thread. Inside #measure, the mark becomes a child span instead of being counted again as part of the parent's self time. The first call on a thread has no range. Later calls record the jump from the previous call site to this one. When enabled is false, returns 0.0 and records nothing.

Parameters:

  • label (Object, nil) (defaults to: nil) —

    optional name. Symbols and strings with the same text are grouped together. nil and blank strings are ignored.

Returns:

  • (Float) —

    self time of this segment, or 0.0 when paused or disabled



46
47
48
49
50
51
52
53
54
55
56
 
# File 'lib/timify/recording.rb', line 46

def add(label = nil)
  return 0.0 unless self.class.enabled?

  location = caller_location
  normalized = normalize_label(label)
  time_spent, events = synchronize do
    paused? ? [0.0, []] : record_add(location, normalized)
  end
  deliver(events)
  time_spent
end

#measure(label = nil) { ... } ⇒ Object

Records the time spent inside block and returns the block's value. Time from the previous mark up to this call is stored first, when it is longer than zero, as an unlabeled segment. The block is a span: its inclusive time is the whole block, and its self time is what nested #measure and #add calls did not take. If the block raises, the span is still recorded and the exception propagates. While paused, or when enabled is false, the block runs and nothing is recorded.

Parameters:

  • label (Object, nil) (defaults to: nil) —

    same rules as #add

Yields:

  • the work to time

Returns:

  • (Object) —

    the block's return value

Raises:

  • (ArgumentError) —

    when no block is given



70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
 
# File 'lib/timify/recording.rb', line 70

def measure(label = nil)
  raise ArgumentError, "measure requires a block" unless block_given?
  return yield unless self.class.enabled?

  location = caller_location
  normalized = normalize_label(label)
  opened = false
  events = []
  synchronize do
    unless paused?
      open_measure(location, normalized)
      opened = true
    end
  end
  return yield unless opened

  begin
    yield
  ensure
    synchronize { events = close_measure }
    deliver(events)
  end
end

#on_share(ratio) {|event| ... } ⇒ Timify

Registers a callback invoked when a child span's inclusive time is at least ratio of the parent's elapsed time so far. Fires for labeled #measure and #add children, not for root spans or unlabeled gap spans. Several callbacks can be registered. They run after the segment is recorded, outside the timer mutex.

Parameters:

  • ratio (Numeric) —

    share from 0 to 1 inclusive

Yields:

  • (event)

Yield Parameters:

Returns:

Raises:

  • (ArgumentError) —

    when no block is given or ratio is outside 0..1



125
126
127
128
129
130
131
132
133
134
135
 
# File 'lib/timify/recording.rb', line 125

def on_share(ratio, &block)
  raise ArgumentError, "on_share requires a block" unless block

  value = Float(ratio)
  unless value >= 0.0 && value <= 1.0
    raise ArgumentError, "ratio must be between 0 and 1"
  end

  synchronize { @share_handlers << [value, block] }
  self
end

#on_slow(seconds) {|event| ... } ⇒ Timify

Registers a callback invoked when a segment is at least seconds long. #add compares the segment. #measure compares the block's inclusive time. Callbacks run after the timer has recorded the segment, and several callbacks can be registered.

Parameters:

  • seconds (Numeric)

Yields:

  • (event)

Yield Parameters:

Returns:

Raises:

  • (ArgumentError) —

    when no block is given or seconds is negative



104
105
106
107
108
109
110
111
112
 
# File 'lib/timify/recording.rb', line 104

def on_slow(seconds, &block)
  raise ArgumentError, "on_slow requires a block" unless block

  threshold = Float(seconds)
  raise ArgumentError, "threshold must be >= 0" if threshold.negative?

  synchronize { @slow_handlers << [threshold, block] }
  self
end

#reset ⇒ Timify

Clears recorded segments and starts the clock again. Keeps #name, #show, #min_time_to_show, #output, #on_slow, and #on_share callbacks. The timer is left running even if it was paused. Other threads drop their old cursor on the next mark.

Returns:



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
 
# File 'lib/timify/recording.rb', line 143

def reset
  synchronize do
    @generation += 1
    @status = :on
    @locations = {}
    @labels = {}
    @ranges = {}
    @roots = []
    @total = 0.0
    @max_time_spent = 0.0
    @initial_time = Time.now
    @finished_time = @initial_time
    @paused_monotonic = 0.0
    @pause_started = nil
    @resume_at = nil
    now = monotonic
    @origin_mark = now
    @last_record_mark = now
    thread_table[object_id] = {
      generation: @generation,
      last_mark: now,
      stack: [],
      location_prev: nil
    }
  end
  self
end

#totals(json: false, group: false) ⇒ Hash, String

Returns the report for every segment recorded so far. Pausing the timer does not hide this report. When #show is true, the printable summary is also written to #output.

locations, labels, and ranges are ordered by self time, slowest first. Each entry contains:

  • secs [Float] accumulated self time
  • inclusive [Float] accumulated inclusive time
  • percent [Integer] share of #total, rounded to the nearest percent
  • count [Integer] number of segments
  • min [Float] shortest self time
  • max [Float] longest self time
  • avg [Float] secs / count
  • p50, p95, p99 [Float] nearest-rank percentiles of self time
  • samples_truncated [Boolean] present when the percentile sample was capped

tree is the chronological list of top-level spans. Each node has label, location, secs, inclusive, and children. grouped_tree merges sibling nodes with the same label recursively: secs and inclusive are summed, count is how many spans were merged, and children are grouped the same way. Order of first appearance is preserved. wall_time is monotonic time from the start to the latest mark, minus pauses.

Parameters:

  • json (Boolean) (defaults to: false) —

    when true, return the same report as a JSON string

  • group (Boolean) (defaults to: false) —

    when true, print a Grouped spans: section after the chronological Spans section. grouped_tree is always included in the hash either way.

Returns:

  • (Hash, String) 


33
34
35
36
37
38
39
40
41
42
43
 
# File 'lib/timify/report.rb', line 33

def totals(json: false, group: false)
  report = synchronize { build_report(group: group) }
  emit(report[:message])

  if json
    require "json"
    report.to_json
  else
    report
  end
end