OctoprintKlipperPlugin/octoprint_klipper/modules/KlipperLogAnalyzer.py

# <Octoprint Klipper Plugin>

# This program is free software: you can redistribute it and/or modify
# it under the terms of the GNU Affero General Public License as
# published by the Free Software Foundation, either version 3 of the
# License, or (at your option) any later version.

# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU Affero General Public License for more details.

# You should have received a copy of the GNU Affero General Public License
# along with this program.  If not, see <https://www.gnu.org/licenses/>.

import flask
import optparse, datetime

class KlipperLogAnalyzer():
   MAXBANDWIDTH=25000.
   MAXBUFFER=2.
   STATS_INTERVAL=5.
   TASK_MAX=0.0025
   APPLY_PREFIX = ['mcu_awake', 'mcu_task_avg', 'mcu_task_stddev', 'bytes_write',
                   'bytes_read', 'bytes_retransmit', 'freq', 'adj']

   def __init__(self, log_file):
      self.log_file = log_file

   def read_log_file(self, logname):
      try:
         f = open(logname, 'r')
         logdata = f.read()
         f.close()
      except IOError:
         print("Couldn't open log file")
      return logdata

   def analyze(self):
      data = self.parse_log(self.log_file, None)
      if not data:
         result1 = dict(error= "No relevant data available in \"{}\"".format(self.log_file))
      else:
         result1 = self.plot_mcu(data, self.MAXBANDWIDTH)
      result = dict(plot = result1,
                    logfiledata = self.read_log_file(self.log_file)
                  )
      return result

   def parse_log(self, logname, mcu):
      if mcu is None:
         mcu = "mcu"
      mcu_prefix = mcu + ":"
      apply_prefix = { p: 1 for p in self.APPLY_PREFIX }
      out = []

      try:
         f = open(logname, 'r')

         for line in f:
            parts = line.split()
            if not parts or parts[0] not in ('Stats', 'INFO:root:Stats'):
               #if parts and parts[0] == 'INFO:root:shutdown:':
               #    break
               continue
            prefix = ""
            keyparts = {}
            for p in parts[2:]:
               if '=' not in p:
                  prefix = p
                  if prefix == mcu_prefix:
                     prefix = ''
                  continue
               name, val = p.split('=', 1)
               if name in apply_prefix:
                  name = prefix + name
               keyparts[name] = val
            if keyparts.get('bytes_write', '0') == '0':
               continue
            keyparts['#sampletime'] = float(parts[1][:-1])
            out.append(keyparts)
         f.close()
      except IOError:
          print("Couldn't open log file")
      return out

   def find_print_restarts(self, data):
      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']
         buffer_time = float(d.get('buffer_time', 0.))
         if (last_runoff_start and last_sampletime - sampletime < 5
            and buffer_time > last_buffer_time):
            runoff_samples[last_runoff_start][1].append(sampletime)
         elif buffer_time < 1.:
            last_runoff_start = sampletime
            runoff_samples[last_runoff_start] = [False, [sampletime]]
         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 list(runoff_samples.values())
                        for sampletime in samples if not stall}
      return sample_resets

   def plot_mcu(self, data, maxbw):
      # Generate data for plot
      basetime = lasttime = data[0]['#sampletime']
      lastbw = float(data[0]['bytes_write']) + float(data[0]['bytes_retransmit'])
      sample_resets = self.find_print_restarts(data)
      times = []
      bwdeltas = []
      loads = []
      awake = []
      hostbuffers = []
      for d in data:
         st = d['#sampletime']
         timedelta = st - lasttime
         if timedelta <= 0.:
            continue
         bw = float(d['bytes_write']) + float(d['bytes_retransmit'])
         if bw < lastbw:
            lastbw = bw
            continue
         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'])
         if hb >= self.MAXBUFFER or st in sample_resets:
            hb = 0.
         else:
            hb = 100. * (self.MAXBUFFER - hb) / self.MAXBUFFER
         hostbuffers.append(hb)
         times.append(st)
         bwdeltas.append(100. * (bw - lastbw) / (maxbw * timedelta))
         loads.append(100. * load / self.TASK_MAX)
         awake.append(100. * float(d.get('mcu_awake', 0.)) / self.STATS_INTERVAL)
         lasttime = st
         lastbw = bw

      result = dict(
         times= times,
         bwdeltas= bwdeltas,
         loads= loads,
         awake= awake,
         buffers= hostbuffers
      )
      return result

   def plot_frequency(self, data, mcu):
      all_keys = {}
      for d in data:
         all_keys.update(d)
      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")))) }
      basetime = lasttime = data[0]['#sampletime']
      for d in data:
         st = d['#sampletime']
         for key, (times, values) in list(graph_keys.items()):
            val = d.get(key)
            if val not in (None, '0', '1'):
               times.append(st)
               values.append(float(val)/1000000.0)

      return values