Lgl timeline.py

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

"""
Parse BL's log files to show the underlying function invocation
sequence in the designated log file.  Also show timing of start
of function.
"""

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

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

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

__version__   = "1.1.2"

debugFlg      = 0
stdoutFlg     = 0
verboseFlg    = 0
wallclockFlg  = 0
rewriteFlg    = 0

filename      = "logs.sorted"
mode          = None
data          = None
td_start      = None
vuser         = "068"
no_concurrent = 50

SPACES1       = "            "
SPACES2       = "        "

started       = {}
node_map      = None

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

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):
   outfile = "time_line.txt"

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

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

   depth         = 0
   depth_max     = 0
   cnt           = 0
   cnt_fail      = 0
   last_hms      = None
   start         = None
   end           = None

   idx           = []
   marks         = []
   for i in range(no_concurrent):
      idx.append(i)
      marks.append(' ')

   while 1:
      line = ifo.readline()

      if not line: break

      line = line[:-1]

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

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

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

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

      cnt += 1

      p = line.split(' ', 6)

      # print p

      hms_elapsed   = p[0]
      hms_wallclock = p[2].replace("]","")
      vuser         = p[3]
      file_lineno   = p[4]
      task          = p[5]

      if re.search(r'TxStart', p[6]):
         s    = p[6].split(' ')
         #mode = s[0]
         mode = "START"
         tmatch = re.search(r'\[(.*?)\]', s[1])
         if tmatch:
            type     = tmatch.group(1)
            subtx    = type.replace(task, "")
            subtx    = subtx.replace("_", "")
         signature = ':'.join((type, vuser))
         # print "Signature [%s]" % signature

         try:
            col = idx.pop()
         except IndexError,e:
            print "Overflowed depth of concurrency stack (max %s) at line %d" % (no_concurrent, cnt)
            sys.exit(1)

         marks[col] = 'v'
         start      = col
         depth     += 1
         if not started.has_key(signature):
            started[signature] = col
         elif not started[signature]:
            started[signature] = col
         else:
            print "%s already started" % signature 
            print >>ofo, "%s already started" % signature 
            # sys.exit(0)
      elif re.search(r'TxEnd', p[6]):
         s    = p[6].split(' ')
         mode     = "*END*"
         tmatch = re.search(r'\[(.*?)\]', s[1])
         if tmatch:
            type     = tmatch.group(1)
            subtx    = type.replace(task, "")
            subtx    = subtx.replace("_", "")
         tmatch = re.search(r'\[(.*?)\]', s[2])
         if tmatch:
            elapsed  = float(tmatch.group(1))
         tmatch = re.search(r'\[(.*?)\]', s[3])
         if tmatch:
            status   = tmatch.group(1)
         tmatch = re.search(r'\[(.*?)\]', s[6])
         if tmatch:
            username  = tmatch.group(1)
         tmatch = re.search(r'\[(.*?)\]', s[7])
         if tmatch:
            obj       = tmatch.group(1)
         signature = ':'.join((type, vuser))
         # print "Signature [%s]" % signature
         if started.has_key(signature):
            # print "Function \"%s\" ending at line %d" % (type, cnt)
            col = started[signature]
            if status == "LR_FAIL":
               cnt_fail  += 1
               status     = "@"
               marks[col] = '+'
            else:
               status     = " "
               marks[col] = '*'
# TypeError
            end        = col
            idx.append(col)
            started[signature] = None
            depth -= 1
         else:
            print "Function \"%s\" not started at line %d" % (type , cnt)
            sys.exit(1)
      else:
         continue

      if depth > depth_max:
         depth_max = depth

      if hms_elapsed == last_hms:
         hms_elapsed   = SPACES1
         hms_wallclock = SPACES2
      else:
         last_hms = hms_elapsed

      marker = ''.join(marks)

      if mode == "START":
         print >>ofo, "%s %s %s %s %s %s          %-30s %s " % (hms_elapsed, marker, hms_wallclock, vuser, node_map[vuser], mode, task[0:30], subtx[0:25])
      else:
         if elapsed > 30:
            flg = "!"
         else:
            flg = " "
         print >>ofo, "%s %s %s %s %s %s %s%s %5.2f %-30s %-25s %s %s" % (hms_elapsed, marker, hms_wallclock, vuser, node_map[vuser], mode, status, flg, elapsed, task[0:30], subtx[0:25], username, obj)

      if start:
         marks[start] = '|'
         start        = None
      if end:
         marks[end]   = ' '
         end          = None

   ifo.close()
   ofo.close()

   print >>sys.stderr, "Processed %d lines (%d LR_FAIL) (max depth %d)" % (cnt, cnt_fail, depth_max)

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

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

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

   for o, a in opts:
      if o == '-d':
         debugFlg = 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

   f = open('node_map.dump', 'r')

   node_map = pickle.load(f)

   if args:
      for arg in args:
         parse(arg)
   else:
      parse(filename)

   return 1

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

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

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

"""
Revision History:

     Date     Who   Description
   --------   ---   --------------------------------------------------
   20040617   plh   Initial implementation

Problems to fix:

To Do:

Issues:

"""

"""
00:00:08 [2004-06-16 18:24:21] 043 ../lib/Login.c:41 FL_Login Login - (VUser Frontline:43)
00:00:08 [2004-06-16 18:24:21] 043 ../lib/Login.c:44 FL_Login host [node2.perf:7001] username [FaMELGTW] password [FaMELGTW]
00:00:08 [2004-06-16 18:24:21] 043 ../lib/Utils.c:1209 FL_Login start transaction [FL_Login_Home]
00:00:10 [2004-06-16 18:24:23] 043 ../lib/Utils.c:1110 FL_Login end transaction [FL_Login_Home]
00:00:10 [2004-06-16 18:24:23] 043 ../lib/Utils.c:1134 FL_Login transaction result [FL_Login_Home] [2.403497] [LR_PASS] [0.000000]
00:00:15 [2004-06-16 18:24:28] 065 ../lib/Login.c:41 BL_Login Login - (VUser Backline:65)
00:00:15 [2004-06-16 18:24:28] 065 ../lib/Login.c:44 BL_Login host [node2.perf:7001] username [BaMELGTW] password [BaMELGTW]
00:00:15 [2004-06-16 18:24:28] 065 ../lib/Utils.c:1209 BL_Login start transaction [BL_Login_Home]
00:00:18 [2004-06-16 18:24:31] 065 ../lib/Utils.c:1110 BL_Login end transaction [BL_Login_Home]
00:00:18 [2004-06-16 18:24:31] 065 ../lib/Utils.c:1134 BL_Login transaction result [BL_Login_Home] [2.181031] [LR_PASS] [0.000000]
00:00:19 [2004-06-16 18:24:32] 043 ../lib/Utils.c:1209 FL_Login start transaction [FL_Login_Redirect]
00:00:21 [2004-06-16 18:24:34] 043 ../lib/Utils.c:1110 FL_Login end transaction [FL_Login_Redirect]
00:00:21 [2004-06-16 18:24:34] 043 ../lib/Utils.c:1134 FL_Login transaction result [FL_Login_Redirect] [0.781231] [LR_PASS] [0.000000]
00:00:27 [2004-06-16 18:24:40] 065 ../lib/Utils.c:1209 BL_Login start transaction [BL_Login_Redirect]
00:00:29 [2004-06-16 18:24:42] 065 ../lib/Utils.c:1110 BL_Login end transaction [BL_Login_Redirect]
00:00:29 [2004-06-16 18:24:42] 065 ../lib/Utils.c:1134 BL_Login transaction result [BL_Login_Redirect] [0.131494] [LR_PASS] [0.000000]
00:00:32 [2004-06-16 18:24:45] 043 ../lib/Utils.c:1224 FL_Login start transaction [FL_Login_NotificationInitFrame]
00:00:34 [2004-06-16 18:24:47] 043 ../lib/Utils.c:1110 FL_Login end transaction [FL_Login_NotificationInitFrame]
00:00:34 [2004-06-16 18:24:47] 043 ../lib/Utils.c:1134 FL_Login transaction result [FL_Login_NotificationInitFrame] [0.041493] [LR_PASS] [0.000000]
00:00:39 [2004-06-16 18:24:52] 065 ../lib/Utils.c:1224 BL_Login start transaction [BL_Login_NotificationInitFrame]
00:00:41 [2004-06-16 18:24:54] 065 ../lib/Utils.c:1110 BL_Login end transaction [BL_Login_NotificationInitFrame]
00:00:41 [2004-06-16 18:24:54] 065 ../lib/Utils.c:1134 BL_Login transaction result [BL_Login_NotificationInitFrame] [0.041671] [LR_PASS] [0.000000]
00:00:44 [2004-06-16 18:24:57] 043 ../lib/Utils.c:1209 FL_Login start transaction [FL_Login_Send]
00:00:51 [2004-06-16 18:25:04] 065 ../lib/Utils.c:1209 BL_Login start transaction [BL_Login_Send]
00:01:00 [2004-06-16 18:25:13] 043 ../lib/Utils.c:1110 FL_Login end transaction [FL_Login_Send]
00:01:00 [2004-06-16 18:25:13] 043 ../lib/Utils.c:1134 FL_Login transaction result [FL_Login_Send] [16.080589] [LR_PASS] [0.001000]
00:01:04 [2004-06-16 18:25:17] 065 ../lib/Utils.c:1110 BL_Login end transaction [BL_Login_Send]
00:01:04 [2004-06-16 18:25:17] 065 ../lib/Utils.c:1134 BL_Login transaction result [BL_Login_Send] [12.559203] [LR_PASS] [0.000000]
00:01:10 [2004-06-16 18:25:23] 043 ../lib/NotificationInit.c:6 FL_NotificationInit global_current_action_name [NotificationInit]
00:01:10 [2004-06-16 18:25:23] 043 ../lib/Utils.c:1224 FL_NotificationInit start transaction [FL_NotificationInit_InitFrame]
"""