|
| 1 | +# Copyright (C) 2016-2018 Kevin O'Connor <kevin@koconnor.net> |
| 2 | + |
| 3 | +import flask |
| 4 | +import optparse, datetime |
| 5 | + |
| 6 | +class KlipperLogAnalyzer(): |
| 7 | + MAXBANDWIDTH=25000. |
| 8 | + MAXBUFFER=2. |
| 9 | + STATS_INTERVAL=5. |
| 10 | + TASK_MAX=0.0025 |
| 11 | + APPLY_PREFIX = ['mcu_awake', 'mcu_task_avg', 'mcu_task_stddev', 'bytes_write', |
| 12 | + 'bytes_read', 'bytes_retransmit', 'freq', 'adj'] |
| 13 | + |
| 14 | + def __init__(self, log_file): |
| 15 | + self.log_file = log_file |
| 16 | + |
| 17 | + def analyze(self): |
| 18 | + data = self.parse_log(self.log_file, None) |
| 19 | + if not data: |
| 20 | + result = dict(error= "Couldn't parse \"{}\"".format(self.log_file)) |
| 21 | + else: |
| 22 | + result = self.plot_mcu(data, self.MAXBANDWIDTH) |
| 23 | + #if options.frequency: |
| 24 | + # plot_frequency(data, outname, options.mcu) |
| 25 | + # return |
| 26 | + return result |
| 27 | + |
| 28 | + def parse_log(self, logname, mcu): |
| 29 | + if mcu is None: |
| 30 | + mcu = "mcu" |
| 31 | + mcu_prefix = mcu + ":" |
| 32 | + apply_prefix = { p: 1 for p in self.APPLY_PREFIX } |
| 33 | + |
| 34 | + f = open(logname, 'rb') |
| 35 | + out = [] |
| 36 | + |
| 37 | + for line in f: |
| 38 | + parts = line.split() |
| 39 | + if not parts or parts[0] not in ('Stats', 'INFO:root:Stats'): |
| 40 | + #if parts and parts[0] == 'INFO:root:shutdown:': |
| 41 | + # break |
| 42 | + continue |
| 43 | + prefix = "" |
| 44 | + keyparts = {} |
| 45 | + for p in parts[2:]: |
| 46 | + if '=' not in p: |
| 47 | + prefix = p |
| 48 | + if prefix == mcu_prefix: |
| 49 | + prefix = '' |
| 50 | + continue |
| 51 | + name, val = p.split('=', 1) |
| 52 | + if name in apply_prefix: |
| 53 | + name = prefix + name |
| 54 | + keyparts[name] = val |
| 55 | + if keyparts.get('bytes_write', '0') == '0': |
| 56 | + continue |
| 57 | + keyparts['#sampletime'] = float(parts[1][:-1]) |
| 58 | + out.append(keyparts) |
| 59 | + f.close() |
| 60 | + return out |
| 61 | + |
| 62 | + def find_print_restarts(self, data): |
| 63 | + runoff_samples = {} |
| 64 | + last_runoff_start = last_buffer_time = last_sampletime = 0. |
| 65 | + last_print_stall = 0 |
| 66 | + for d in reversed(data): |
| 67 | + # Check for buffer runoff |
| 68 | + sampletime = d['#sampletime'] |
| 69 | + buffer_time = float(d.get('buffer_time', 0.)) |
| 70 | + if (last_runoff_start and last_sampletime - sampletime < 5 |
| 71 | + and buffer_time > last_buffer_time): |
| 72 | + runoff_samples[last_runoff_start][1].append(sampletime) |
| 73 | + elif buffer_time < 1.: |
| 74 | + last_runoff_start = sampletime |
| 75 | + runoff_samples[last_runoff_start] = [False, [sampletime]] |
| 76 | + else: |
| 77 | + last_runoff_start = 0. |
| 78 | + last_buffer_time = buffer_time |
| 79 | + last_sampletime = sampletime |
| 80 | + # Check for print stall |
| 81 | + print_stall = int(d['print_stall']) |
| 82 | + if print_stall < last_print_stall: |
| 83 | + if last_runoff_start: |
| 84 | + runoff_samples[last_runoff_start][0] = True |
| 85 | + last_print_stall = print_stall |
| 86 | + sample_resets = {sampletime: 1 for stall, samples in runoff_samples.values() |
| 87 | + for sampletime in samples if not stall} |
| 88 | + return sample_resets |
| 89 | + |
| 90 | + def plot_mcu(self, data, maxbw): |
| 91 | + # Generate data for plot |
| 92 | + basetime = lasttime = data[0]['#sampletime'] |
| 93 | + lastbw = float(data[0]['bytes_write']) + float(data[0]['bytes_retransmit']) |
| 94 | + sample_resets = self.find_print_restarts(data) |
| 95 | + times = [] |
| 96 | + bwdeltas = [] |
| 97 | + loads = [] |
| 98 | + awake = [] |
| 99 | + hostbuffers = [] |
| 100 | + for d in data: |
| 101 | + st = d['#sampletime'] |
| 102 | + timedelta = st - lasttime |
| 103 | + if timedelta <= 0.: |
| 104 | + continue |
| 105 | + bw = float(d['bytes_write']) + float(d['bytes_retransmit']) |
| 106 | + if bw < lastbw: |
| 107 | + lastbw = bw |
| 108 | + continue |
| 109 | + load = float(d['mcu_task_avg']) + 3*float(d['mcu_task_stddev']) |
| 110 | + if st - basetime < 15.: |
| 111 | + load = 0. |
| 112 | + pt = float(d['print_time']) |
| 113 | + hb = float(d['buffer_time']) |
| 114 | + if hb >= self.MAXBUFFER or st in sample_resets: |
| 115 | + hb = 0. |
| 116 | + else: |
| 117 | + hb = 100. * (self.MAXBUFFER - hb) / self.MAXBUFFER |
| 118 | + hostbuffers.append(hb) |
| 119 | + #times.append(datetime.datetime.utcfromtimestamp(st)) |
| 120 | + times.append(st) |
| 121 | + bwdeltas.append(100. * (bw - lastbw) / (maxbw * timedelta)) |
| 122 | + loads.append(100. * load / self.TASK_MAX) |
| 123 | + awake.append(100. * float(d.get('mcu_awake', 0.)) / self.STATS_INTERVAL) |
| 124 | + lasttime = st |
| 125 | + lastbw = bw |
| 126 | + |
| 127 | + result = dict( |
| 128 | + times= times, |
| 129 | + bwdeltas= bwdeltas, |
| 130 | + loads= loads, |
| 131 | + awake= awake, |
| 132 | + buffers= hostbuffers |
| 133 | + ) |
| 134 | + return result |
| 135 | + |
| 136 | + def plot_frequency(self, data, mcu): |
| 137 | + all_keys = {} |
| 138 | + for d in data: |
| 139 | + all_keys.update(d) |
| 140 | + one_mcu = mcu is not None |
| 141 | + graph_keys = { key: ([], []) for key in all_keys |
| 142 | + if (key in ("freq", "adj") or (not one_mcu and ( |
| 143 | + key.endswith(":freq") or key.endswith(":adj")))) } |
| 144 | + basetime = lasttime = data[0]['#sampletime'] |
| 145 | + for d in data: |
| 146 | + st = d['#sampletime'] |
| 147 | + for key, (times, values) in graph_keys.items(): |
| 148 | + val = d.get(key) |
| 149 | + if val not in (None, '0', '1'): |
| 150 | + times.append(st) |
| 151 | + values.append(float(val)) |
0 commit comments