Analyse Test Script Logs

calculate Mean and SD

This script takes the output of another script which produces test summary logs and calculates Mean and SD for query execution times. See [ODBC Test Script].

#!/usr/bin/env python
#
#  Purpose:
#
#  $Id:$
#
#-------------------------------------------------------------------------------

"""
  Analyse SLAPD logs

  ...
"""
#-------------------------------------------------------------------------------

import os
import re
import sys
import math
import getopt
import logging

#-------------------------------------------------------------------------------

from datetime import datetime

#-------------------------------------------------------------------------------

__version__   = "1.0.0"
__id__        = "@(#)  analyse.py  [%s]  01/05/2008"

verbose_flg   = False

debug_level   = 0

LOGFILE       = "xxx.log"
PIDFILE       = "analyse.pid"

tables        = []

log           = None
pid           = None
file_name     = None

#===============================================================================

def INFO(msg):
   if log: log.info(' ' + msg)
   if verbose_flg: print "[analyse]  %s" % msg

#-------------------------------------------------------------------------------

def ERROR(msg):
   if log: log.error(msg)
   sys.stderr.write('[analyse]  %s\n' % msg)

#-------------------------------------------------------------------------------

def WARNING(msg):
   if log: log.warning('*****' + msg + '*****')
   if verbose_flg: print "[analyse]  %s" % msg

#===============================================================================

def analyse(fname):
   try:
      f = open(fname, 'r')
   except IOError, e:
      sys.stderr.write('[analyse]  Open failed: ' + str(e) + '\n')
      sys.exit(1)

   s_Started = 'Started'
   p_Started = re.compile(s_Started)

   s_time   = r'.*\[([^\]]*)\]'
   p_time   = re.compile(s_time)

   times =  []

   cnt = 0

   sum_time  = 0.0
   sum_time2 = 0.0

   while True:
      line = f.readline()

      if not line: break

      line = line.strip()

      m = p_Started.search(line)

      if m:
          continue

      m = p_time.search(line)

      if m:
         time    = float(m.group(1))

         times.append(time)

         cnt += 1

         sum_time    += time
         t_squared    = time * time
         sum_time2   += t_squared

         if verbose_flg: print "%s  %3d  %s" % time

   mean = sum_time / cnt

   sum_sqr = 0.0

   for t in times:
       delta    = (t - mean)
       sqr      = delta * delta
       sum_sqr += sqr

   sigma = math.sqrt(sum_sqr / cnt)

   sd   = math.sqrt((sum_time2 - (cnt * (mean * mean)))/cnt)

   print "Mean = %7.3f [%d]  sigma  %.2f  SD %.2f" % (mean, cnt, sigma, sd)

   f.close()

   if debug_level > 5: INFO("Processed %d lines" % (len(Data), ))

#===============================================================================

def init():
   global log
   global pid

   pid = os.getpid()

   log  = logging.getLogger('xxx')
   hdlr = logging.FileHandler(LOGFILE)
   fmtr = logging.Formatter('%(asctime)s %(levelname)s %(message)s')

   hdlr.setFormatter(fmtr)
   log.addHandler(hdlr)
   log.setLevel(logging.INFO)

   INFO("Started processing")

   if (not verbose_flg):
      INFO("PID is %d" % pid)

#===============================================================================

def main():
   global verbose_flg
   global debug_level
   global file_name

   try:
      opts, args = getopt.getopt(sys.argv[1:], "df:D:vVw?")
   except getopt.error, msg:
      print __doc__
      return 1

   for o, a in opts:
      if o == '-d':
         debug_level   += 1
      elif o == '-D':
         debug_level    = int(a)
      elif o == '-f':
         file_name      = a
      elif o == '-v':
         verbose_flg    = True
      elif o == '-V':
         print "[analyse]  Version: %s" % __version__
         return 1
      elif o == '-?':
         print __doc__
         return 1

   print "[analyse]  Working directory is %s" % os.getcwd()

   if (debug_level > 0): print "Debugging level set to %d" % debug_level

   if args:
      for arg in args:
         print arg

   init()

   analyse('lastnight.log')

   return 0

#-------------------------------------------------------------------------------

if __name__ == '__main__' or __name__ == sys.argv[0]:
   try:
      sys.exit(main())
   except KeyboardInterrupt, e:
      print "[analyse]  Interrupted!"

#-------------------------------------------------------------------------------

"""
Revision History:

     Date     Who   Description
   --------   ---   ------------------------------------------------------------
   20080501   plh   Initial implementation

Problems to fix:

To Do:

Issues:

"""

#-------------------------------------------------------------------------------

Input File

2008-05-02 13:03:58,328 INFO  ===== Started processing ==================================
2008-05-02 13:04:00,125 INFO  01 ManifestNo EA004454072AU  [1.735] sec    7 rows returned
2008-05-02 13:04:01,546 INFO  02 ManifestNo EE007797760BD  [1.421] sec    4 rows returned
2008-05-02 13:04:02,640 INFO  03 ManifestNo EA004393078AU  [1.094] sec    5 rows returned
2008-05-02 13:04:03,625 INFO  04 ManifestNo EA003698436AU  [0.985] sec    3 rows returned
2008-05-02 13:04:05,328 INFO  05 ManifestNo EA004065228AU  [1.703] sec    8 rows returned
2008-05-02 13:04:06,750 INFO  06 ManifestNo EE017124361BR  [1.422] sec    6 rows returned
2008-05-02 13:04:08,203 INFO  07 ManifestNo EM710190113KR  [1.453] sec    5 rows returned
2008-05-02 13:04:09,655 INFO  08 ManifestNo EM640327308KR  [1.453] sec    6 rows returned
2008-05-02 13:04:11,125 INFO  09 ManifestNo EE000212495VU  [1.453] sec    6 rows returned
2008-05-02 13:04:12,078 INFO  10 ManifestNo EH609611995CN  [0.953] sec    1 rows returned

Output

Looks like:

Mean =   3.762 [5542]  sigma  1.53  SD 1.53