Prune log.py
Revision as of 18:35, 24 May 2008 by PeterHarding (talk | contribs) (New page: <pre> #! /usr/bin/env python # # Purpose: Parse and display an informix log file # # $Id:$ # #--------------------------------------------------------------------- """ Parse Ben Lee's L...)
#! /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]
"""