Prune log.py

#! /usr/bin/env python
#
#  Purpose: Parse and display an informix log file
#
#  $Id:$
#
#---------------------------------------------------------------------

"""
Parse Ben Lee's LR log files to show the underlying function
invocation sequence in the designated log file. 

Another option shows timing of start of function.

Instructions for use:

1.  You should change to the loadgen directory - the one containing the log files generated by Ben's code.

2.  Run:

       $ prune_log.py -t *.log

    This produces a logs.sorted file contining the merged and sorted rewritten logs.

3.  Then run:

       $ time_line.py

    This produces 'time_line.txt' which contains the time line and concurrency map.

"""

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

import re
import os
import sys
import glob
import time
import getopt
import pickle

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

__version__  = "1.2.2"

debugFlg     = 0
stdoutFlg    = 0
verboseFlg   = 0
wallclockFlg = 0
rewriteFlg   = 0
directoryFlg = None

filename     = "Backline_0068.log"
mode         = None
data         = None
t_start      = None
td_start     = None
vuser        = "068"
node_map     = {}

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

addresses    = {}
user_threads = {}
locks        = {}
transactions = {}

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

class Lock:
   address   = None
   wtlist    = None
   owner     = None
   lklist    = None
   type      = None
   tblsnum   = None
   rowid     = None
   key_no    = None
   bsize     = None

   def __init__(self, p):
      print "XXXX", p
      self.address   = p[0]
      self.wtlist    = p[1]
      self.owner     = p[2]
      self.lklist    = p[3]
      self.type      = p[4]
      self.tblsnum   = p[5]
      self.rowid     = p[6]
      self.key_no    = p[7]
      self.bsize     = p[8]

   def Check(self, p):
      pass

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

def startSeconds(s):
   return time.mktime(time.strptime(s, "%Y-%m-%d %H:%M:%S"))

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

def seconds(hms):
   s = hms.split(':')

   return ((s[0] * 60) + s[1]) * 60 + s[2]

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

def hms(t_secs):
   hm     = t_secs / 60
   hours  = hm / 60
   mins   = hm % 60
   secs   = t_secs % 60

   return "%02d:%02d:%02d" % ( hours, mins, secs)

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

def parse(filename):
   global t_start

   print filename

   tmatch = re.search(r'(.*?).log', filename)
   if tmatch:
      name = tmatch.group(1)
   else:
      name = filename + ".log"
      filename += ".log"

   if rewriteFlg:
      outfile = name + ".out"
   else:
      outfile = name + ".seq"

   tmatch = re.search(r'line_(.*?).log', filename)
   if tmatch:
      vuser_id = int(tmatch.group(1))
   else:
      vuser_id = 0

   vuser = "%03d" % vuser_id

   try:
      ifo = open(filename, 'r')
   except IOError, msg:
      sys.stderr.write(filename + ': cannot open: ' + `msg` + '\n')
      sys.exit(1)

   if stdoutFlg == 1:
      ofo = sys.stdout
   else:
      try:
         ofo = open(outfile, 'w')
      except IOError, msg:
         sys.stderr.write(outfile + ': cannot open: ' + `msg` + '\n')
         sys.exit(1)

   cnt = 0

   username      = "*UNDEF*"
   current_task  = None
   end_iteration = 0
   t_offset      = None
   endFlg        = 0
   obj           = "-"

   while 1:

      line = ifo.readline()

      if not line: break

      line = line[:-1]
      line = line.replace("\r","")

      if re.search("^[^0-9]", line):
         continue

      if re.search("^#", line):
         continue

      if re.search("^$", line):
         continue

      if re.search("^\r$", line):
         continue

      if re.search("initial due date time", line):
         continue

      if re.search("username", line):
         tmatch = re.search(r'host \[(.*?):7001\] username \[(.*?)\]', line)
         if tmatch:
            node     = tmatch.group(1)
            username = tmatch.group(2)
            print "Username  = \"%s\"" % username
            print "Node      = \"%s\" (vuser %s)" % (node, vuser)
            node_map[vuser] = node
         continue

      if not t_offset:
         if re.search("Timestamp", line):
            tmatch = re.search(r'Timestamp \((.*?)\)', line)
            if tmatch:
               t_timestamp = int(tmatch.group(1))
               print "Timestamp = \"%d\"" % t_timestamp
               if t_start:
                  t_offset = t_timestamp - t_start
               else:
                  t_start = t_timestamp
                  print "Setting t_start = \"%d\"" % t_start
                  t_offset = 0
               print "Delta     = \"%d\"" % t_offset
               continue
            sys.exit(0)
            continue

      cnt += 1

      if re.search("TxEnd", line):
         endFlg = 1

      p = line.split(' ', 5)

      # print p

      f_elapsed = float(p[0])

      t_elapsed = int(f_elapsed) + t_offset

      if wallclockFlg == 1:
         t_wallclock = ' '.join((p[1], p[2]))
      else:
         t_wallclock = ''

      location = p[3]
      task     = p[4]

      if task == "BL_RequestSearch":
         tmatch = re.search(r'value_request_id \[Value=(.*?)\]', p[5])
         if tmatch:
            request_id = tmatch.group(1)
            obj         = request_id
            continue

      elif task == "BL_HomeRequestQueueWait":
         tmatch = re.search(r'item \[(.*?)\] rq \[Value=(.*?)\] awb \[Value=(.*?)\]', p[5])
         if tmatch:
            item_no = tmatch.group(1)
            request_id = tmatch.group(2)
            awb_number = tmatch.group(3)
            obj        = "%s:%s" % (awb_number, request_id)
            continue

      elif task == "BL_ActivityNew_No_Queue":
         tmatch = re.search(r'new_activity_id \[(.*?)\]', p[5])
         if tmatch:
            activity_id = tmatch.group(1)
            obj         = activity_id
            continue

      elif task == "BL_ActivityEventCreate_No_Queue":
         tmatch = re.search(r'item \[(.*?)\] match \[(.*?)\] value_task \[Value=(.*?)\]', p[5])
         if tmatch:
            item_no     = tmatch.group(1)
            activity_id = tmatch.group(2)
            value_task  = tmatch.group(3)
            obj         = activity_id
            continue
         tmatch = re.search(r'added to awb \[(.*?)\] value_activity_event \[Value=(.*?)\]', p[5])
         if tmatch:
            awb_number  = tmatch.group(1)
            event       = tmatch.group(2)
            continue
         tmatch = re.search(r'Total Activities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_act      = tmatch.group(1)
            continue
         tmatch = re.search(r'Total OpenActivities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_open_act = tmatch.group(1)
            continue

      # added to awb [4288432503] request type [Value=task.event.arrangedPickupRecollection]
      elif task == "BL_RequestEventCreate_No_Queue":
         tmatch = re.search(r'added to awb \[(.*?)\] request type \[Value=(.*?)\]', p[5])
         if tmatch:
            awb_number  = tmatch.group(1)
            req_type    = tmatch.group(2)
            obj         = awb_number
            continue

      # new_sub_activity_id
      elif task == "BL_SubActivityNew_No_Queue":
         tmatch = re.search(r'item \[(.*?)\] match \[(.*?)\] value_task \[Value=(.*?)\]', p[5])
         if tmatch:
            item_no     = tmatch.group(1)
            activity_id = tmatch.group(2)
            value_task  = tmatch.group(3)
            continue
         tmatch = re.search(r'added to awb \[(.*?)\] value_activity_event \[Value=(.*?)\]', p[5])
         if tmatch:
            awb_number  = tmatch.group(1)
            event       = tmatch.group(2)
            continue
         tmatch = re.search(r'Total Activities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_act      = tmatch.group(1)
            continue
         tmatch = re.search(r'Total OpenActivities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_open_act = tmatch.group(1)
            continue
         tmatch = re.search(r'new_sub_activity_id \[(.*?)\]', p[5])
         if tmatch:
            sub_act_id  = tmatch.group(1)
            obj         = sub_act_id
            continue

      elif task == "BL_ActivityClose_No_Queue":
         tmatch = re.search(r'item \[(.*?)\] match \[(.*?)\] value_task \[Value=(.*?)\]', p[5])
         if tmatch:
            item_no     = tmatch.group(1)
            activity_id = tmatch.group(2)
            value_task  = tmatch.group(3)
            obj         = activity_id
            continue
         tmatch = re.search(r'Total Activities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_act      = tmatch.group(1)
            continue
         tmatch = re.search(r'Total OpenActivities rows displayed \[(.*?)\]', p[5])
         if tmatch:
            no_open_act = tmatch.group(1)
            continue

      elif task == "FL_AWBSearch":
         tmatch = re.search(r'FL_AWBSearch_AdvancedSearch_NextStep', p[5])
         if tmatch:
            awb_number = "-"
            obj         = awb_number
         tmatch = re.search(r'AWB \[(.*?)\]', p[5])
         if tmatch:
            awb_number  = tmatch.group(1)
            obj         = awb_number
            # print "AWB [%s]" % awb_number
            # continue

      # FL_RequestCreate added to awb [4363566152] confirm / new_request_id [242991]
      elif task == "FL_RequestCreate":
         tmatch = re.search(r'added to awb \[(.*?)\] confirm \/ new_request_id \[(.*?)\]', p[5])
         if tmatch:
            awb_number  = tmatch.group(1)
            request_id  = tmatch.group(2)
            obj         = awb_number

      if rewriteFlg:
         if endFlg == 1:
            endFlg = 0
            try:
               print >>ofo, "%s %s %s %s %s %s %s [%s] [%s]" % (hms(t_elapsed), p[1], p[2], vuser, p[3], p[4], p[5], username, obj)
            except:
               print "%s" % line
               sys.exit(0)
         else:
            print >>ofo, "%s %s %s %s %s %s %s" % (hms(t_elapsed), p[1], p[2], vuser, p[3], p[4], p[5])
      else:
         if ((task != current_task) or (re.search(r'global_current_action_name \[', p[5]))):
            if current_task == "BL_RequestSearch":
               print >>ofo, "%s%s %s %-32s     RequestID  %s" % (hms(t_elapsed), t_wallclock, vuser, current_task, request_id)
            elif current_task == "BL_HomeRequestQueueWait":
               print >>ofo, "%s%s %s %-32s     RequestID  %s  AWB %s [%s]" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, request_id, awb_number, item_no)
            elif current_task == "BL_ActivityNew_No_Queue":
               print >>ofo, "%s%s %s %-32s     ActivityID %s" % (hms(t_elapsed), t_wallclock, vuser, current_task, activity_id)
            elif current_task == "BL_ActivityEventCreate_No_Queue":
               print >>ofo, "%s%s %s %-32s     ActivityID %s  AWB %s [%s:%s/%s]" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, activity_id, awb_number, item_no, no_open_act, no_act)
            elif current_task == "BL_RequestEventCreate_No_Queue":
               print >>ofo, "%s%s %s %-32s     AWB %s  RequestType [%s]" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, awb_number, req_type)
            elif current_task == "BL_SubActivityNew_No_Queue":
               print >>ofo, "%s%s %s %-32s     ActivityID %s  AWB %s [%s:%s/%s] SubActivityID %s" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, activity_id, awb_number, item_no, no_open_act, no_act, sub_act_id)
            elif current_task == "BL_ActivityClose_No_Queue":
               print >>ofo, "%s%s %s %-32s     ActivityID  %s  [%s:%s/%s]" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, activity_id, item_no, no_open_act, no_act)
            elif current_task == "BL_RequestClose_No_Queue":
               print >>ofo, "%s%s %s %-32s     RequestID   %s" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, request_id)
            elif current_task == "FL_AWBSearch":
               print >>ofo, "%s%s %s %-32s     AWB %s" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, awb_number)
            elif current_task == "FL_RequestCreate":
               print >>ofo, "%s%s %s %-32s     AWB %s  RequestID %s" % (hms(t_elapsed),
                  t_wallclock, vuser, current_task, awb_number, request_id)
            else:
               print >>ofo, "%s%s %s %-32s" % (hms(t_elapsed), t_wallclock, vuser, current_task)

            if current_task and current_task.find("EndIteration") != -1:
               print >>ofo, "          -------------------------"

         current_task = task

   ifo.close()
   ofo.close()

   print >>sys.stderr, "Processed %d lines" % cnt

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

def main():
   global filename
   global td_start
   global t_start
   global debugFlg
   global directoryFlg
   global stdoutFlg
   global verboseFlg
   global rewriteFlg
   global wallclockFlg

   try:
      opts, args = getopt.getopt(sys.argv[1:], "dDf:ors:tvVw?")
   except getopt.error, msg:
      print __doc__
      return 1

   for o, a in opts:
      if o == '-d':
         debugFlg = 1
      elif o == '-D':
         directoryFlg = 1
      elif o == '-f':
         filename = a
      elif o == '-o':
         stdoutFlg = 1
      elif o == '-s':
         td_start = a
      elif o == '-v':
         verboseFlg = 1
      elif o == '-V':
         print "Version: %s" % __version__
         return 1
      elif o == '-r':
         rewriteFlg = 1
      elif o == '-t':
         rewriteFlg = 1
         wallclockFlg = 1
      elif o == '-w':
         wallclockFlg = 1
      elif o == '-?':
         print __doc__
         return 1

   if (debugFlg):
      print ">> Flg    %s" % debugFlg

   if td_start:
      t_start          = startSeconds(td_start)
      print "Start     = %d" % t_start
   else:
      t_start          = None

   if directoryFlg:
      files = glob.glob("*.log")
      for file in files:
         parse(file)
   elif args:
      for arg in args:
         parse(arg)
   else:
      parse(filename)

   if rewriteFlg:
      print "Concatenating rewritten output files"
      os.system('cat *.out > logs.rewriten')
      print "Sorting rewritten logs"
      os.system('sort logs.rewriten > logs.sorted')
      os.system('rm -f logs.rewriten')

      # Pickle the vuser/node mapping

      print str(node_map)
      f = open('node_map.dump', 'w')
      pickle.dump(node_map, f)
      f.close()

   return 1

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

if __name__ == '__main__' or __name__ == sys.argv[0]:
   sys.exit(main())

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

"""
Revision History:

     Date     Who   Description
   --------   ---   --------------------------------------------------
   20040603   plh   Initial implementation

Problems to fix:

To Do:

Issues:

"""

"""
0000.0 [2004-06-11 20:55:34] ../lib/Utils.c:775 BL_Login Timestamp (1086951334) - Fri Jun 11 20:55:34 2004

0000.0 [2004-06-11 20:55:34] ../lib/Login.c:42 BL_Login Login - (VUser Backline:68)
0000.0 [2004-06-11 20:55:34] ../lib/Login.c:45 BL_Login host [node1.perf:7001] username [BbMELGTW] password [BbMELGTW]
0000.0 [2004-06-11 20:55:34] ../lib/Utils.c:1179 BL_Login start transaction [BL_Login_Home]
0002.0 [2004-06-11 20:55:36] ../lib/Utils.c:1101 BL_Login end transaction [BL_Login_Home]
0002.0 [2004-06-11 20:55:36] ../lib/Utils.c:1107 BL_Login transaction duration [BL_Login_Home] [2.273965]
0014.0 [2004-06-11 20:55:48] ../lib/Utils.c:1179 BL_Login start transaction [BL_Login_Redirect]
0016.0 [2004-06-11 20:55:50] ../lib/Utils.c:1101 BL_Login end transaction [BL_Login_Redirect]
0016.0 [2004-06-11 20:55:50] ../lib/Utils.c:1107 BL_Login transaction duration [BL_Login_Redirect] [0.218618]
0024.0 [2004-06-11 20:55:58] ../lib/Utils.c:1194 BL_Login start transaction [BL_Login_NotificationInitFrame]
0026.0 [2004-06-11 20:56:00] ../lib/Utils.c:1101 BL_Login end transaction [BL_Login_NotificationInitFrame]
0026.0 [2004-06-11 20:56:00] ../lib/Utils.c:1107 BL_Login transaction duration [BL_Login_NotificationInitFrame] [0.003013]
0037.0 [2004-06-11 20:56:11] ../lib/Utils.c:1179 BL_Login start transaction [BL_Login_Send]
0039.0 [2004-06-11 20:56:13] ../lib/Utils.c:1101 BL_Login end transaction [BL_Login_Send]
0039.0 [2004-06-11 20:56:13] ../lib/Utils.c:1107 BL_Login transaction duration [BL_Login_Send] [1.581912]
0047.0 [2004-06-11 20:56:21] ../lib/NotificationInit.c:6 BL_NotificationInit global_current_action_name [NotificationInit]
0047.0 [2004-06-11 20:56:21] ../lib/Utils.c:1588 BL_NotificationInit BL_NotificationInit
0047.0 [2004-06-11 20:56:21] ../lib/Utils.c:1194 BL_NotificationInit start transaction [BL_NotificationInit_InitFrame]
0049.0 [2004-06-11 20:56:23] ../lib/Utils.c:1101 BL_NotificationInit end transaction [BL_NotificationInit_InitFrame]
0049.0 [2004-06-11 20:56:23] ../lib/Utils.c:1107 BL_NotificationInit transaction duration [BL_NotificationInit_InitFrame] [0.061407]
0060.0 [2004-06-11 20:56:34] ../lib/StartIteration.c:5 BL_StartIteration global_current_action_name [StartIteration]
0060.0 [2004-06-11 20:56:34] ../lib/Utils.c:1588 BL_StartIteration BL_StartIteration
0060.0 [2004-06-11 20:56:34] ../lib/StartIteration.c:8 BL_StartIteration start user data point [BL_IterationTransaction]
0060.0 [2004-06-11 20:56:34] ../lib/NotificationRender.c:12 BL_NotificationRender global_current_action_name [NotificationRender]
0060.0 [2004-06-11 20:56:34] ../lib/Utils.c:1588 BL_NotificationRender BL_NotificationRender
0060.0 [2004-06-11 20:56:34] ../lib/NotificationRender.c:18 BL_NotificationRender notification_interval [13.000000].
0060.0 [2004-06-11 20:56:34] BL_HomeRequestQueueWait.c:15 BL_HomeRequestQueueWait global_current_action_name [HomeRequestQueueWait]
0060.0 [2004-06-11 20:56:34] ../lib/Utils.c:1588 BL_HomeRequestQueueWait BL_HomeRequestQueueWait
0060.0 [2004-06-11 20:56:34] ../lib/Utils.c:1179 BL_HomeRequestQueueWait start transaction [BL_HomeRequestQueueWait_Home]
"""