| 
									
										
										
										
											2017-06-27 20:23:30 -04:00
										 |  |  | #!/usr/bin/env python2 | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | # Script to parse a logging file, extract the stats, and graph them | 
					
						
							|  |  |  | # | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | # Copyright (C) 2016-2019  Kevin O'Connor <kevin@koconnor.net> | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | # | 
					
						
							|  |  |  | # This file may be distributed under the terms of the GNU GPLv3 license. | 
					
						
							|  |  |  | import optparse, datetime | 
					
						
							| 
									
										
										
										
											2017-12-30 18:20:53 -05:00
										 |  |  | import matplotlib | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | 
 | 
					
						
							|  |  |  | MAXBANDWIDTH=25000. | 
					
						
							| 
									
										
										
										
											2017-02-11 14:43:36 -05:00
										 |  |  | MAXBUFFER=2. | 
					
						
							| 
									
										
										
										
											2017-07-19 14:13:35 -04:00
										 |  |  | STATS_INTERVAL=5. | 
					
						
							| 
									
										
										
										
											2017-08-09 18:52:13 -04:00
										 |  |  | TASK_MAX=0.0025 | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2019-01-13 22:00:08 -05:00
										 |  |  | APPLY_PREFIX = [ | 
					
						
							|  |  |  |     'mcu_awake', 'mcu_task_avg', 'mcu_task_stddev', 'bytes_write', | 
					
						
							|  |  |  |     'bytes_read', 'bytes_retransmit', 'freq', 'adj', | 
					
						
							|  |  |  |     'target', 'temp', 'pwm' | 
					
						
							|  |  |  | ] | 
					
						
							| 
									
										
										
										
											2018-02-03 18:43:52 -05:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  | def parse_log(logname, mcu): | 
					
						
							|  |  |  |     if mcu is None: | 
					
						
							|  |  |  |         mcu = "mcu" | 
					
						
							|  |  |  |     mcu_prefix = mcu + ":" | 
					
						
							| 
									
										
										
										
											2018-02-03 18:43:52 -05:00
										 |  |  |     apply_prefix = { p: 1 for p in APPLY_PREFIX } | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     f = open(logname, 'rb') | 
					
						
							|  |  |  |     out = [] | 
					
						
							|  |  |  |     for line in f: | 
					
						
							|  |  |  |         parts = line.split() | 
					
						
							| 
									
										
										
										
											2016-12-06 11:10:52 -05:00
										 |  |  |         if not parts or parts[0] not in ('Stats', 'INFO:root:Stats'): | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |             #if parts and parts[0] == 'INFO:root:shutdown:': | 
					
						
							|  |  |  |             #    break | 
					
						
							|  |  |  |             continue | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |         prefix = "" | 
					
						
							|  |  |  |         keyparts = {} | 
					
						
							|  |  |  |         for p in parts[2:]: | 
					
						
							| 
									
										
										
										
											2018-05-23 18:19:50 -04:00
										 |  |  |             if '=' not in p: | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |                 prefix = p | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  |                 if prefix == mcu_prefix: | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |                     prefix = '' | 
					
						
							|  |  |  |                 continue | 
					
						
							|  |  |  |             name, val = p.split('=', 1) | 
					
						
							| 
									
										
										
										
											2018-02-03 18:43:52 -05:00
										 |  |  |             if name in apply_prefix: | 
					
						
							|  |  |  |                 name = prefix + name | 
					
						
							|  |  |  |             keyparts[name] = val | 
					
						
							| 
									
										
										
										
											2018-11-26 17:37:04 -05:00
										 |  |  |         if 'print_time' not in keyparts: | 
					
						
							| 
									
										
										
										
											2016-12-06 11:10:52 -05:00
										 |  |  |             continue | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |         keyparts['#sampletime'] = float(parts[1][:-1]) | 
					
						
							|  |  |  |         out.append(keyparts) | 
					
						
							|  |  |  |     f.close() | 
					
						
							|  |  |  |     return out | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | def setup_matplotlib(output_to_file): | 
					
						
							| 
									
										
										
										
											2019-11-10 10:18:31 -05:00
										 |  |  |     global matplotlib | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     if output_to_file: | 
					
						
							|  |  |  |         matplotlib.use('Agg') | 
					
						
							|  |  |  |     import matplotlib.pyplot, matplotlib.dates, matplotlib.font_manager | 
					
						
							|  |  |  |     import matplotlib.ticker | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2017-02-01 11:21:01 -05:00
										 |  |  | def find_print_restarts(data): | 
					
						
							| 
									
										
										
										
											2018-01-14 10:13:09 -05:00
										 |  |  |     runoff_samples = {} | 
					
						
							|  |  |  |     last_runoff_start = last_buffer_time = last_sampletime = 0. | 
					
						
							|  |  |  |     last_print_stall = 0 | 
					
						
							|  |  |  |     for d in reversed(data): | 
					
						
							|  |  |  |         # Check for buffer runoff | 
					
						
							|  |  |  |         sampletime = d['#sampletime'] | 
					
						
							| 
									
										
										
										
											2017-10-29 20:30:36 -04:00
										 |  |  |         buffer_time = float(d.get('buffer_time', 0.)) | 
					
						
							| 
									
										
										
										
											2018-01-28 10:23:44 -05:00
										 |  |  |         if (last_runoff_start and last_sampletime - sampletime < 5 | 
					
						
							|  |  |  |             and buffer_time > last_buffer_time): | 
					
						
							| 
									
										
										
										
											2018-01-14 10:13:09 -05:00
										 |  |  |             runoff_samples[last_runoff_start][1].append(sampletime) | 
					
						
							| 
									
										
										
										
											2018-01-28 10:23:44 -05:00
										 |  |  |         elif buffer_time < 1.: | 
					
						
							|  |  |  |             last_runoff_start = sampletime | 
					
						
							|  |  |  |             runoff_samples[last_runoff_start] = [False, [sampletime]] | 
					
						
							| 
									
										
										
										
											2018-01-14 10:13:09 -05:00
										 |  |  |         else: | 
					
						
							|  |  |  |             last_runoff_start = 0. | 
					
						
							|  |  |  |         last_buffer_time = buffer_time | 
					
						
							|  |  |  |         last_sampletime = sampletime | 
					
						
							|  |  |  |         # Check for print stall | 
					
						
							|  |  |  |         print_stall = int(d['print_stall']) | 
					
						
							|  |  |  |         if print_stall < last_print_stall: | 
					
						
							|  |  |  |             if last_runoff_start: | 
					
						
							|  |  |  |                 runoff_samples[last_runoff_start][0] = True | 
					
						
							|  |  |  |         last_print_stall = print_stall | 
					
						
							|  |  |  |     sample_resets = {sampletime: 1 for stall, samples in runoff_samples.values() | 
					
						
							|  |  |  |                      for sampletime in samples if not stall} | 
					
						
							| 
									
										
										
										
											2017-02-01 11:21:01 -05:00
										 |  |  |     return sample_resets | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | def plot_mcu(data, maxbw): | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     # Generate data for plot | 
					
						
							|  |  |  |     basetime = lasttime = data[0]['#sampletime'] | 
					
						
							|  |  |  |     lastbw = float(data[0]['bytes_write']) + float(data[0]['bytes_retransmit']) | 
					
						
							| 
									
										
										
										
											2017-02-01 11:21:01 -05:00
										 |  |  |     sample_resets = find_print_restarts(data) | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     times = [] | 
					
						
							|  |  |  |     bwdeltas = [] | 
					
						
							|  |  |  |     loads = [] | 
					
						
							| 
									
										
										
										
											2017-07-19 14:13:35 -04:00
										 |  |  |     awake = [] | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     hostbuffers = [] | 
					
						
							|  |  |  |     for d in data: | 
					
						
							|  |  |  |         st = d['#sampletime'] | 
					
						
							|  |  |  |         timedelta = st - lasttime | 
					
						
							|  |  |  |         if timedelta <= 0.: | 
					
						
							|  |  |  |             continue | 
					
						
							|  |  |  |         bw = float(d['bytes_write']) + float(d['bytes_retransmit']) | 
					
						
							| 
									
										
										
										
											2016-12-06 11:10:52 -05:00
										 |  |  |         if bw < lastbw: | 
					
						
							|  |  |  |             lastbw = bw | 
					
						
							|  |  |  |             continue | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |         load = float(d['mcu_task_avg']) + 3*float(d['mcu_task_stddev']) | 
					
						
							|  |  |  |         if st - basetime < 15.: | 
					
						
							|  |  |  |             load = 0. | 
					
						
							|  |  |  |         pt = float(d['print_time']) | 
					
						
							|  |  |  |         hb = float(d['buffer_time']) | 
					
						
							| 
									
										
										
										
											2018-01-14 10:13:09 -05:00
										 |  |  |         if hb >= MAXBUFFER or st in sample_resets: | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |             hb = 0. | 
					
						
							|  |  |  |         else: | 
					
						
							|  |  |  |             hb = 100. * (MAXBUFFER - hb) / MAXBUFFER | 
					
						
							|  |  |  |         hostbuffers.append(hb) | 
					
						
							|  |  |  |         times.append(datetime.datetime.utcfromtimestamp(st)) | 
					
						
							|  |  |  |         bwdeltas.append(100. * (bw - lastbw) / (maxbw * timedelta)) | 
					
						
							| 
									
										
										
										
											2017-08-09 18:52:13 -04:00
										 |  |  |         loads.append(100. * load / TASK_MAX) | 
					
						
							| 
									
										
										
										
											2017-07-21 14:19:59 -04:00
										 |  |  |         awake.append(100. * float(d.get('mcu_awake', 0.)) / STATS_INTERVAL) | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |         lasttime = st | 
					
						
							|  |  |  |         lastbw = bw | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     # Build plot | 
					
						
							| 
									
										
										
										
											2017-12-30 18:20:53 -05:00
										 |  |  |     fig, ax1 = matplotlib.pyplot.subplots() | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     ax1.set_title("MCU bandwidth and load utilization") | 
					
						
							| 
									
										
										
										
											2017-04-11 13:40:25 -04:00
										 |  |  |     ax1.set_xlabel('Time') | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     ax1.set_ylabel('Usage (%)') | 
					
						
							| 
									
										
										
										
											2018-01-14 10:46:48 -05:00
										 |  |  |     ax1.plot_date(times, bwdeltas, 'g', label='Bandwidth', alpha=0.8) | 
					
						
							|  |  |  |     ax1.plot_date(times, loads, 'r', label='MCU load', alpha=0.8) | 
					
						
							|  |  |  |     ax1.plot_date(times, hostbuffers, 'c', label='Host buffer', alpha=0.8) | 
					
						
							|  |  |  |     ax1.plot_date(times, awake, 'y', label='Awake time', alpha=0.6) | 
					
						
							| 
									
										
										
										
											2017-12-30 18:24:46 -05:00
										 |  |  |     fontP = matplotlib.font_manager.FontProperties() | 
					
						
							|  |  |  |     fontP.set_size('x-small') | 
					
						
							|  |  |  |     ax1.legend(loc='best', prop=fontP) | 
					
						
							| 
									
										
										
										
											2017-12-30 18:20:53 -05:00
										 |  |  |     ax1.xaxis.set_major_formatter(matplotlib.dates.DateFormatter('%H:%M')) | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     ax1.grid(True) | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     return fig | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | def plot_frequency(data, mcu): | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |     all_keys = {} | 
					
						
							|  |  |  |     for d in data: | 
					
						
							|  |  |  |         all_keys.update(d) | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  |     one_mcu = mcu is not None | 
					
						
							|  |  |  |     graph_keys = { key: ([], []) for key in all_keys | 
					
						
							|  |  |  |                    if (key in ("freq", "adj") or (not one_mcu and ( | 
					
						
							|  |  |  |                            key.endswith(":freq") or key.endswith(":adj")))) } | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |     for d in data: | 
					
						
							|  |  |  |         st = datetime.datetime.utcfromtimestamp(d['#sampletime']) | 
					
						
							|  |  |  |         for key, (times, values) in graph_keys.items(): | 
					
						
							|  |  |  |             val = d.get(key) | 
					
						
							|  |  |  |             if val not in (None, '0', '1'): | 
					
						
							|  |  |  |                 times.append(st) | 
					
						
							|  |  |  |                 values.append(float(val)) | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     # Build plot | 
					
						
							|  |  |  |     fig, ax1 = matplotlib.pyplot.subplots() | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  |     if one_mcu: | 
					
						
							|  |  |  |         ax1.set_title("MCU '%s' frequency" % (mcu,)) | 
					
						
							|  |  |  |     else: | 
					
						
							|  |  |  |         ax1.set_title("MCU frequency") | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |     ax1.set_xlabel('Time') | 
					
						
							|  |  |  |     ax1.set_ylabel('Frequency') | 
					
						
							|  |  |  |     for key in sorted(graph_keys): | 
					
						
							|  |  |  |         times, values = graph_keys[key] | 
					
						
							|  |  |  |         ax1.plot_date(times, values, '.', label=key) | 
					
						
							|  |  |  |     fontP = matplotlib.font_manager.FontProperties() | 
					
						
							|  |  |  |     fontP.set_size('x-small') | 
					
						
							|  |  |  |     ax1.legend(loc='best', prop=fontP) | 
					
						
							|  |  |  |     ax1.xaxis.set_major_formatter(matplotlib.dates.DateFormatter('%H:%M')) | 
					
						
							|  |  |  |     ax1.yaxis.set_major_formatter(matplotlib.ticker.FormatStrFormatter('%d')) | 
					
						
							|  |  |  |     ax1.grid(True) | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     return fig | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | def plot_temperature(data, heater): | 
					
						
							| 
									
										
										
										
											2019-01-13 22:00:08 -05:00
										 |  |  |     temp_key = heater + ':' + 'temp' | 
					
						
							|  |  |  |     target_key = heater + ':' + 'target' | 
					
						
							|  |  |  |     pwm_key = heater + ':' + 'pwm' | 
					
						
							|  |  |  |     times = [] | 
					
						
							|  |  |  |     temps = [] | 
					
						
							|  |  |  |     targets = [] | 
					
						
							|  |  |  |     pwm = [] | 
					
						
							|  |  |  |     for d in data: | 
					
						
							|  |  |  |         temp = d.get(temp_key) | 
					
						
							|  |  |  |         if temp is None: | 
					
						
							|  |  |  |             continue | 
					
						
							|  |  |  |         times.append(datetime.datetime.utcfromtimestamp(d['#sampletime'])) | 
					
						
							|  |  |  |         temps.append(float(temp)) | 
					
						
							|  |  |  |         pwm.append(float(d[pwm_key])) | 
					
						
							|  |  |  |         targets.append(float(d[target_key])) | 
					
						
							|  |  |  |     # Build plot | 
					
						
							|  |  |  |     fig, ax1 = matplotlib.pyplot.subplots() | 
					
						
							|  |  |  |     ax1.set_title("Temperature of heater %s" % (heater,)) | 
					
						
							|  |  |  |     ax1.set_xlabel('Time') | 
					
						
							|  |  |  |     ax1.set_ylabel('Temperature') | 
					
						
							|  |  |  |     ax1.plot_date(times, temps, 'r', label='Measured temp', alpha=0.8) | 
					
						
							|  |  |  |     ax1.plot_date(times, targets, 'g', label='Target', alpha=0.8) | 
					
						
							|  |  |  |     ax2 = ax1.twinx() | 
					
						
							|  |  |  |     ax2.set_ylabel('pwm') | 
					
						
							|  |  |  |     ax2.plot_date(times, pwm, 'y', label='pwm', alpha=0.8) | 
					
						
							|  |  |  |     fontP = matplotlib.font_manager.FontProperties() | 
					
						
							|  |  |  |     fontP.set_size('x-small') | 
					
						
							|  |  |  |     ax1.legend(loc='best', prop=fontP) | 
					
						
							|  |  |  |     ax1.xaxis.set_major_formatter(matplotlib.dates.DateFormatter('%H:%M')) | 
					
						
							|  |  |  |     ax1.grid(True) | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     return fig | 
					
						
							| 
									
										
										
										
											2019-01-13 22:00:08 -05:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | def main(): | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     # Parse command-line arguments | 
					
						
							|  |  |  |     usage = "%prog [options] <logfile>" | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     opts = optparse.OptionParser(usage) | 
					
						
							| 
									
										
										
										
											2017-12-29 15:27:51 -05:00
										 |  |  |     opts.add_option("-f", "--frequency", action="store_true", | 
					
						
							|  |  |  |                     help="graph mcu frequency") | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     opts.add_option("-o", "--output", type="string", dest="output", | 
					
						
							|  |  |  |                     default=None, help="filename of output graph") | 
					
						
							| 
									
										
										
										
											2019-01-13 22:00:08 -05:00
										 |  |  |     opts.add_option("-t", "--temperature", type="string", dest="heater", | 
					
						
							|  |  |  |                     default=None, help="graph heater temperature") | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  |     opts.add_option("-m", "--mcu", type="string", dest="mcu", default=None, | 
					
						
							|  |  |  |                     help="limit stats to the given mcu") | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     options, args = opts.parse_args() | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     if len(args) != 1: | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |         opts.error("Incorrect number of arguments") | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |     logname = args[0] | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     # Parse data | 
					
						
							| 
									
										
										
										
											2018-02-19 23:12:14 -05:00
										 |  |  |     data = parse_log(logname, options.mcu) | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  |     if not data: | 
					
						
							|  |  |  |         return | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  | 
 | 
					
						
							|  |  |  |     # Draw graph | 
					
						
							|  |  |  |     setup_matplotlib(options.output is not None) | 
					
						
							| 
									
										
										
										
											2019-01-13 22:00:08 -05:00
										 |  |  |     if options.heater is not None: | 
					
						
							| 
									
										
										
										
											2019-06-19 14:12:56 -04:00
										 |  |  |         fig = plot_temperature(data, options.heater) | 
					
						
							|  |  |  |     elif options.frequency: | 
					
						
							|  |  |  |         fig = plot_frequency(data, options.mcu) | 
					
						
							|  |  |  |     else: | 
					
						
							|  |  |  |         fig = plot_mcu(data, MAXBANDWIDTH) | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     # Show graph | 
					
						
							|  |  |  |     if options.output is None: | 
					
						
							|  |  |  |         matplotlib.pyplot.show() | 
					
						
							|  |  |  |     else: | 
					
						
							|  |  |  |         fig.set_size_inches(8, 6) | 
					
						
							|  |  |  |         fig.savefig(options.output) | 
					
						
							| 
									
										
										
										
											2016-10-31 11:03:52 -04:00
										 |  |  | 
 | 
					
						
							|  |  |  | if __name__ == '__main__': | 
					
						
							|  |  |  |     main() |