Class: Roby::CLI::Log

Inherits:
Thor show all
Defined in:
lib/roby/cli/log.rb,
lib/roby/cli/log/flamegraph_renderer.rb

Defined Under Namespace

Classes: FlamegraphRenderer

Instance Method Summary collapse

Instance Method Details

#current(robot_name = nil) ⇒ Object 



316
317
318
319
320
321
322
323
324
325
326
327
 
# File 'lib/roby/cli/log.rb', line 316

def current(robot_name = nil)
    Roby.app.require_app_dir
    if robot_name
        Roby.app.setup_robot_names_from_config_dir
        Roby.app.robot(robot_name)
    end
    if options[:dir]
        puts Roby.app.log_current_dir
    else
        puts Roby.app.log_current_file
    end
end

#decode(file = nil) ⇒ Object 



240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
 
# File 'lib/roby/cli/log.rb', line 240

def decode(file = nil)
    file = handle_file_argument(file)

    require "roby/droby/logfile/reader"
    require "roby/droby/plan_rebuilder"

    stream = Roby::DRoby::Logfile::Reader.open(file)
    replay = options[:replay]
    if replay != "no"
        replay_debug = (replay == "debug")
        rebuilder = Roby::DRoby::PlanRebuilder.new
    end

    while data = stream.load_one_cycle
        data.each_slice(4) do |m, sec, usec, args|
            header = "#{Time.at(sec, usec)} #{m} "
            puts "#{header} #{args.map(&:to_s).join('  ')}"
            header = " " * header.size
            if rebuilder
                begin
                    rebuilder.process_one_event(m, sec, usec, args)
                    if replay_debug
                        if m == :merged_plan
                            puts "Merged plan"
                            plan = args[1]
                            puts "  #{plan.tasks.size} tasks: #{plan.tasks.map { |id, _| id.to_s }.join(', ')}"
                            puts "  #{plan.task_events.size} task events: #{plan.task_events.map { |id, _| id.to_s }.join(', ')}"
                            puts "  #{plan.free_events.size} events: #{plan.free_events.map { |id, _| id.to_s }.join(', ')}"
                        end
                        pp rebuilder
                    end
                rescue Roby::DRoby::UnknownSibling
                    # Add some more debugging information
                    pp rebuilder
                    raise
                end
            end
        end
        rebuilder&.clear_integrated
    end
end

#display(file = nil) ⇒ Object 



334
335
336
337
338
 
# File 'lib/roby/cli/log.rb', line 334

def display(file = nil)
    file = handle_file_argument(file)
    require "roby/cli/display"
    Display.new.file(file, index_path: options[:index_path])
end

#rebuild_index(file = nil) ⇒ Object 



40
41
42
43
44
45
 
# File 'lib/roby/cli/log.rb', line 40

def rebuild_index(file = nil)
    file = handle_file_argument(file)
    require "roby/droby/logfile/reader"
    Roby::DRoby::Logfile::Reader.open(file)
       .rebuild_index
end

#repair(file) ⇒ Object 



283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
 
# File 'lib/roby/cli/log.rb', line 283

def repair(file)
    require "fileutils"
    require "roby/droby/logfile/reader"
    logfile = Roby::DRoby::Logfile::Reader.open(file)
    last_cycle = nil
    until logfile.eof?
        current_pos = logfile.tell
        begin
            last_cycle = logfile.load_one_cycle
        rescue Roby::DRoby::Logfile::TruncatedFileError
            stat = File.stat(file)
            puts "last chunk(s) in the file seem to have only been partially written."
            puts "truncating at #{current_pos} out of #{stat.size} (removing #{stat.size - current_pos} bytes)"
            if last_cycle
                info = last_cycle.last.last
                end_time = Time.at(*info[:start]) + info[:end]
                puts "the repaired file ends at #{end_time}"
            else
                puts "there are no valid cycles in the truncated file"
            end
            FileUtils.cp file, "#{file}.broken"
            puts "the original has been saved as '#{file}.broken'"
            File.open(file, "a+") do |io|
                io.truncate(current_pos)
            end
            break
        end
    end
ensure logfile.close
end

#stats(file = nil) ⇒ Object 



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
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
 
# File 'lib/roby/cli/log.rb', line 134

def stats(file = nil)
    file = handle_file_argument(file)

    require "roby/droby/logfile/reader"
    stream = Roby::DRoby::Logfile::Reader.open(file)
    index = stream.index

    cycle_count = index.size

    if cycle_count == 0
        puts "empty log file"
        exit 0
    end

    timespan = index.range
    puts "#{cycle_count} cycles between #{timespan.first.to_hms} "\
         "and #{timespan.last.to_hms}"
    process_utime = index.inject(0) { |old, info| old + info[:utime] }
    process_stime = index.inject(0) { |old, info| old + info[:stime] }
    real_time = timespan.last - timespan.first
    ratio = (process_utime + process_stime) / real_time
    puts format("Time: %.2fs user / %.2fs sys / %.2fs real (%i%% CPU use)",
                process_utime, process_stime, real_time, ratio * 100)

    min, max = nil
    event_count = index.inject(0) do |total, cycle_info|
        count = cycle_info[:event_count]
        min = count if !min || min > count
        max = count if !max || max < count
        total + count
    end
    puts "#{event_count} log events, #{event_count / cycle_count} "\
         "events/cycle (min: #{min}, max: #{max})"

    io = STDOUT
    if options[:save]
        io = File.open(options[:save], "w")
    end

    # !!! make sure the order in header, fomatting and in the format
    # call below all match
    header = %w{
        0_actual_start
        1_cycle_index 2_log_queue_size
        3_plan_task_count 4_plan_event_count
        5_utime 6_stime 7_dump_time 8_duration
        9_total_allocated_objects
        10_minor 11_major
        12_live_object_count
        13_oob_removed
        14_gc_total_time
    }
    # rubocop:disable Lint/NestedPercentLiteral
    # Starts at 1_cycle_index. 0_actual_start is formatted with strftime
    formatting = %w{
        %i %i
        %i %i
        %.3f %.3f %.3f %.3f
        %i
        %i %i
        %i
        %i
        %.3f
    }
    # rubocop:enable Lint/NestedPercentLiteral
    formatting = formatting.join(",")

    puts header.join(",")
    index.each do |info|
        gc = info[:gc]
        oob_gc = info[:pre_oob_gc] || gc
        start_sec, start_usec = info[:start]
        start = Time.at(start_sec, start_usec)

        formatted_fields =
            format(
                formatting,
                *info.values_at(
                    :cycle_index, :log_queue_size,
                    :plan_task_count, :plan_event_count,
                    :utime, :stime, :dump_time, :end
                ),
                *gc.values_at(
                    :total_allocated_objects,
                    :minor_gc_count, :major_gc_count
                ),
                gc[:total_allocated_objects] - gc[:total_freed_objects],
                gc[:total_freed_objects] - oob_gc[:total_freed_objects],
                info[:gc_total_time] || 0
            )

        absolute_start_s =
            (start + info[:actual_start])
            .strftime("%H:%M:%S.%3N")
        io.puts "#{absolute_start_s} #{formatted_fields}"
    end

    exit(0)
end

#timepoints(file = nil) ⇒ Object 



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

def timepoints(file = nil)
    file = handle_file_argument(file)

    require "roby/droby/logfile/reader"
    require "roby/droby/timepoints"
    require "roby/droby/timepoints_ctf"
    require "roby/cli/log/flamegraph_renderer"

    stream = Roby::DRoby::Logfile::Reader.open(file)

    if options[:raw]
        current_context = {}
        while data = stream.load_one_cycle
            data.each_slice(4) do |m, sec, usec, args|
                thread_id, thread_name, timepoint_name = *args
                path = (current_context[thread_id] ||= [thread_name])

                case m
                when :timepoint
                    puts "#{Roby.format_time(Time.at(sec, usec))} "\
                         "#{path.join('/')}/#{timepoint_name}"
                when :timepoint_group_start
                    puts "#{Roby.format_time(Time.at(sec, usec))} "\
                         "#{path.join('/')}/#{timepoint_name} {"
                    path.push timepoint_name
                when :timepoint_group_end
                    path.pop
                    puts "#{Roby.format_time(Time.at(sec, usec))} "\
                         "#{path.join('/')}/#{timepoint_name} }"
                end
            end
        end
        return
    end

    analyzer = Roby::DRoby::Timepoints::Analysis.new
    if options[:ctf]
        analyzer = Roby::DRoby::Timepoints::CTF.new
    else
        analyzer = Roby::DRoby::Timepoints::Analysis.new
    end
    while data = stream.load_one_cycle
        data.each_slice(4) do |m, sec, usec, args|
            case m
            when :timepoint
                analyzer.add Time.at(sec, usec), *args
            when :timepoint_group_start
                analyzer.group_start Time.at(sec, usec), *args
            when :timepoint_group_end
                analyzer.group_end Time.at(sec, usec), *args
            end
        end
    end

    if options[:ctf]
        path = Pathname.new(file).expand_path.sub_ext(".ctf")
        path.mkpath
        puts "saving in #{path}"
        analyzer.save(path)
    elsif options[:flamegraph]
        graph = analyzer.flamegraph
        graph = graph.map do |name, duration|
            [name, (duration * 1000).round]
        end
        File.open(options[:flamegraph], "w") do |io|
            io.write FlamegraphRenderer.new(graph).graph_html
        end
    else
        puts analyzer.format
    end
    exit 0
end

#upgrade_format(file) ⇒ Object 



34
35
36
37
 
# File 'lib/roby/cli/log.rb', line 34

def upgrade_format(file)
    require "roby/log/upgrade"
    Roby::Log::Upgrade.to_new_format(file)
end