diff options
Diffstat (limited to 'scripts')
| -rwxr-xr-x | scripts/logextract.py | 367 |
1 files changed, 216 insertions, 151 deletions
diff --git a/scripts/logextract.py b/scripts/logextract.py index 5d86cdce..937c68ec 100755 --- a/scripts/logextract.py +++ b/scripts/logextract.py @@ -148,22 +148,69 @@ class TMCUartHelper: # Shutdown extraction ###################################################################### -stats_seq_s = r" send_seq=(?P<sseq>[0-9]+) receive_seq=(?P<rseq>[0-9]+) " +def add_high_bits(val, ref, mask): + half = (mask + 1) // 2 + return ref + ((val - (ref & mask) + half) & mask) - half + count_s = r"(?P<count>[0-9]+)" time_s = r"(?P<time>[0-9]+[.][0-9]+)" esttime_s = r"(?P<esttime>[0-9]+[.][0-9]+)" shortseq_s = r"(?P<shortseq>[0-9a-f])" -stats_r = re.compile(r"^Stats " + time_s + ": ") -serial_dump_r = re.compile(r"^Dumping serial stats: .*" + stats_seq_s) -send_dump_r = re.compile(r"^Dumping send queue " + count_s + " messages$") sent_r = re.compile(r"^Sent " + count_s + " " + esttime_s + " " + time_s + " [0-9]+: seq: 1" + shortseq_s + ",") -receive_dump_r = re.compile(r"^Dumping receive queue " + count_s + " messages$") + +# MCU "Sent" shutdown message parsing +class MCUSentStream: + def __init__(self, mcu, count): + self.mcu = mcu + self.sent_stream = [] + self.send_count = count + def parse_line(self, line_num, line): + m = sent_r.match(line) + if m is not None: + shortseq = int(m.group('shortseq'), 16) + seq = (self.mcu.shutdown_seq + int(m.group('count')) + - self.send_count) + seq = add_high_bits(shortseq, seq, 0xf) + ts = float(m.group('time')) + esttime = float(m.group('esttime')) + self.mcu.sent_time_to_seq[(esttime, seq & 0xf)] = seq + self.mcu.sent_seq_to_time[seq] = ts + line = self.mcu.annotate(line, seq, ts) + self.sent_stream.append((ts, line_num, line)) + return True, None + return self.mcu.parse_line(line_num, line) + def get_lines(self): + return self.sent_stream + receive_r = re.compile(r"^Receive: " + count_s + " " + time_s + " " + esttime_s - + " [0-9]+: seq: 1" + shortseq_s + ",") -gcode_r = re.compile(r"^Read " + time_s + r": (?P<gcode>['\"].*)$") -gcode_state_r = re.compile(r"^gcode state: ") -varlist_split_r = re.compile(r"([^ ]+)=") + + " [0-9]+: seq: 1" + shortseq_s + ",") + +# MCU "Receive" shutdown message parsing +class MCUReceiveStream: + def __init__(self, mcu): + self.mcu = mcu + self.receive_stream = [] + def parse_line(self, line_num, line): + m = receive_r.match(line) + if m is not None: + shortseq = int(m.group('shortseq'), 16) + ts = float(m.group('time')) + esttime = float(m.group('esttime')) + seq = self.mcu.sent_time_to_seq.get((esttime, (shortseq - 1) & 0xf)) + if seq is not None: + self.mcu.receive_seq_to_time[seq + 1] = ts + line = self.mcu.annotate(line, seq, ts) + self.receive_stream.append((ts, line_num, line)) + return True, None + return self.mcu.parse_line(line_num, line) + def get_lines(self): + return self.receive_stream + +stats_seq_s = r" send_seq=(?P<sseq>[0-9]+) receive_seq=(?P<rseq>[0-9]+) " +serial_dump_r = re.compile(r"^Dumping serial stats: .*" + stats_seq_s) +send_dump_r = re.compile(r"^Dumping send queue " + count_s + " messages$") +receive_dump_r = re.compile(r"^Dumping receive queue " + count_s + " messages$") clock_r = re.compile(r"^clocksync state: .* clock_est=\((?P<st>[^ ]+)" + r" (?P<sc>[0-9]+) (?P<f>[^ ]+)\)") repl_seq_r = re.compile(r": seq: 1" + shortseq_s) @@ -171,48 +218,65 @@ repl_clock_r = re.compile(r"clock=(?P<clock>[0-9]+)(?: |$)") repl_uart_r = re.compile(r"tmcuart_(?:response|send) oid=[0-9]+" + r" (?:read|write)=(?P<msg>(?:'[^']*'" + r'|"[^"]*"))(?: |$)') -mcu_r = re.compile(r"MCU '(?P<mcu>[^']+)' (is_)?shutdown: (?P<reason>.*)$") -def add_high_bits(val, ref, mask): - half = (mask + 1) // 2 - return ref + ((val - (ref & mask) + half) & mask) - half +# MCU shutdown message parsing +class MCUStream: + def __init__(self, name): + self.name = name + self.sent_time_to_seq = {} + self.sent_seq_to_time = {} + self.receive_seq_to_time = {} + self.clock_est = 0., 0., 1. + self.shutdown_seq = None + def trans_clock(self, clock, ts): + sample_time, sample_clock, freq = self.clock_est + exp_clock = int(sample_clock + (ts - sample_time) * freq) + ext_clock = add_high_bits(clock, exp_clock, 0xffffffff) + return sample_time + (ext_clock - sample_clock) / freq + def annotate(self, line, seq, ts): + if seq is not None: + line = repl_seq_r.sub(r"\g<0>(%d)" % (seq,), line) + def clock_update(m): + return m.group(0).rstrip() + "(%.6f) " % ( + self.trans_clock(int(m.group('clock')), ts),) + line = repl_clock_r.sub(clock_update, line) + def uart_update(m): + msg = TMCUartHelper().parse_msg(ast.literal_eval(m.group('msg'))) + return m.group(0).rstrip() + "%s " % (msg,) + line = repl_uart_r.sub(uart_update, line) + if self.name != 'mcu': + line = "mcu '%s': %s" % (self.name, line) + return line + def parse_line(self, line_num, line): + m = clock_r.match(line) + if m is not None: + st = float(m.group('st')) + sc = int(m.group('sc')) + f = float(m.group('f')) + self.clock_est = (st, sc, f) + m = serial_dump_r.match(line) + if m is not None: + self.shutdown_seq = int(m.group('rseq')) + m = send_dump_r.match(line) + if m is not None: + return True, MCUSentStream(self, int(m.group('count'))) + m = receive_dump_r.match(line) + if m is not None: + return True, MCUReceiveStream(self) + return False, None + def get_lines(self): + return [] -class GatherShutdown: - class mcu_info: - def __init__(self, name): - self.name = name - self.sent_stream = [] - self.receive_stream = [] - self.sent_stream = [] - self.receive_stream = [] - self.sent_time_to_seq = {} - self.sent_seq_to_time = {} - self.receive_seq_to_time = {} - self.clock_est = 0., 0., 1. - self.shutdown_seq = None - self.send_count = self.receive_count = 0 - def __init__(self, configs, line_num, recent_lines, logname): - self.shutdown_line_num = line_num - self.filename = "%s.shutdown%05d" % (logname, line_num) - self.gcode_filename = "%s.gcode%05d" % (logname, line_num) - self.comments = [] - if configs: - configs_by_id = {c.config_num: c for c in configs.values()} - config = configs_by_id[max(configs_by_id.keys())] - config.add_comment(format_comment(line_num, recent_lines[-1][1])) - self.comments.append("# config %s" % (config.filename,)) - self.stats_stream = [] +gcode_cmd_r = re.compile(r"^Read " + time_s + r": (?P<gcode>['\"].*)$") +varlist_split_r = re.compile(r"([^ ]+)=") + +# G-Code shutdown message parsing +class GCodeStream: + def __init__(self, shutdown_line_num, logname): self.gcode_stream = [] + self.gcode_commands = [] self.gcode_state = '' - self.mcus = {} - self.mcu = None - self.first_stat_time = self.last_stat_time = None - for line_num, line in recent_lines: - self.parse_line(line_num, line) - self.first_stat_time = self.last_stat_time - def add_comment(self, comment): - if comment is not None: - self.comments.append(comment) + self.gcode_filename = "%s.gcode%05d" % (logname, shutdown_line_num) def extract_params(self, line): parts = varlist_split_r.split(line) try: @@ -243,6 +307,40 @@ class GatherShutdown: out.append('M221 S%f' % (kv['extrude_factor'] * 100.,)) out.extend(['; End of state restore', '', '']) self.gcode_state = '\n'.join(out) + def parse_line(self, line_num, line): + m = gcode_cmd_r.match(line) + if m is not None: + ts = float(m.group('time')) + self.gcode_stream.append((ts, line_num, line)) + self.gcode_commands.append(m.group('gcode')) + return True, None + return False, None + def get_lines(self): + # Produce output gcode stream + if self.gcode_stream: + data = [ast.literal_eval(gc) for gc in self.gcode_commands] + f = open(self.gcode_filename, 'wb') + f.write(self.gcode_state + ''.join(data)) + f.close() + return self.gcode_stream + +stats_r = re.compile(r"^Stats " + time_s + ": ") +mcu_r = re.compile(r"MCU '(?P<mcu>[^']+)' (is_)?shutdown: (?P<reason>.*)$") +gcode_r = re.compile(r"Dumping gcode input " + count_s + r" blocks$") +gcode_state_r = re.compile(r"^gcode state: ") + +# Stats message parsing and high-level message dispatch +class StatsStream: + def __init__(self, shutdown_line_num, logname): + self.shutdown_line_num = shutdown_line_num + self.gcode_stream = GCodeStream(shutdown_line_num, logname) + self.mcus = {} + self.first_stat_time = self.last_stat_time = None + self.stats_stream = [] + def reset_first_stat_time(self): + self.first_stat_time = self.last_stat_time + def get_stat_times(self): + return self.first_stat_time, self.last_stat_time def check_stats_seq(self, ts, line): # Parse stats parts = line.split() @@ -256,83 +354,19 @@ class GatherShutdown: keyparts[mcu + name] = val min_ts = 0 max_ts = 999999999999 - for mcu, info in self.mcus.items(): - sname = '%s:send_seq' % (mcu,) - rname = '%s:receive_seq' % (mcu,) + for mcu_name, mcu in self.mcus.items(): + sname = '%s:send_seq' % (mcu_name,) + rname = '%s:receive_seq' % (mcu_name,) if sname not in keyparts: continue sseq = int(keyparts[sname]) rseq = int(keyparts[rname]) - min_ts = max(min_ts, info.sent_seq_to_time.get(sseq-1, 0), - info.receive_seq_to_time.get(rseq, 0)) - max_ts = min(max_ts, info.sent_seq_to_time.get(sseq, 999999999999), - info.receive_seq_to_time.get(rseq+1, 999999999999)) + min_ts = max(min_ts, mcu.sent_seq_to_time.get(sseq-1, 0), + mcu.receive_seq_to_time.get(rseq, 0)) + max_ts = min(max_ts, mcu.sent_seq_to_time.get(sseq, 999999999999), + mcu.receive_seq_to_time.get(rseq+1, 999999999999)) return min(max(ts, min_ts + 0.00000001), max_ts - 0.00000001) - def trans_clock(self, clock, ts): - sample_time, sample_clock, freq = self.mcu.clock_est - exp_clock = int(sample_clock + (ts - sample_time) * freq) - ext_clock = add_high_bits(clock, exp_clock, 0xffffffff) - return sample_time + (ext_clock - sample_clock) / freq - def annotate(self, line, mcu_name, seq, ts): - if seq is not None: - line = repl_seq_r.sub(r"\g<0>(%d)" % (seq,), line) - def clock_update(m): - return m.group(0).rstrip() + "(%.6f) " % ( - self.trans_clock(int(m.group('clock')), ts),) - line = repl_clock_r.sub(clock_update, line) - def uart_update(m): - msg = TMCUartHelper().parse_msg(ast.literal_eval(m.group('msg'))) - return m.group(0).rstrip() + "%s " % (msg,) - line = repl_uart_r.sub(uart_update, line) - if mcu_name != 'mcu': - line = "mcu '%s': %s" % (mcu_name, line) - return line - def add_line(self, line_num, line): - self.parse_line(line_num, line) - if (self.first_stat_time is not None - and self.last_stat_time > self.first_stat_time + 5.): - self.finalize() - return False - if (line.startswith('Git version') - or line.startswith('Start printer at') - or line == '===== Config file ====='): - self.finalize() - return False - return True def parse_line(self, line_num, line): - m = sent_r.match(line) - if m is not None: - shortseq = int(m.group('shortseq'), 16) - seq = (self.mcu.shutdown_seq + int(m.group('count')) - - self.mcu.send_count) - seq = add_high_bits(shortseq, seq, 0xf) - ts = float(m.group('time')) - esttime = float(m.group('esttime')) - self.mcu.sent_time_to_seq[(esttime, seq & 0xf)] = seq - self.mcu.sent_seq_to_time[seq] = ts - line = self.annotate(line, self.mcu.name, seq, ts) - self.mcu.sent_stream.append((ts, line_num, line)) - return - m = receive_r.match(line) - if m is not None: - shortseq = int(m.group('shortseq'), 16) - ts = float(m.group('time')) - esttime = float(m.group('esttime')) - seq = self.mcu.sent_time_to_seq.get((esttime, (shortseq - 1) & 0xf)) - if seq is not None: - self.mcu.receive_seq_to_time[seq + 1] = ts - line = self.annotate(line, self.mcu.name, seq, ts) - self.mcu.receive_stream.append((ts, line_num, line)) - return - m = gcode_r.match(line) - if m is not None: - ts = float(m.group('time')) - self.gcode_stream.append((ts, line_num, line, m.group('gcode'))) - return - m = gcode_state_r.match(line) - if m is not None: - self.handle_gcode_state(line) - return m = stats_r.match(line) if m is not None: ts = float(m.group('time')) @@ -340,35 +374,32 @@ class GatherShutdown: if self.first_stat_time is None: self.first_stat_time = ts self.stats_stream.append((ts, line_num, line)) - return + return True, None + self.stats_stream.append((None, line_num, line)) m = mcu_r.match(line) if m is not None: - mcu = m.group('mcu') - self.mcu = self.mcus.setdefault(mcu, self.mcu_info(mcu)) - m = clock_r.match(line) - if m is not None: - st = float(m.group('st')) - sc = int(m.group('sc')) - f = float(m.group('f')) - self.mcu.clock_est = (st, sc, f) - m = serial_dump_r.match(line) - if m is not None: - self.mcu.shutdown_seq = int(m.group('rseq')) - m = send_dump_r.match(line) + mcu_name = m.group('mcu') + mcu_stream = MCUStream(mcu_name) + self.mcus[mcu_name] = mcu_stream + return True, mcu_stream + m = gcode_r.match(line) if m is not None: - self.mcu.send_count = int(m.group('count')) - m = receive_dump_r.match(line) + return True, self.gcode_stream + m = gcode_state_r.match(line) if m is not None: - self.mcu.receive_count = int(m.group('count')) - self.stats_stream.append((None, line_num, line)) - def finalize(self): + self.gcode_stream.handle_gcode_state(line) + return True, None + return False, None + def get_lines(self): # Ignore old stats - stream_ts = [i[0] for mcu in self.mcus.values() - for i in mcu.sent_stream + mcu.receive_stream] - if not stream_ts: - return - min_stream_ts = min(stream_ts) - max_stream_ts = max(stream_ts) + all_ts = [] + for mcu_name, mcu in self.mcus.items(): + all_ts.extend(mcu.sent_seq_to_time.values()) + all_ts.extend(mcu.receive_seq_to_time.values()) + if not all_ts: + return [] + min_stream_ts = min(all_ts) + max_stream_ts = max(all_ts) for i, info in enumerate(self.stats_stream): if info[0] is not None and info[0] >= min_stream_ts - 5.: del self.stats_stream[:i] @@ -382,10 +413,50 @@ class GatherShutdown: and last_ts <= max_stream_ts): last_ts = max_stream_ts + 0.00000001 self.stats_stream[i] = (last_ts, line_num, line) + return self.stats_stream + +# Main handler for creating shutdown diagnostics file +class GatherShutdown: + def __init__(self, configs, line_num, recent_lines, logname): + self.filename = "%s.shutdown%05d" % (logname, line_num) + self.comments = [] + if configs: + configs_by_id = {c.config_num: c for c in configs.values()} + config = configs_by_id[max(configs_by_id.keys())] + config.add_comment(format_comment(line_num, recent_lines[-1][1])) + self.comments.append("# config %s" % (config.filename,)) + self.stats_stream = StatsStream(line_num, logname) + self.active_streams = [self.stats_stream] + self.all_streams = list(self.active_streams) + for line_num, line in recent_lines: + self.parse_line(line_num, line) + self.stats_stream.reset_first_stat_time() + def add_comment(self, comment): + if comment is not None: + self.comments.append(comment) + def add_line(self, line_num, line): + self.parse_line(line_num, line) + first, last = self.stats_stream.get_stat_times() + if first is not None and last > first + 5.: + self.finalize() + return False + if (line.startswith('Git version') + or line.startswith('Start printer at') + or line == '===== Config file ====='): + self.finalize() + return False + return True + def parse_line(self, line_num, line): + for s in self.active_streams: + did_parse, new_stream = s.parse_line(line_num, line) + if did_parse: + if new_stream is not None: + self.all_streams.append(new_stream) + self.active_streams = [new_stream, self.stats_stream] + break + def finalize(self): # Make sure no timestamp goes backwards - streams = ([self.stats_stream, self.gcode_stream] + - [mcu.sent_stream for mcu in self.mcus.values()] + - [mcu.receive_stream for mcu in self.mcus.values()]) + streams = [p.get_lines() for p in self.all_streams] for s in streams: for i in range(1, len(s)): if s[i-1][0] > s[i][0]: @@ -397,12 +468,6 @@ class GatherShutdown: f = open(self.filename, 'wb') f.write('\n'.join(self.comments + out)) f.close() - # Produce output gcode stream - if self.gcode_stream: - data = [ast.literal_eval(gc[3]) for gc in self.gcode_stream] - f = open(self.gcode_filename, 'wb') - f.write(self.gcode_state + ''.join(data)) - f.close() ###################################################################### |