Difference between revisions of "Timeline.py"
Jump to navigation
Jump to search
PeterHarding (talk | contribs) |
PeterHarding (talk | contribs) |
||
Line 344: | Line 344: | ||
[[Category:Python]] | [[Category:Python]] | ||
[[Category:Log Analysis]] | [[Category:Log Analysis]] | ||
[[Category:Examples]] |
Latest revision as of 17:09, 19 July 2009
#! /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] """