Module: Tracee::Benchmarkable

Included in:
Logger
Defined in:
lib/tracee/benchmarkable.rb

Overview

Suppose, we have a code that works too slow, still it runs for 50ms. You measure time in 5 points between calls, and it gives you the first time:

0.025997, 0.012339, 0.037864, 0.0415

the next time:

0.01658, 0.011366, 0.046607, 0.052117

the third time:

0.016733, 0.011295, 0.032805, 0.036667

How long has each block of code been executed actualy? The code runtime may fluctuate slightly because a PC does some work beside your benchmarking. The less the code runtime, the more relative fluctuations are. Thats why we do enough passes to minify them.

This module allows to not only measure time between arbitrary calls (ticks), and not only get an average from multiple repeats of a block, but to get a list of averages between each arbitrary call (tick) in a block.

Here’s a sample:

> $log.benchmark(times:20) Ability.new(u)

23:29:59.021 INFO [ability.rb:76 :assistant_permissions]: [tick +0.576797] 
23:29:59.034 INFO [ability.rb:84 :assistant_permissions]: [tick +0.245685] 
23:29:59.075 INFO [ability.rb:93 :assistant_permissions]: [tick +0.728214] 
23:29:59.120 INFO [ability.rb:111 :assistant_permissions]: [tick +0.866646] 
23:29:59.120 INFO [(irb):8 :irb_binding]: [tick +0.000559] [120.978946ms each; 2419.578914ms total] #<Ability:0x000000088c89c8>

Instance Method Summary collapse

Instance Method Details

#benchmark(times: 1) ⇒ Object 



27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
 
# File 'lib/tracee/benchmarkable.rb', line 27

def benchmark(times: 1)
  return yield unless info?
  
  @benchmark = Benchmark.new
  before_proc = Time.now
  
  prev_level, self.level = self.level, :unknown
  (times - 1).times {yield}
  self.level = prev_level
  @benchmark.last_pass!
  result = yield
  
  now = Time.now
  @benchmark = nil
  
  diff_ms = (now - before_proc)*1000
  milliseconds_each = highlight_time_diff(diff_ms/times)
  milliseconds_total = highlight_time_diff(diff_ms)
  info "[#{milliseconds_each}ms each; #{milliseconds_total}ms total] #{result}", caller_at: 1
  
ensure
  self.level = prev_level
  @benchmark = nil
end

#tick(msg = '', caller_offset: 0) ⇒ Object 



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
 
# File 'lib/tracee/benchmarkable.rb', line 52

def tick(msg='', caller_offset: 0)
  return unless @benchmark or info?
  
  now = Time.now
  
  if @benchmark
    if prev = Thread.current[:tracee_checkpoint]
      tick_diff = @benchmark.add_time(now - prev)
      if @benchmark.last_pass
        info "[tick +#{highlight_time_diff(tick_diff)}] #{msg}", caller_at: caller_offset+1
      end
      @benchmark.next
    # else we just write `now' to a thread var
    end
  else
    if prev = Thread.current[:tracee_checkpoint]
      info "[tick +#{highlight_time_diff(now - prev)}] #{msg}", caller_at: caller_offset+1
    else
      info "[tick] #{msg}", caller_at: caller_offset+1
    end
  end
  
  Thread.current[:tracee_checkpoint] = now
  nil
end

#tick!(msg = '', caller_offset: 0) ⇒ Object 



78
79
80
81
82
83
84
85
 
# File 'lib/tracee/benchmarkable.rb', line 78

def tick!(msg='', caller_offset: 0)
  return unless @benchmark or info?
  
  @benchmark.first! if @benchmark
  Thread.current[:tracee_checkpoint] = nil
  
  tick msg, caller_offset: caller_offset+1
end