Class: Vuf::Profiler

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

Instance Method Summary collapse

Constructor Details

#initialize ⇒ Profiler

Returns a new instance of Profiler.



3
4
5
6
7
8
9
 
# File 'lib/vuf/profiler.rb', line 3

def initialize
  @mutex = Mutex.new
  @delay = 
  @stats = {:counter => {}, :time => {}, :avtime => {}}
  @timers = {}
  @enable = false
end

Instance Method Details

#count(label) ⇒ Object 



14
15
16
17
18
19
 
# File 'lib/vuf/profiler.rb', line 14

def count(label)
  @mutex.synchronize {
    @stats[:counter][label] ||= 0
    @stats[:counter][label] += 1
  }
end

#disable ⇒ Object 



12
 
# File 'lib/vuf/profiler.rb', line 12

def disable ; @enable = false ; end

#enable ⇒ Object 



11
 
# File 'lib/vuf/profiler.rb', line 11

def enable ; @enable = true ; end

#finalize ⇒ Object 



81
82
83
84
85
86
87
 
# File 'lib/vuf/profiler.rb', line 81

def finalize
  return if @stat_thread.nil? || !@stat_thread.alive?
  @running = false
  @stat_thread.wakeup
  @stat_thread.join
  @stat_thread=nil
end

#result ⇒ Object 



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
 
# File 'lib/vuf/profiler.rb', line 40

def result
  counter_stat = [] ; time_stat = [] ; current_time = Time.new
  error = nil
  @mutex.synchronize {
    begin 
      @stats[:counter].each{|k,v| counter_stat << [k, "#{k} => #{v.to_s.rjust(10,' ')}"] }
      counter_stat = counter_stat.sort{|a,b| a.first <=> b.first}.collect{|a| a.last}
      @stats[:time].each{ |k,v|
        # retrieve previous av_time and number of mesures (nbdata)
        av_time,nbdata = @stats[:avtime][k]
        # Init values if not already done
        av_time ||= 0 ; nbdata ||= 0
        # retrieve cumultime from previous average time
        cumul_time = av_time * nbdata
        unless v.nil?
          v.each{|time| cumul_time += time}
          # increase number of mesures with number of new mesure
          nbdata += v.size
        end
        av_time = cumul_time / nbdata
        time_stat << "#{k.to_s.rjust(20,' ')} => #{av_time.round(8).to_s.rjust(12,' ')} s/op " + 
          "[#{nbdata.to_s.rjust(12,' ')} op| #{(nbdata*av_time).round(2).to_s.rjust(8,' ')} s]"
        @stats[:avtime][k] = [av_time,nbdata]
        @stats[:time][k] = nil
      }
      @timers.each{|k,v|
        t = current_time - v.first
        if v.last && ( t > v.last)
          time_stat << "Timeout on #{k.last} : #{t} s"
        end
      }
      # time_stat = time_stat.sort{|a,b| a.first <=> b.first}.collect{|a| a.last}          
    rescue => e
      Logger.error {"Error in statistic #{e.message}\n#{e.backtrace.join("\n")}"}
      error = e
    end
  }
  raise error if error
  [counter_stat, time_stat].flatten.join("\n  - ")
end

#run(delay = 10) ⇒ Object 



89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
 
# File 'lib/vuf/profiler.rb', line 89

def run(delay=10)
  return if @stat_thread
  
  @stat_thread = Thread.new do
    enable ; GC::Profiler.enable ; @running = true
    while @running
      start('total') ; sleep(delay) ; stop('total')
      gc_result = [] ; GC::Profiler.result.each_line{|l| gc_result << l}
      Logger.info "Profiling Result : \n  - #{result}\n#{gc_result.shift}#{gc_result.first}#{gc_result.last}"
    end
    GC::Profiler.disable ; disable
  end
  # Ensure that finaliz was call at exit
  Kernel.at_exit { finalize }
end

#start(label, limit = nil) ⇒ Object 



20
21
22
 
# File 'lib/vuf/profiler.rb', line 20

def start(label,limit=nil)
  @mutex.synchronize { @timers[[Thread.current,label]] = [Time.new,limit] }
end

#stop(label) ⇒ Object 



24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
 
# File 'lib/vuf/profiler.rb', line 24

def stop(label)
  Logger.error "Invalid label #{label}" unless label.instance_of?(String) || label.instance_of?(Symbol)
  new_time = Time.new
  @mutex.synchronize { 
    time,limit = @timers.delete([Thread.current,label])
    if time
      @stats[:time][label] ||= []
      t = new_time - time
      if limit && t > limit
        Logger.warn "Time limit exceeds for #{label} : #{t} s"
      end
      @stats[:time][label] << t
    end
  }
end