2017-06-28 02:23:30 +02:00
|
|
|
#!/usr/bin/env python2
|
2016-10-31 16:03:52 +01:00
|
|
|
# Script to parse a logging file, extract the stats, and graph them
|
|
|
|
#
|
|
|
|
# Copyright (C) 2016 Kevin O'Connor <kevin@koconnor.net>
|
|
|
|
#
|
|
|
|
# This file may be distributed under the terms of the GNU GPLv3 license.
|
|
|
|
import optparse, datetime
|
|
|
|
import matplotlib.pyplot as plt, matplotlib.dates as mdates
|
|
|
|
|
|
|
|
MAXBANDWIDTH=25000.
|
2017-02-11 20:43:36 +01:00
|
|
|
MAXBUFFER=2.
|
2017-07-19 20:13:35 +02:00
|
|
|
STATS_INTERVAL=5.
|
2017-08-10 00:52:13 +02:00
|
|
|
TASK_MAX=0.0025
|
2016-10-31 16:03:52 +01:00
|
|
|
|
|
|
|
def parse_log(logname):
|
|
|
|
f = open(logname, 'rb')
|
|
|
|
out = []
|
|
|
|
for line in f:
|
|
|
|
parts = line.split()
|
2016-12-06 17:10:52 +01:00
|
|
|
if not parts or parts[0] not in ('Stats', 'INFO:root:Stats'):
|
2016-10-31 16:03:52 +01:00
|
|
|
#if parts and parts[0] == 'INFO:root:shutdown:':
|
|
|
|
# break
|
|
|
|
continue
|
2017-10-30 01:30:36 +01:00
|
|
|
keyparts = dict(p.split('=', 1)
|
|
|
|
for p in parts[2:] if not p.endswith(':'))
|
2016-12-06 17:10:52 +01:00
|
|
|
if keyparts.get('bytes_write', '0') == '0':
|
|
|
|
continue
|
2016-10-31 16:03:52 +01:00
|
|
|
keyparts['#sampletime'] = float(parts[1][:-1])
|
|
|
|
out.append(keyparts)
|
|
|
|
f.close()
|
|
|
|
return out
|
|
|
|
|
2017-02-01 17:21:01 +01:00
|
|
|
def find_print_restarts(data):
|
|
|
|
last_print_time = 0.
|
|
|
|
print_resets = []
|
|
|
|
for d in data:
|
|
|
|
print_time = float(d.get('print_time', last_print_time))
|
2017-10-30 01:30:36 +01:00
|
|
|
buffer_time = float(d.get('buffer_time', 0.))
|
|
|
|
if print_time == last_print_time and not buffer_time:
|
2017-02-01 17:21:01 +01:00
|
|
|
print_resets.append(d['#sampletime'])
|
|
|
|
last_print_time = 0.
|
2017-10-30 01:30:36 +01:00
|
|
|
elif buffer_time:
|
2017-02-01 17:21:01 +01:00
|
|
|
last_print_time = print_time
|
|
|
|
sample_resets = {}
|
|
|
|
for d in data:
|
|
|
|
st = d['#sampletime']
|
|
|
|
while print_resets and st > print_resets[0]:
|
|
|
|
print_resets.pop(0)
|
|
|
|
if not print_resets:
|
|
|
|
break
|
|
|
|
if st + 2. * MAXBUFFER > print_resets[0]:
|
|
|
|
sample_resets[st] = 1
|
|
|
|
return sample_resets
|
|
|
|
|
2017-07-19 20:13:35 +02:00
|
|
|
def plot_mcu(data, maxbw, outname, graph_awake=False):
|
2016-10-31 16:03:52 +01:00
|
|
|
# Generate data for plot
|
|
|
|
basetime = lasttime = data[0]['#sampletime']
|
|
|
|
lastbw = float(data[0]['bytes_write']) + float(data[0]['bytes_retransmit'])
|
2017-02-01 17:21:01 +01:00
|
|
|
sample_resets = find_print_restarts(data)
|
2016-10-31 16:03:52 +01:00
|
|
|
times = []
|
|
|
|
bwdeltas = []
|
|
|
|
loads = []
|
2017-07-19 20:13:35 +02:00
|
|
|
awake = []
|
2016-10-31 16:03:52 +01: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 17:10:52 +01:00
|
|
|
if bw < lastbw:
|
|
|
|
lastbw = bw
|
|
|
|
continue
|
2016-10-31 16:03:52 +01: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'])
|
2017-10-30 01:30:36 +01:00
|
|
|
if not hb or hb >= MAXBUFFER or st in sample_resets:
|
2016-10-31 16:03:52 +01: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-10 00:52:13 +02:00
|
|
|
loads.append(100. * load / TASK_MAX)
|
2017-07-21 20:19:59 +02:00
|
|
|
awake.append(100. * float(d.get('mcu_awake', 0.)) / STATS_INTERVAL)
|
2016-10-31 16:03:52 +01:00
|
|
|
lasttime = st
|
|
|
|
lastbw = bw
|
|
|
|
|
|
|
|
# Build plot
|
|
|
|
fig, ax1 = plt.subplots()
|
|
|
|
ax1.set_title("MCU bandwidth and load utilization")
|
2017-04-11 19:40:25 +02:00
|
|
|
ax1.set_xlabel('Time')
|
2016-10-31 16:03:52 +01:00
|
|
|
ax1.set_ylabel('Usage (%)')
|
2017-07-19 20:13:35 +02:00
|
|
|
if graph_awake:
|
|
|
|
ax1.plot_date(times, awake, 'b', label='Awake time')
|
2016-10-31 16:03:52 +01:00
|
|
|
ax1.plot_date(times, bwdeltas, 'g', label='Bandwidth')
|
2016-12-06 17:10:52 +01:00
|
|
|
ax1.plot_date(times, loads, 'r', label='MCU load')
|
2017-02-01 17:21:01 +01:00
|
|
|
ax1.plot_date(times, hostbuffers, 'c', label='Host buffer')
|
2017-02-11 20:43:36 +01:00
|
|
|
ax1.legend(loc='best')
|
2016-10-31 16:03:52 +01:00
|
|
|
ax1.xaxis.set_major_formatter(mdates.DateFormatter('%H:%M'))
|
|
|
|
#plt.gcf().autofmt_xdate()
|
|
|
|
ax1.grid(True)
|
|
|
|
plt.savefig(outname)
|
|
|
|
|
|
|
|
def main():
|
|
|
|
usage = "%prog [options] <logfile> <outname>"
|
|
|
|
opts = optparse.OptionParser(usage)
|
2017-07-19 20:13:35 +02:00
|
|
|
opts.add_option("-a", "--awake", action="store_true"
|
|
|
|
, help="graph mcu awake time")
|
2016-10-31 16:03:52 +01:00
|
|
|
options, args = opts.parse_args()
|
|
|
|
if len(args) != 2:
|
|
|
|
opts.error("Incorrect number of arguments")
|
|
|
|
logname, outname = args
|
|
|
|
data = parse_log(logname)
|
|
|
|
if not data:
|
|
|
|
return
|
2017-07-19 20:13:35 +02:00
|
|
|
plot_mcu(data, MAXBANDWIDTH, outname, graph_awake=options.awake)
|
2016-10-31 16:03:52 +01:00
|
|
|
|
|
|
|
if __name__ == '__main__':
|
|
|
|
main()
|