Parsing a 10046 trace with python

This needs work (I am just learning python), but try the following…

#!/usr/bin/python
#--------------------------------------------------------------------------------------------------
#Author:        Steve Howard
#Date:          March 23, 2009
#Organization:  AppCrawler
#Purpose:       Simple script to print statements in executed order from 10046 trace file.  It also
#                 prints the milliseconds between the current and previous execution.  This
#                 provides a high level overview of gaps between statements.  Large gaps
#                 warrant further investigation.
#--------------------------------------------------------------------------------------------------

import fileinput
import string
import sys
import time, datetime
from datetime import datetime
from datetime import timedelta

#**************************************************************************************************
def tail_f(f):
  interval = 1.0

  while True:
    where = f.tell()
    line = f.readline()
    if not line:
      time.sleep(interval)
      f.seek(where)
    else:
      yield line

#**************************************************************************************************

b=False
sqls = {}
deps = {}
tok=""
c=0
tim=0
firstTime=False
timeCheck=False
start=0
prevtim=0
i=0
printarray = []
printarray1 = []
printarray2 = []
printarray3 = []
printarray4 = []
printarray5 = []

#**************************************************************************************************

l=time.strptime("2004-10-22 09:05:51", "%Y-%m-%d %H:%M:%S")
p=datetime(*l[:6])
for line in tail_f(open(sys.argv[1])):
  if timeCheck == False and (line[0:3] == "***") == True:

    """
    *** ACTION NAME:() 2009-10-01 09:00:01.757
    *** MODULE NAME:(sqlplus@oh1xpwcdb01 (TNS V1-V3)) 2009-10-01 09:00:01.757
    *** SERVICE NAME:(SYS$USERS) 2009-10-01 09:00:01.757
    *** SESSION ID:(1212.19284) 2009-10-01 09:00:01.757
    """
    print line
    if line.find("ACTION NAME:") > 0:
      tmpTim=line.split(" ")[3:]
      l=time.strptime(tmpTim[0] + " " + tmpTim[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
      p=datetime(*l[:6])
      timeCheck = True
    elif line.find("MODULE NAME:") > 0:
      tmpTim=line.split(" ")[5:]
      l=time.strptime(tmpTim[0] + " " + tmpTim[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
      p=datetime(*l[:6])
      timeCheck = True
    elif line.find("SERVICE NAME:") > 0:
      tmpTim=line.split(" ")[3:]
      l=time.strptime(tmpTim[0] + " " + tmpTim[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
      p=datetime(*l[:6])
      timeCheck = True
    elif line.find("SESSION ID:") > 0:
      tmpTim=line.split(" ")[3:]
      l=time.strptime(tmpTim[0] + " " + tmpTim[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
      p=datetime(*l[:6])
      timeCheck = True
    else:
      tmpTim=line.split(" ")[1:]
      l=time.strptime(tmpTim[0] + " " + tmpTim[1].split(".")[0], "%Y-%m-%d %H:%M:%S")
      p=datetime(*l[:6])
  if firstTime == False and line.find("tim=") > 0:
    cols=dict((c, line.count(c)) for c in line)
    for col in range(0,cols.get(" ")):
      t=line.split(" ")[col]
      if t.split("=")[0] == "tim":
        start=int(line.split(" ")[col].replace("tim=",""))
        firstTime=True
  i=i+1 #keep track of line numbers for printing out to troubleshoot in raw trace file
  if (b==True and line.startswith("END OF STMT")):
    sqls[c]=tok
    deps[c]=dep
    tok=""
    b=False
  elif line.startswith("PARSING IN CURSOR"):
    c=int(line.split(" ")[3].replace("#",""))
    dep=int(line.split(" ")[5].replace("dep=",""))
    b=True
  elif line.startswith("FETCH #"):
    c=line.split(" ")[1].replace("#","").split(":")[0]
    dep=int(line.split(",")[7].replace("dep=",""))
  elif line.startswith("EXEC #"):
    c=int(line.split(":")[0].replace("EXEC #",""))
    rows=line.split(",")[6].split("=")[1]
    if deps[c] == 0:
      if tim==0:
        prevtim=tim
        tim=int(line.split(",")[10].replace("tim=",""))
        start=tim
      else:
        prevtim=tim
        tim=int(line.split(",")[10].replace("tim=",""))

      printarray.append("#-------------------------------------------------------------------");
      b=p + timedelta(0,0,tim-start)
      printarray.append(str(b))
      printarray.append(str((tim - prevtim) / 1000) + " milliseconds since the previous top level execution statement.")

      printarray.append("LINE# =  "  + str(i))
      printarray.append("Rows processed = "  + str(rows) + '\n')

      printarray.append(sqls[c]);
      for sql in range(len(printarray1)):
        printarray.append("  " + printarray1[sql]);
      del printarray1[0:]
      for sql in range(len(printarray)):
        print printarray[sql]
        sys.stdout.flush()
      del printarray[0:]
    elif deps[c] == 1:
      printarray1.append(sqls[c]);
      for sql in range(len(printarray2)):
        printarray1.append("    " + printarray2[sql]);
      del printarray2[0:]
    elif deps[c] == 2:
      printarray2.append(sqls[c]);
      for sql in range(len(printarray3)):
        printarray1.append("    " + printarray3[sql]);
      del printarray3[0:]
    elif deps[c] == 3:
      printarray2.append(sqls[c]);
      for sql in range(len(printarray4)):
        printarray2.append("    " + printarray4[sql]);
      del printarray4[0:]
    elif deps[c] == 4:
      printarray4.append(sqls[c]);
  elif (b==1):
    tok=tok + line

What is nice is this will actually print in sequentially executed order all statements found in the trace. it also indents by dependency level. In other words, if a function is called by a select statement, the SQL in the function will show up below the select, but be indented so you can see it was only run because the select above it called it.

This is really good for understanding program flow without reading source code.