Class: Roby::Log::Timings

Inherits:
Object show all
Defined in:
lib/roby/log/timings.rb

Constant Summary collapse

REF_TIMING = 
:start
ALL_TIMINGS = 
[ :real_start, :events, 
:structure_check, :exception_propagation,
:exceptions_fatal, :garbage_collect, :application_errors, 
:expected_ruby_gc, :ruby_gc, :droby, :expected_sleep, :sleep, :end ]
NUMERIC_FIELDS = 
[:cycle_index, :live_objects, :object_allocation, :log_queue_size, :ruby_gc_duration, 
:plan_task_count, :plan_event_count]
DELTAS = 
[:cpu_time]
ALL_NUMERIC_FIELDS = 
NUMERIC_FIELDS + DELTAS
ALL_FIELDS = 
ALL_TIMINGS + ALL_NUMERIC_FIELDS + [:event_count, :pos]

Instance Attribute Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(logfile) ⇒ Timings

Returns a new instance of Timings.



19
20
21
22
23
 
# File 'lib/roby/log/timings.rb', line 19

def initialize(logfile)
    @logfile = logfile
    @ignored_timings = Set.new
    rewind
end

Instance Attribute Details

#ignored_timings ⇒ Object (readonly)

Returns the value of attribute ignored_timings.



18
19
20
 
# File 'lib/roby/log/timings.rb', line 18

def ignored_timings
  @ignored_timings
end

#logfile ⇒ Object (readonly)

Returns the value of attribute logfile.



17
18
19
 
# File 'lib/roby/log/timings.rb', line 17

def logfile
  @logfile
end

Instance Method Details

#display(cumulative) ⇒ Object 



149
150
151
152
153
154
155
156
157
158
159
160
161
 
# File 'lib/roby/log/timings.rb', line 149

def display(cumulative)
    header = ([REF_TIMING] + ALL_TIMINGS + ALL_NUMERIC_FIELDS).enum_for(:each_with_index).
 map { |n, i| "#{i + 1}_#{n}" }.
 join("\t")

    puts header
    each_cycle(cumulative) do |numeric, results|
 print "#{timeval_to_s(results.shift)} "
 print results.join(" ")
 print " "
 puts numeric.join(" ")
    end
end

#each_cycle(cumulative = false) ⇒ Object 



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
 
# File 'lib/roby/log/timings.rb', line 26

def each_cycle(cumulative = false)
    last_deltas = Hash.new
    for data in logfile.index_data[1..-1]
 result  = []
 timings = data
 ref     = Time.at(*timings.delete(REF_TIMING))
 result  << ref

 unknown_timings = (timings.keys.to_set - ALL_FIELDS.to_set - ignored_timings)
 if !unknown_timings.empty?
      STDERR.puts "ignoring the following timings: #{unknown_timings.to_a.join(", ")}"
      @ignored_timings |= unknown_timings
 end
 timings = ALL_TIMINGS.map do |name|
      timings[name]
 end

 if cumulative
      timings.inject(0) do |last, time| 
  time ||= last
  result << time
  time
      end
 else
      timings.inject(0) do |last, time| 
  time ||= last
  result << time - last
  time
      end
 end

 numeric = data.values_at(*NUMERIC_FIELDS)
 deltas = DELTAS.map do |name|
      value = if old_value = last_deltas[name]
   data[name] - old_value
        else
   0
        end
      last_deltas[name] = data[name]
      value
 end

 yield(numeric + deltas, result)
    end

rescue ArgumentError => e
    if e.message =~ /marshal data too short/
 STDERR.puts "File truncated"
    else raise
    end
end

#rewind ⇒ Object 



24
 
# File 'lib/roby/log/timings.rb', line 24

def rewind; logfile.rewind end

#stats ⇒ Object 



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
 
# File 'lib/roby/log/timings.rb', line 82

def stats
    last_start = nil
    mean, max, stdev = nil
    count = 0

    mean_cycle  = 0
    stdev_cycle = 0
    max_cycle   = nil

    # Compute mean value
    each_cycle(false) do |numeric, timings|
 if !mean
      mean  = Array.new(numeric.size + timings.size, 0.0)
      max   = Array.new
 end

 # Compute mean value
 start = timings.shift + timings.first
 if last_start
      cycle_length = start - last_start
      if !max_cycle || max_cycle < cycle_length
  max_cycle = cycle_length
      end
      mean_cycle += cycle_length
 end
 last_start = start 

 (numeric + timings).each_with_index do |v, i| 
      mean[i] += v if v
      max[i] = v if v && (!max[i] || max[i] < v)
 end
 count += 1
    end
    mean.map! { |v| v / count }
    mean_cycle /= count

    last_start = nil
    rewind
    stdev = Array.new(mean.size, 0.0)
    each_cycle(false) do |numeric, timings|
 start = timings.shift + timings.first
 if last_start
      stdev_cycle += (start - last_start - mean_cycle)**2
 end
 last_start = start

 (numeric + timings).each_with_index { |v, i| stdev[i] += (v - mean[i]) ** 2 if v }
    end
    stdev.map! { |v| Math.sqrt(v / count) if v }

    format = "%-28s %-10.2f %-10.2f %-10.2f"

    puts "\n" + "Per-cycle statistics".center(50)
    puts "%-28s %-10s %-10s %-10s" % ['', 'mean', 'stddev', 'max']
    puts format % ["cycle", mean_cycle * 1000, Math.sqrt(stdev_cycle / count) * 1000, max_cycle * 1000]
    ALL_NUMERIC_FIELDS.each_with_index do |name, i|
 puts format % [name, mean[i], stdev[i], (max[i] || 0)] unless name == :cycle_index
    end

    puts "\n" + "Broken down cycle timings".center(50)
    puts "%-28s %-10s %-10s %-10s" % ['', 'mean', 'stddev', 'max']
    (ALL_TIMINGS).each_with_index do |name, i|
 i += ALL_NUMERIC_FIELDS.size
 puts format % [name, mean[i] * 1000, stdev[i] * 1000, max[i] * 1000]
    end
end

#timeval_to_s(t) ⇒ Object 



78
79
80
 
# File 'lib/roby/log/timings.rb', line 78

def timeval_to_s(t)
    '%02i:%02i:%02i.%03i' % [t.tv_sec / 3600, t.tv_sec % 3600 / 60, t.tv_sec % 60, t.tv_usec / 1000]
end