#!/usr/bin/python # test_etscan.py # """ [ Ptyhon $RCSfile: test_etscan.py,v $ $Revision: 1.11 $ ] AUTHOR : [ $Author: orca777 $ Carl r. ] DATE_CRE : [ 04.07.2003 ] DATE_MOD : [ $Date: 2004/08/01 14:30:40 $ ] DB : [ Oracle 7, 8i, 9i, 10g ] PYTHON : [ 2.3 and higher ] CMNT : [ Oracle Extended Trace Event 10046 Scanner, first pre state ] """ from pyparsing import alphas,nums, dblQuotedString, Combine, Word, Group, delimitedList, restOfLine from pyparsing import Suppress, quotedString, printables, alphanums, Literal, OneOrMore, LineStart import string extendedTraceLine = None def stripQuotes( s, l, t ): return [ t[0].strip("'") ] def getextendedTraceLine(): global extendedTraceLine if extendedTraceLine is None: # Common Token _ASSIGN_ = Literal("=").suppress() _QUOTE_ = Literal("'").suppress() _INTEGER_ = Word( nums ) _COMMA_ = Literal(",").suppress() _CURSOR_HANDLE_ = Literal('#').suppress() + _INTEGER_ _DPOINT_ = Literal(':').suppress() _SLASH_ = Literal('/').suppress() _BSLASH_ = Literal('\\').suppress() # #[ WAIT #4: nam='db file sequential read' ela= 3236 p1=1 p2=1691 p3=1 ] # _WAIT_BEGIN_ = Literal('WAIT') _WAIT_NAME_ = Literal("nam").suppress() + _ASSIGN_ + quotedString _WAIT_ELAPSED_ = Literal("ela").suppress() + _ASSIGN_ + _INTEGER_ _WAIT_P1_ = Literal("p1" ).suppress() + _ASSIGN_ + _INTEGER_ _WAIT_P2_ = Literal("p2" ).suppress() + _ASSIGN_ + _INTEGER_ _WAIT_P3_ = Literal("p3" ).suppress() + _ASSIGN_ + _INTEGER_ traceLineWait = ( _WAIT_BEGIN_.setResultsName ("TraceEvent")+ _CURSOR_HANDLE_.setResultsName ("CursorHandle") + _DPOINT_ + _WAIT_NAME_.setResultsName ("WaitName").setParseAction(stripQuotes) + _WAIT_ELAPSED_.setResultsName ("WaitElapsed") + _WAIT_P1_.setResultsName ("WaitP1") + _WAIT_P2_.setResultsName ("WaitP2") + _WAIT_P3_.setResultsName ("WaitP3") ) # #[ EXEC #4:c=0,e=2089,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1084801435871273 ] # _EXEC_BEGIN_ = Literal('EXEC') _EXEC_CPU_ = Literal("c").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_ELAPSED_ = Literal("e").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_PHYS_READ_ = Literal("p").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_CONSISTENT_ = Literal("cr").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_CURRENT_ = Literal("cu").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_MISSED_ = Literal("mis").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_ROWS_ = Literal("r").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_DEPTH_ = Literal("dep").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_OPT_GOAL_ = Literal("og").suppress() + _ASSIGN_ + _INTEGER_ _EXEC_TIME_ = Literal("tim").suppress() + _ASSIGN_ + _INTEGER_ traceLineExec = ( _EXEC_BEGIN_.setResultsName ("TraceEvent") + _CURSOR_HANDLE_.setResultsName ("CursorHandle") + _DPOINT_ + _EXEC_CPU_.setResultsName ("ExecCPU") + _COMMA_ + _EXEC_ELAPSED_.setResultsName ("ExecElapsed") + _COMMA_ + _EXEC_PHYS_READ_.setResultsName ("ExecPhysRead") + _COMMA_ + _EXEC_CONSISTENT_.setResultsName ("ExecConsistent") + _COMMA_ + _EXEC_CURRENT_.setResultsName ("ExecCurrent") + _COMMA_ + _EXEC_MISSED_.setResultsName ("ExecMissed") + _COMMA_ + _EXEC_ROWS_.setResultsName ("ExecRows") + _COMMA_ + _EXEC_DEPTH_.setResultsName ("ExecDepth") + _COMMA_ + _EXEC_OPT_GOAL_.setResultsName ("ExecOptGoal") + _COMMA_ + _EXEC_TIME_.setResultsName ("ExecTime") ) # #[ FETCH #4:c=10000,e=35829,p=4,cr=29,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435907231 ] # _FETCH_BEGIN_ = Literal('FETCH') _FETCH_CPU_ = Literal('c').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_ELAPSED_ = Literal('e').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_PHYS_READ_ = Literal('p').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_CONSISTENT_ = Literal('cr').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_CURRENT_ = Literal('cu').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_MISSED_ = Literal('mis').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_ROWS_ = Literal('r').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_DEPTH_ = Literal('dep').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_OPT_GOAL_ = Literal('og').suppress() + _ASSIGN_ + _INTEGER_ _FETCH_TIME_ = Literal('tim').suppress() + _ASSIGN_ + _INTEGER_ traceLineFetch = ( _FETCH_BEGIN_.setResultsName ('TraceEvent') + _CURSOR_HANDLE_.setResultsName ('CursorHandle') + _DPOINT_ + _FETCH_CPU_.setResultsName ('FetchCPU') + _COMMA_ + _FETCH_ELAPSED_.setResultsName ('FetchElapsed') + _COMMA_ + _FETCH_PHYS_READ_.setResultsName ('FetchPhysRead') + _COMMA_ + _FETCH_CONSISTENT_.setResultsName ('FetchConsistent') + _COMMA_ + _FETCH_CURRENT_.setResultsName ('FetchCurrent') + _COMMA_ + _FETCH_MISSED_.setResultsName ('FetchMissed') + _COMMA_ + _FETCH_ROWS_.setResultsName ('FetchRows') + _COMMA_ + _FETCH_DEPTH_.setResultsName ('FetchDepth') + _COMMA_ + _FETCH_OPT_GOAL_.setResultsName ('FetchOptGoal') + _COMMA_ + _FETCH_TIME_.setResultsName ('FetchTime') ) # # The parse trace event # [ PARSE #2:c=0,e=338,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1087828747439451 ] # _PARSE_BEGIN_ = Literal('PARSE') _PARSE_CPU_ = Literal('c').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_ELAPSED_ = Literal('e').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_PHYS_READ_ = Literal('p').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_CONSISTENT_ = Literal('cr').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_CURRENT_ = Literal('cu').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_MISSED_ = Literal('mis').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_ROWS_ = Literal('r').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_DEPTH_ = Literal('dep').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_OPT_GOAL_ = Literal('og').suppress() + _ASSIGN_ + _INTEGER_ _PARSE_TIME_ = Literal('tim').suppress() + _ASSIGN_ + _INTEGER_ # constructing PARSE Trace event traceLineParse = ( _PARSE_BEGIN_.setResultsName ('TraceEvent') + _CURSOR_HANDLE_.setResultsName ('CursorHandle') + _DPOINT_ + _PARSE_CPU_.setResultsName ('ParseCPU') + _COMMA_ + _PARSE_ELAPSED_.setResultsName ('ParseElapsed') + _COMMA_ + _PARSE_PHYS_READ_.setResultsName ('ParsePhysRead') + _COMMA_ + _PARSE_CONSISTENT_.setResultsName ('ParseConsistent') + _COMMA_ + _PARSE_CURRENT_.setResultsName ('ParseCurrent') + _COMMA_ + _PARSE_MISSED_.setResultsName ('ParseMissed') + _COMMA_ + _PARSE_ROWS_.setResultsName ('ParseRows') + _COMMA_ + _PARSE_DEPTH_.setResultsName ('ParseDepth') + _COMMA_ + _PARSE_OPT_GOAL_.setResultsName ('ParseOptGoal') + _COMMA_ + _PARSE_TIME_.setResultsName ('ParseTime') ) # # [ ===================== # PARSING IN CURSOR #1 len=71 dep=0 uid=260 oct=42 lid=260 tim=1087828747368534 hv=3555457345 ad='8fa86f70' # ALTER SESSION SET EVENTS '10046 trace name context forever, level 12' # END OF STMT ] # _PIC_DLINE_ = Literal('=====================').suppress() _PIC_BEGIN_ = Literal('PARSING IN CURSOR') _PIC_END_ = Literal('END OF STMT').suppress() _PIC_LENGTH_ = Literal('len').suppress() + _ASSIGN_ + _INTEGER_ _PIC_DEPTH_ = Literal('dep').suppress() + _ASSIGN_ + _INTEGER_ _PIC_PARSING_UID_ = Literal('uid').suppress() + _ASSIGN_ + _INTEGER_ _PIC_ORA_CMD_TYPE_ = Literal('oct').suppress() + _ASSIGN_ + _INTEGER_ _PIC_CALLER_UID_ = Literal('lid').suppress() + _ASSIGN_ + _INTEGER_ _PIC_TIME_ = Literal('tim').suppress() + _ASSIGN_ + _INTEGER_ _PIC_STMT_ID_ = Literal('hv').suppress() + _ASSIGN_ + _INTEGER_ _PIC_CURS_ADDRESS_ = Literal('ad').suppress() + _ASSIGN_ + quotedString _PIC_SQL_TEXT = OneOrMore( LineStart() + ~_PIC_END_ + restOfLine ) # constructing PARSING IN CURSOR (PIC) trace event traceLinePIC = ( _PIC_DLINE_ + LineStart() + _PIC_BEGIN_.setResultsName ('TraceEvent') + _CURSOR_HANDLE_.setResultsName ('CursorHandle') + _PIC_LENGTH_.setResultsName ('PicLength') + _PIC_DEPTH_.setResultsName ('PicDepth') + _PIC_PARSING_UID_.setResultsName ('PicParsingUID') + _PIC_ORA_CMD_TYPE_.setResultsName ('PicOraCmdType') + _PIC_CALLER_UID_.setResultsName ('PicCallerUID') + _PIC_TIME_.setResultsName ('PicTime') + _PIC_STMT_ID_.setResultsName ('PicStmtID') + _PIC_CURS_ADDRESS_.setResultsName ('PicCursAddress').setParseAction(stripQuotes) + _PIC_SQL_TEXT.setResultsName ('PicSqlText') + _PIC_END_ ) # # Stat Entries : building in summary the real execution plan of the executed SQL # # [ STAT #2 id=1 cnt=1 pid=0 pos=0 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ ' ] # _STAT_BEGIN_ = Literal('STAT') _STAT_ID_ = Literal('id').suppress() + _ASSIGN_ + _INTEGER_ _STAT_CNT_ = Literal('cnt').suppress() + _ASSIGN_ + _INTEGER_ _STAT_PID_ = Literal('pid').suppress() + _ASSIGN_ + _INTEGER_ _STAT_POS_ = Literal('pos').suppress() + _ASSIGN_ + _INTEGER_ _STAT_OBJECT_ID_ = Literal('obj').suppress() + _ASSIGN_ + _INTEGER_ _STAT_OPERATION_ = Literal('op').suppress() + _ASSIGN_ + quotedString traceLineStat = ( _STAT_BEGIN_.setResultsName ('TraceEvent') + _CURSOR_HANDLE_.setResultsName ('CursorHandle') + _STAT_ID_.setResultsName ('StatId') + _STAT_CNT_.setResultsName ('StatCnt') + _STAT_PID_.setResultsName ('StatPid') + _STAT_POS_.setResultsName ('StatPos') + _STAT_OBJECT_ID_.setResultsName ('StatObjectId') + _STAT_OPERATION_.setResultsName ('StatOperation').setParseAction(stripQuotes) ) # # The Parsing Header of the Trace file # # [ /ORACLE/COSI/trace/cosi2_ora_11629.trc # Oracle9i Enterprise Edition Release 9.0.1.4.0 - 64bit Production # With the Partitioning and Real Application Clusters options # JServer Release 9.0.1.4.0 - Production ] _PATH_DELIM_ = Literal('/') _PATH_COMPONENT_ = OneOrMore ( alphanums ^ Literal('_') ).setDebug() _PATH_TRACE_FILE_ = OneOrMore ( _PATH_COMPONENT_ + _PATH_DELIM_ ) _TRACE_FILE_NAME_ = _PATH_COMPONENT_ + Literal('.trc') _HEADER_TRACE_FILE_ = ( Literal('/') + _PATH_TRACE_FILE_ + _TRACE_FILE_NAME_ ) _PATH_COMPONENT_.setDebug() _PATH_DELIM_.setDebug() _PATH_TRACE_FILE_.setDebug() _TRACE_FILE_NAME_.setDebug() traceHeader = ( _HEADER_TRACE_FILE_.setResultsName ('HeaderTraceFile') ) traceHeader.setDebug() # # Constructing all tracelines # extendedTraceLine = ( traceHeader ^ traceLineWait ^ traceLineExec ^ traceLineFetch ^ traceLineParse ^ traceLinePIC ^ traceLineStat ) return extendedTraceLine tracedata = """ EXEC #4:c=0,e=2089,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1084801435871273 WAIT #4: nam='db file sequential read' ela= 3249 p1=1 p2=12599 p3=1 WAIT #4: nam='db file sequential read' ela= 10983 p1=1 p2=13804 p3=1 WAIT #4: nam='db file sequential read' ela= 4675 p1=1 p2=2227 p3=1 WAIT #4: nam='KJC: Wait for msg sends to complete' ela= 329 p1=0 p2=0 p3=0 WAIT #4: nam='global cache cr request' ela= 540 p1=1 p2=1691 p3=15460379520 WAIT #4: nam='db file sequential read' ela= 3236 p1=1 p2=1691 p3=1 FETCH #4:c=10000,e=35829,p=4,cr=29,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435907231 FETCH #4:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435907613 FETCH #4:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435907875 FETCH #4:c=0,e=22,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908015 FETCH #4:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908151 FETCH #4:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908282 FETCH #4:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908415 FETCH #4:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908568 FETCH #4:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908713 FETCH #4:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908842 FETCH #4:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435908973 FETCH #4:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1084801435909110 FETCH #4:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1084801435909269 STAT #4 id=1 cnt=12 pid=0 pos=0 obj=0 op='SORT ORDER BY ' STAT #4 id=2 cnt=12 pid=1 pos=1 obj=0 op='NESTED LOOPS OUTER ' STAT #4 id=3 cnt=12 pid=2 pos=1 obj=96 op='TABLE ACCESS BY INDEX ROWID DEPENDENCY$ ' STAT #4 id=4 cnt=12 pid=3 pos=1 obj=127 op='INDEX RANGE SCAN ' STAT #4 id=5 cnt=12 pid=2 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ ' STAT #4 id=6 cnt=12 pid=5 pos=1 obj=36 op='INDEX UNIQUE SCAN ' WAIT #4: nam='row cache lock' ela= 1303 p1=8 p2=0 p3=3 PARSING IN CURSOR #2 len=42 dep=1 uid=0 oct=3 lid=0 tim=1087828747439472 hv=2091761008 ad='95cc2000' select condition from cdef$ where rowid=:1 END OF STMT PARSE #2:c=0,e=338,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1087828747439451 BINDS #2: bind 0: dty=11 mxl=16(16) mal=00 scl=00 pre=00 oacflg=18 oacfl2=1 size=16 offset=0 bfp=102e94f38 bln=16 avl=16 flg=05 value=0000A99D.0003.0001 EXEC #2:c=0,e=1506,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1087828747441342 FETCH #2:c=0,e=237,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=1087828747441702 STAT #2 id=1 cnt=1 pid=0 pos=0 obj=31 op='TABLE ACCESS BY USER ROWID CDEF$ ' """ parsingInBlock = """ ===================== PARSING IN CURSOR #1 len=71 dep=0 uid=260 oct=42 lid=260 tim=1087828747368534 hv=3555457345 ad='8fa86f70' ALTER SESSION SET EVENTS '10046 trace name context forever, level 12' END OF STMT """ traceHeaderStr = """ /ORACLE/COSI/trace/cosi2_ora_11629.trc """ for line in tracedata.split("\n"): if not line: continue print line if 'WAIT #' in line: fields = getextendedTraceLine().parseString(line) print fields if 'EXEC #' in line: fields = getextendedTraceLine().parseString(line) print fields if 'FETCH #' in line: fields = getextendedTraceLine().parseString(line) print fields if 'STAT #' in line: fields = getextendedTraceLine().parseString(line) print fields if 'PARSE #' in line: fields = getextendedTraceLine().parseString(line) print fields # Testing ParsingInCursor (PIC) Trace Event... print parsingInBlock fields = getextendedTraceLine().parseString(parsingInBlock) print fields # Testing TraceHeader ... print traceHeaderStr fields = getextendedTraceLine().parseString(traceHeaderStr) print fields """ $Header: /cvsroot/etprof/etprof/Test/test_etscan.py,v 1.11 2004/08/01 14:30:40 orca777 Exp $ $Log: test_etscan.py,v $ Revision 1.11 2004/08/01 14:30:40 orca777 Added Grammar for the PARSE Trace Event and refined token naming Revision 1.10 2004/07/31 19:43:16 orca777 Added Grammar for the STAT Trace Event Revision 1.9 2004/07/24 10:44:02 orca777 Added Grammar for PARSING IN CURSOR (PIC) Trace Event Revision 1.8 2004/07/10 21:26:48 orca777 Combined grammar for tracelines ( traceLineWait ^ traceLineExec ^ traceLineFetch) Revision 1.7 2004/07/10 20:35:55 orca777 no message """