{"id":4,"date":"2009-04-15T14:39:21","date_gmt":"2009-04-15T19:39:21","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=4"},"modified":"2016-08-30T09:32:37","modified_gmt":"2016-08-30T14:32:37","slug":"parsing-a-10046-trace-with-python","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2009\/04\/15\/parsing-a-10046-trace-with-python\/","title":{"rendered":"Parsing a 10046 trace with python"},"content":{"rendered":"<p>This needs work (I am just learning python), but try the following&#8230;<\/p>\n<pre lang=\"python\" line=\"1\">\r\n#!\/usr\/bin\/python\r\n#--------------------------------------------------------------------------------------------------\r\n#Author:        Steve Howard\r\n#Date:          March 23, 2009\r\n#Organization:  AppCrawler\r\n#Purpose:       Simple script to print statements in executed order from 10046 trace file.  It also\r\n#                 prints the milliseconds between the current and previous execution.  This\r\n#                 provides a high level overview of gaps between statements.  Large gaps\r\n#                 warrant further investigation.\r\n#--------------------------------------------------------------------------------------------------\r\n\r\nimport fileinput\r\nimport string\r\nimport sys\r\nimport time, datetime\r\nfrom datetime import datetime\r\nfrom datetime import timedelta\r\n\r\n#**************************************************************************************************\r\ndef tail_f(f):\r\n  interval = 1.0\r\n\r\n  while True:\r\n    where = f.tell()\r\n    line = f.readline()\r\n    if not line:\r\n      time.sleep(interval)\r\n      f.seek(where)\r\n    else:\r\n      yield line\r\n\r\n#**************************************************************************************************\r\n\r\nb=False\r\nsqls = {}\r\ndeps = {}\r\ntok=\"\"\r\nc=0\r\ntim=0\r\nfirstTime=False\r\ntimeCheck=False\r\nstart=0\r\nprevtim=0\r\ni=0\r\nprintarray = []\r\nprintarray1 = []\r\nprintarray2 = []\r\nprintarray3 = []\r\nprintarray4 = []\r\nprintarray5 = []\r\n\r\n#**************************************************************************************************\r\n\r\nl=time.strptime(\"2004-10-22 09:05:51\", \"%Y-%m-%d %H:%M:%S\")\r\np=datetime(*l[:6])\r\nfor line in tail_f(open(sys.argv[1])):\r\n  if timeCheck == False and (line[0:3] == \"***\") == True:\r\n\r\n    \"\"\"\r\n    *** ACTION NAME:() 2009-10-01 09:00:01.757\r\n    *** MODULE NAME:(sqlplus@oh1xpwcdb01 (TNS V1-V3)) 2009-10-01 09:00:01.757\r\n    *** SERVICE NAME:(SYS$USERS) 2009-10-01 09:00:01.757\r\n    *** SESSION ID:(1212.19284) 2009-10-01 09:00:01.757\r\n    \"\"\"\r\n    print line\r\n    if line.find(\"ACTION NAME:\") > 0:\r\n      tmpTim=line.split(\" \")[3:]\r\n      l=time.strptime(tmpTim[0] + \" \" + tmpTim[1].split(\".\")[0], \"%Y-%m-%d %H:%M:%S\")\r\n      p=datetime(*l[:6])\r\n      timeCheck = True\r\n    elif line.find(\"MODULE NAME:\") > 0:\r\n      tmpTim=line.split(\" \")[5:]\r\n      l=time.strptime(tmpTim[0] + \" \" + tmpTim[1].split(\".\")[0], \"%Y-%m-%d %H:%M:%S\")\r\n      p=datetime(*l[:6])\r\n      timeCheck = True\r\n    elif line.find(\"SERVICE NAME:\") > 0:\r\n      tmpTim=line.split(\" \")[3:]\r\n      l=time.strptime(tmpTim[0] + \" \" + tmpTim[1].split(\".\")[0], \"%Y-%m-%d %H:%M:%S\")\r\n      p=datetime(*l[:6])\r\n      timeCheck = True\r\n    elif line.find(\"SESSION ID:\") > 0:\r\n      tmpTim=line.split(\" \")[3:]\r\n      l=time.strptime(tmpTim[0] + \" \" + tmpTim[1].split(\".\")[0], \"%Y-%m-%d %H:%M:%S\")\r\n      p=datetime(*l[:6])\r\n      timeCheck = True\r\n    else:\r\n      tmpTim=line.split(\" \")[1:]\r\n      l=time.strptime(tmpTim[0] + \" \" + tmpTim[1].split(\".\")[0], \"%Y-%m-%d %H:%M:%S\")\r\n      p=datetime(*l[:6])\r\n  if firstTime == False and line.find(\"tim=\") > 0:\r\n    cols=dict((c, line.count(c)) for c in line)\r\n    for col in range(0,cols.get(\" \")):\r\n      t=line.split(\" \")[col]\r\n      if t.split(\"=\")[0] == \"tim\":\r\n        start=int(line.split(\" \")[col].replace(\"tim=\",\"\"))\r\n        firstTime=True\r\n  i=i+1 #keep track of line numbers for printing out to troubleshoot in raw trace file\r\n  if (b==True and line.startswith(\"END OF STMT\")):\r\n    sqls[c]=tok\r\n    deps[c]=dep\r\n    tok=\"\"\r\n    b=False\r\n  elif line.startswith(\"PARSING IN CURSOR\"):\r\n    c=int(line.split(\" \")[3].replace(\"#\",\"\"))\r\n    dep=int(line.split(\" \")[5].replace(\"dep=\",\"\"))\r\n    b=True\r\n  elif line.startswith(\"FETCH #\"):\r\n    c=line.split(\" \")[1].replace(\"#\",\"\").split(\":\")[0]\r\n    dep=int(line.split(\",\")[7].replace(\"dep=\",\"\"))\r\n  elif line.startswith(\"EXEC #\"):\r\n    c=int(line.split(\":\")[0].replace(\"EXEC #\",\"\"))\r\n    rows=line.split(\",\")[6].split(\"=\")[1]\r\n    if deps[c] == 0:\r\n      if tim==0:\r\n        prevtim=tim\r\n        tim=int(line.split(\",\")[10].replace(\"tim=\",\"\"))\r\n        start=tim\r\n      else:\r\n        prevtim=tim\r\n        tim=int(line.split(\",\")[10].replace(\"tim=\",\"\"))\r\n\r\n      printarray.append(\"#-------------------------------------------------------------------\");\r\n      b=p + timedelta(0,0,tim-start)\r\n      printarray.append(str(b))\r\n      printarray.append(str((tim - prevtim) \/ 1000) + \" milliseconds since the previous top level execution statement.\")\r\n\r\n      printarray.append(\"LINE# =  \"  + str(i))\r\n      printarray.append(\"Rows processed = \"  + str(rows) + '\\n')\r\n\r\n      printarray.append(sqls[c]);\r\n      for sql in range(len(printarray1)):\r\n        printarray.append(\"  \" + printarray1[sql]);\r\n      del printarray1[0:]\r\n      for sql in range(len(printarray)):\r\n        print printarray[sql]\r\n        sys.stdout.flush()\r\n      del printarray[0:]\r\n    elif deps[c] == 1:\r\n      printarray1.append(sqls[c]);\r\n      for sql in range(len(printarray2)):\r\n        printarray1.append(\"    \" + printarray2[sql]);\r\n      del printarray2[0:]\r\n    elif deps[c] == 2:\r\n      printarray2.append(sqls[c]);\r\n      for sql in range(len(printarray3)):\r\n        printarray1.append(\"    \" + printarray3[sql]);\r\n      del printarray3[0:]\r\n    elif deps[c] == 3:\r\n      printarray2.append(sqls[c]);\r\n      for sql in range(len(printarray4)):\r\n        printarray2.append(\"    \" + printarray4[sql]);\r\n      del printarray4[0:]\r\n    elif deps[c] == 4:\r\n      printarray4.append(sqls[c]);\r\n  elif (b==1):\r\n    tok=tok + line\r\n<\/pre>\n<p>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.<\/p>\n<p>This is really good for understanding program flow without reading source code.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>This needs work (I am just learning python), but try the following&#8230; #!\/usr\/bin\/python #&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8212;&#8211; #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&hellip;<\/p>\n<p class=\"more-link-p\"><a class=\"more-link\" href=\"http:\/\/appcrawler.com\/wordpress\/2009\/04\/15\/parsing-a-10046-trace-with-python\/\">Read more &rarr;<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_mi_skip_tracking":false,"footnotes":""},"categories":[19,24,22,26],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/4"}],"collection":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/comments?post=4"}],"version-history":[{"count":13,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/4\/revisions"}],"predecessor-version":[{"id":7,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/4\/revisions\/7"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=4"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=4"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=4"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}