Timeline.py
Jump to navigation
Jump to search
#! /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"
SPACES = " "
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 = "timeline.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(25):
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
col = idx.pop()
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
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 "%s ending" % type
col = started[signature]
if status == "LR_FAIL":
cnt_fail += 1
status = "@"
marks[col] = '+'
else:
status = " "
marks[col] = '*'
end = col
idx.append(col)
started[signature] = None
depth -= 1
else:
print "%s not started" % type
sys.exit(1)
else:
continue
if depth > depth_max:
depth_max = depth
if hms_elapsed == last_hms:
hms_elapsed = SPACES
hms_wallclock = SPACES
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]
"""