Oracle Database Time Model Viewer in Excel 5

16 03 2011

March 16, 2011 (Updated August 11, 2011)

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

In the previous articles in this series we looked at ways to analyze the Oracle time model data at the system-wide level with drill-down into the session level detail, with cross references to a handful of statistics found in V$OSSTAT and V$SYSSTAT, and the system-wide wait events with drill-down into the session level wait event detail.  There is a chance that some of the statistics might appear to be inconsistent between the various performance views, or possibly even between the start of the retrieval of the rows from a single performance view and the retrieval of the final row from the query of that performance view.  You might even find in some cases, with some combinations of operating system platform and Oracle release version that the statistics in V$OSSTAT might not be in the unit of measure described in the Oracle Database documentation – a recent thread on the OTN forums contains an example of such a case (I completely overlooked the inconsistency that was pointed out in that thread).  Is there a reason for the inconsistency?  A quick browse through Metalink (MOS) finds the following articles:

Bug 7430365: INCORRECT VALUES FOR USER_TIME IN V$OSSTAT (3.79 hours per CPU per elapsed hour)
Bug 3574504: INCORRECT STATISTICS IN V$OSSTAT IN HP-UX
Bug 5933195: NUM_CPUS VALUE IN V$OSSTAT IS WRONG
Bug 5639749: CPU_COUNT NOT SHOWN PROPERLY FROM THE DATABASE
Bug 10427553: HOW DOES V$OSSTAT GET IT’S INFORMATION ON AIX
Bug 9228541: CPU TIME REPORTED INCORRECTLY IN V$SYSMETRIC_HISTORY (3.75 hours per CPU per elapsed hour)
Doc ID 889396.1: Very large value for OS_CPU_WAIT_TIME FROM V$OSSTAT / AWR Report
Bug 7447648: OS_CPU_WAIT_TIME VALUE FROM V$OSSTAT IS INCORRECT

At the end of the previous article, we had produced a demonstration project that generated screen output similar to the following (note that the project code as of the end of part four in the series may be downloaded by using the link at the end of the fourth article):

Let’s continue adding features to the project.  We will start by adding three new CommandButtons to the UserForm with the (Name) property set to the following (one name per CommandButton): cmdTraceSession, cmdStopTrace, and cmdShowExecutionPlan.  Assign useful titles to the CommandButtons by setting appropriate values for the Caption property – due to limited available space on the UserForm I selected the Captions: Trace, Stop Trace, and XPLAN.  The UserForm in my sample project currently appears as shown in the following screen capture:

Next, we need to add a little more code to the Initialize event of the UserForm to add the SQL statements that will allow the CommandButtons to function.  Double-click in the background area of the UserForm to display the Initialize event code for the UserForm.

Scroll down through the code until you find the following comment section:

    'More code will be copied here
    '
    '
    '

Add a couple of blank lines above that comment section and paste in the following code:

    Set snpSQLStats = New ADODB.Recordset
    Set comSQLStats = New ADODB.Command

    With comTrace
        strSQL = "DBMS_MONITOR.SESSION_TRACE_ENABLE(?,?,TRUE,TRUE)"

        .CommandText = strSQL
        .CommandType = adCmdStoredProc
        .ActiveConnection = dbDatabase
    End With

    With comXPLAN
        strSQL = "SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR( ?, ?, 'TYPICAL +PEEKED_BINDS'))"

        'Add the bind variables
        .Parameters.Append .CreateParameter("sqlid", adVarChar, adParamInput, 40, "")
        .Parameters.Append .CreateParameter("childnumber", adNumeric, adParamInput, 8, 0)

        .CommandText = strSQL
        .CommandType = adCmdText
        .CommandTimeout = 30
        .ActiveConnection = dbDatabase
    End With 

    With comSQLChildReason
        strSQL = "SELECT" & vbCrLf
        strSQL = strSQL & "  SSC.*" & vbCrLf
        strSQL = strSQL & "FROM" & vbCrLf
        strSQL = strSQL & "  V$SQL_SHARED_CURSOR SSC" & vbCrLf
        strSQL = strSQL & "WHERE" & vbCrLf
        strSQL = strSQL & "  SSC.SQL_ID= ?" & vbCrLf
        strSQL = strSQL & "  AND SSC.CHILD_NUMBER= ?" & vbCrLf

        'Set up the command properties
        .CommandText = strSQL
        .CommandType = adCmdText
        .CommandTimeout = 30

        .ActiveConnection = dbDatabase

        'Add the bind variables
        .Parameters.Append .CreateParameter("sqlid", adVarChar, adParamInput, 40, "")
        .Parameters.Append .CreateParameter("childnumber", adNumeric, adParamInput, 8, 0)
    End With

    With comSQLChildBind
        strSQL = "SELECT" & vbCrLf
        strSQL = strSQL & "  SBM.POSITION," & vbCrLf
        strSQL = strSQL & "  SBM.DATATYPE," & vbCrLf
        strSQL = strSQL & "  SBM.MAX_LENGTH," & vbCrLf
        strSQL = strSQL & "  SBM.BIND_NAME" & vbCrLf
        strSQL = strSQL & "FROM" & vbCrLf
        strSQL = strSQL & "  V$SQL S," & vbCrLf
        strSQL = strSQL & "  V$SQL_BIND_METADATA SBM" & vbCrLf
        strSQL = strSQL & "WHERE" & vbCrLf
        strSQL = strSQL & "  S.SQL_ID= ?" & vbCrLf
        strSQL = strSQL & "  AND S.CHILD_NUMBER= ?" & vbCrLf
        strSQL = strSQL & "  AND S.CHILD_ADDRESS=SBM.ADDRESS" & vbCrLf
        strSQL = strSQL & "ORDER BY" & vbCrLf
        strSQL = strSQL & "  SBM.POSITION" & vbCrLf

        'Set up the command properties
        .CommandText = strSQL
        .CommandType = adCmdText
        .CommandTimeout = 30

        .ActiveConnection = dbDatabase

        'Add the bind variables
        .Parameters.Append .CreateParameter("sqlid", adVarChar, adParamInput, 40, "")
        .Parameters.Append .CreateParameter("childnumber", adNumeric, adParamInput, 8, 0)
    End With

    Set snpSQLStats = New ADODB.Recordset
    Set comSQLStats = New ADODB.Command

    With comSQLStats
        strSQL = "SELECT" & vbCrLf
        strSQL = strSQL & "  LAST_ACTIVE_TIME," & vbCrLf
        strSQL = strSQL & "  PARSE_CALLS," & vbCrLf
        strSQL = strSQL & "  EXECUTIONS," & vbCrLf
        strSQL = strSQL & "  CPU_TIME," & vbCrLf
        strSQL = strSQL & "  ELAPSED_TIME," & vbCrLf
        strSQL = strSQL & "  APPLICATION_WAIT_TIME," & vbCrLf
        strSQL = strSQL & "  CONCURRENCY_WAIT_TIME," & vbCrLf
        strSQL = strSQL & "  CLUSTER_WAIT_TIME," & vbCrLf
        strSQL = strSQL & "  USER_IO_WAIT_TIME," & vbCrLf
        strSQL = strSQL & "  PLSQL_EXEC_TIME," & vbCrLf
        strSQL = strSQL & "  JAVA_EXEC_TIME," & vbCrLf
        strSQL = strSQL & "  BUFFER_GETS," & vbCrLf
        strSQL = strSQL & "  DISK_READS," & vbCrLf
        strSQL = strSQL & "  DIRECT_WRITES," & vbCrLf
        strSQL = strSQL & "  ROWS_PROCESSED," & vbCrLf
        strSQL = strSQL & "  FETCHES," & vbCrLf
        strSQL = strSQL & "  LOADS," & vbCrLf
        strSQL = strSQL & "  INVALIDATIONS" & vbCrLf
        strSQL = strSQL & "FROM" & vbCrLf
        strSQL = strSQL & "  V$SQLSTATS" & vbCrLf
        strSQL = strSQL & "WHERE" & vbCrLf
        strSQL = strSQL & "  SQL_ID= ?" & vbCrLf
        strSQL = strSQL & "  AND PLAN_HASH_VALUE= ?"
        'Set up the command properties
        .CommandText = strSQL
        .CommandType = adCmdText
        .CommandTimeout = 30

        .ActiveConnection = dbDatabase

        'Add the bind variables
        .Parameters.Append .CreateParameter("sqlid", adVarChar, adParamInput, 40, "")
        .Parameters.Append .CreateParameter("plan_hash_value", adNumeric, adParamInput, 8, 0)
    End With

In the above, you might have noticed that I neglected to set up the two bind variables for the comTrace object (an object of type ADODB.Command), while I did set up the two bind variables for the comXPLAN object.  The reason for this omission is that in previous testing I simply could not make the SQL code execute with bind variables, so I cheated a bit, and will simply replace the CommandText property value for the comTrace object with hardcoded values for the session’s SID and SERIAL# when the cmdTraceSession CommandButton is clicked.

View the UserForm again (find frmTimeModel under the Forms heading, right-click the UserForm’s name, and select View Object).  Then double-click the cmdTraceSession CommandButton to show the Click event for that object.  Change the Click event so that it includes the following code:

Private Sub cmdTraceSession_Click()
    Dim i As Integer
    Dim intSessionTrace As Integer
    Dim strSQL As String

    If intCurrentSessionIndex > -1 Then
        strSQL = "DBMS_MONITOR.SESSION_TRACE_ENABLE(" & Format(lngSID(intCurrentSessionIndex)) & "," & Format(lngSerial(intCurrentSessionIndex)) & " ,TRUE,TRUE)"
        comTrace.CommandText = strSQL
        comTrace.Execute
    End If

    'Remember that we enabled trace for this session
    intSessionTrace = 0
    For i = 1 To 1000
        If SessionTrace(i).lngSID = lngSID(intCurrentSessionIndex) Then
            intSessionTrace = i
            Exit For
        End If
    Next i
    If intSessionTrace = 0 Then
        'Find an unused entry
        For i = 1 To 1000
            If SessionTrace(i).lngSID = 0 Then
                intSessionTrace = i
                SessionTrace(i).lngSID = lngSID(intCurrentSessionIndex)
                SessionTrace(i).lngSerial = lngSerial(intCurrentSessionIndex)
                Exit For
            End If
        Next i
    End If
    SessionTrace(intSessionTrace).int10046Level = 12
    cmdStopTrace.Enabled = True
    cmdTraceSession.Enabled = False
    tvTimeModel.SetFocus 
End Sub

If you examine the code, you will see that we use the intCurrentSessionIndex variable’s value to know which session is the session of interest, and then set the SessionTrace object’s int10046Level property to 12 to indicate that we have enabled a level 12 trace for the session (this allows us to remember which sessions are being traced).  But, we have a couple of problems: the intCurrentSessionIndex variable has a default value of 0 and so far we have not added code to assign a value to that variable; secondly, the SessionTrace object simply does not exist.  Adding the SessionTrace object is easy, so we will start there.  Scroll all the way up to the top of the project’s code and add the following code above everything else:

Private Type TraceDefinition
    lngSID As Long
    lngSerial As Long
    int10046Level As Integer
    int10053Level As Integer
    int10032Level As Integer
    int10033Level As Integer
    int10104Level As Integer
End Type

Dim SessionTrace(1000) As TraceDefinition

The first of the above sections creates the definition of the object type TraceDefinition which is simply composed of seven variables.

While in that section of the project code, add a couple of more variable declarations that will be used later (first scroll down to where you see similar variable declarations):

Dim snpSQLStats As ADODB.Recordset          'ADO recordset object used to retrieve the statistics for the execution plan
Dim comSQLStats As ADODB.Command            'ADO command object used to retrieve the statistics for the execution plan

The second section (beginning with the word Dim) creates an array of 1,000 (actually 1,001) objects of type TraceDefinition.

Now for the hard part – how do we know which session is the current session – the one that is currently highlighted in the TreeView control?  The key to this is in how we named the TreeView rows (by setting the Key property) as the rows were added in the UpdateDisplay subroutine.  Each row that contains session-level detail has a Key property that begins with the value SESSION, so we are able to easily determine when a session-level detail row is clicked.  Also part of the Key property is an underscore ( _ ) character that acts as a field delimiter between the rest of the name and a sequential number that points to additional information about that session.  View the UserForm object again and double-click the TreeView control.  Switch to the NodeClick event for the TreeView control (in the drop-down list at the right of the code window) and change the NodeClick event’s code to show the following:

Private Sub tvTimeModel_NodeClick(ByVal Node As MSComctlLib.Node)
    Dim i As Integer
    Dim intSessionTrace As Integer

    If Left(Node.Key, 7) = "SESSION" Then
        intCurrentSessionIndex = Right(Node.Key, Len(Node.Key) - InStr(Node.Key, "_"))

        intSessionTrace = 0
        For i = 1 To 1000
            If (SessionTrace(i).lngSID = lngSID(intCurrentSessionIndex)) And (SessionTrace(i).lngSerial = lngSerial(intCurrentSessionIndex)) Then
                intSessionTrace = i
                Exit For
            End If
        Next i
        If intSessionTrace > 0 Then
            If SessionTrace(intSessionTrace).int10046Level > 0 Then
                cmdTraceSession.Enabled = False
                cmdStopTrace.Enabled = True
            Else
                cmdTraceSession.Enabled = True
                cmdStopTrace.Enabled = False
            End If
        Else
            cmdTraceSession.Enabled = True
            cmdStopTrace.Enabled = False
        End If
        If strSQLID(intCurrentSessionIndex) <> "" Then
            cmdShowExecutionPlan.Enabled = True
        Else
            cmdShowExecutionPlan.Enabled = False
        End If
    Else
        intCurrentSessionIndex = -1
        cmdTraceSession.Enabled = False
        cmdStopTrace.Enabled = False
        cmdShowExecutionPlan.Enabled = False
    End If
End Sub

Easy to understand so far?  Let’s add the code to the cmdStopTrace CommandButton.  View the UserForm and then double-click the cmdStopTrace CommandButton.  Change the Click event’s code to show the following:

Private Sub cmdStopTrace_Click()
    Dim i As Integer
    Dim intSessionTrace As Integer
    Dim strSQL As String

    If intCurrentSessionIndex > -1 Then
        strSQL = "DBMS_MONITOR.SESSION_TRACE_DISABLE(" & Format(lngSID(intCurrentSessionIndex)) & "," & Format(lngSerial(intCurrentSessionIndex)) & ")"
        comTrace.CommandText = strSQL
        comTrace.Execute

        'Remember that we disabled trace for this session
        intSessionTrace = 0
        For i = 1 To 1000
            If SessionTrace(i).lngSID = lngSID(intCurrentSessionIndex) Then
                intSessionTrace = i
                Exit For
            End If
        Next i
        If intSessionTrace <> 0 Then
            SessionTrace(intSessionTrace).int10046Level = 0
            If (SessionTrace(intSessionTrace).int10032Level = 0) _
              And (SessionTrace(intSessionTrace).int10033Level = 0) _
              And (SessionTrace(intSessionTrace).int10046Level = 0) _
              And (SessionTrace(intSessionTrace).int10053Level = 0) _
              And (SessionTrace(intSessionTrace).int10104Level = 0) Then
                'Forget this trace entry
                SessionTrace(intSessionTrace).lngSID = 0
                SessionTrace(intSessionTrace).lngSerial = 0
            End If
        End If
        cmdStopTrace.Enabled = False
        cmdTraceSession.Enabled = True
    End If
    tvTimeModel.SetFocus
End Sub

You might notice that the code to stop the trace for a session is very similar to the code to start the trace.

The code for the cmdShowExecutionPlan CommandButton could be quite tame, as it was in the original Time Model Viewer project, but that would be a bit boring.  Let’s do something a little special.  First, view the UserForm object and then double-click the cmdShowExecutionPlan CommandButton.  Change the Click event for the CommandButton to show the following:

Private Sub cmdShowExecutionPlan_Click()
    Dim strOut As String
    Dim strSQLSQLID As String
    Dim intSQLChildNumber As Integer
    Dim intFileNum As Integer
    Dim intFlag As Integer
    Dim j As Integer

    On Error Resume Next

    tvTimeModel.SetFocus
    If intCurrentSessionIndex > -1 Then
        strSQLSQLID = Left(strSQLID(intCurrentSessionIndex), InStr(strSQLID(intCurrentSessionIndex), "/") - 1)
        intSQLChildNumber = Val(Right(strSQLID(intCurrentSessionIndex), Len(strSQLID(intCurrentSessionIndex)) - InStr(strSQLID(intCurrentSessionIndex), "/")))

        comXPLAN("sqlid") = strSQLSQLID
        comXPLAN("childnumber") = Null
        'If you only want the plan for the current SQL statement, uncomment the following
        'comXPLAN("childnumber") = intSQLChildNumber

        Set snpXPLAN = comXPLAN.Execute
        If Not (snpXPLAN Is Nothing) Then
            If snpXPLAN.State = 1 Then
                'Create the directory if it does not already exist
                If Len(Dir("C:\ExcelTimeModelViewer", vbDirectory)) < 5 Then
                    MkDir "C:\ExcelTimeModelViewer"
                End If

                intFileNum = FreeFile
                Open "C:\ExcelTimeModelViewer\DBMS_XPLAN.txt" For Output As #intFileNum

                If snpXPLAN.EOF = True Then
                    strOut = "No Execution Plans for SQL ID " & strSQLSQLID
                Else
                    strOut = ""
                End If
                Do While Not snpXPLAN.EOF
                    If (Left(snpXPLAN(0), 7) = "SQL_ID ") And (InStr(LCase(snpXPLAN(0)), "child number ") > 1) And (InStr(LCase(snpXPLAN(0)), "cannot be found") = 0) Then
                        If intFlag = True Then
                            strOut = strOut & String(100, "~") & vbCrLf
                            strOut = strOut & "" & vbCrLf
                            intFlag = False
                        End If
                        strOut = strOut & String(100, "*") & vbCrLf
                        comSQLChildReason("sqlid") = strSQLSQLID
                        comSQLChildReason("childnumber") = CInt(Right(snpXPLAN(0), Len(snpXPLAN(0)) - (InStr(snpXPLAN(0), "child number ") + 12)))
                        Set snpSQLChildReason = comSQLChildReason.Execute

                        If Not (snpSQLChildReason Is Nothing) Then
                            If snpSQLChildReason.State = 1 Then
                                If Not (snpSQLChildReason.EOF) Then
                                    strOut = strOut & "Reason for Child Cursor Creation" & vbCrLf
                                    For j = 4 To snpSQLChildReason.Fields.Count - 1
                                        If snpSQLChildReason(j) = "Y" Then
                                            strOut = strOut & snpSQLChildReason.Fields(j).Name & "" & vbCrLf
                                        End If
                                    Next j
                                    strOut = strOut & "**********" & vbCrLf
                                End If
                                snpSQLChildReason.Close
                            End If
                        End If

                        comSQLChildBind("sqlid") = strSQLSQLID
                        comSQLChildBind("childnumber") = CInt(Right(snpXPLAN(0), Len(snpXPLAN(0)) - (InStr(snpXPLAN(0), "child number ") + 12)))
                        Set snpSQLChildBind = comSQLChildBind.Execute

                        If Not (snpSQLChildBind Is Nothing) Then
                            If snpSQLChildBind.State = 1 Then
                                If Not (snpSQLChildBind.EOF) Then
                                    strOut = strOut & "Bind Variable Definitions" & vbCrLf
                                    Do While Not (snpSQLChildBind.EOF)
                                        strOut = strOut & "  Position:" & CStr(snpSQLChildBind("position"))
                                        strOut = strOut & "  Max Length:" & CStr(snpSQLChildBind("max_length"))
                                        Select Case snpSQLChildBind("datatype")
                                          Case 1
                                              strOut = strOut & "  VARCHAR2"
                                          Case 2
                                              strOut = strOut & "  NUMBER"
                                          Case 8
                                              strOut = strOut & "  LONG"
                                          Case 11
                                              strOut = strOut & "  ROWID"
                                          Case 12
                                              strOut = strOut & "  DATE"
                                          Case 23
                                              strOut = strOut & "  RAW"
                                          Case 24
                                              strOut = strOut & "  LONG RAW"
                                          Case 96
                                              strOut = strOut & "  CHAR"
                                          Case 112
                                              strOut = strOut & "  CLOB"
                                          Case 113
                                              strOut = strOut & "  BLOB"
                                          Case 114
                                              strOut = strOut & "  BFILE"
                                          Case Else
                                              strOut = strOut & "  TYPE " & CStr(snpSQLChildBind("datatype"))
                                        End Select
                                        strOut = strOut & "  Name:" & snpSQLChildBind("bind_name")
                                        strOut = strOut & "" & vbCrLf

                                        snpSQLChildBind.MoveNext
                                    Loop
                                    strOut = strOut & "**********" & vbCrLf
                                End If
                                snpSQLChildBind.Close
                            End If
                        End If
                    End If

                    If InStr(UCase(snpXPLAN(0)), "PLAN HASH VALUE:") = 1 Then
                        'Found the PLAN_HASH_VALUE
                        comSQLStats("sqlid") = strSQLSQLID
                        comSQLStats("plan_hash_value") = Val(Right(snpXPLAN(0), Len(snpXPLAN(0)) - InStr(snpXPLAN(0), ":")))
                        Set snpSQLStats = comSQLStats.Execute

                        If Not (snpSQLStats Is Nothing) Then
                            If snpSQLStats.State = 1 Then
                                If Not (snpSQLStats.EOF) Then
                                    If snpSQLStats("executions") > 0 Then
                                        strOut = strOut & "" & vbCrLf
                                        strOut = strOut & "Statistics for Execution Plan:" & vbCrLf
                                        strOut = strOut & "  Last Active: " & snpSQLStats("last_active_time") & vbCrLf
                                        strOut = strOut & "  Parses:                " & Format(Format(snpSQLStats("parse_calls"), "#,##0   "), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Executions:            " & Format(Format(snpSQLStats("executions"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Exec Per Parse: " & Format(Format(snpSQLStats("executions") / snpSQLStats("parse_calls"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  CPU Time:              " & Format(Format(snpSQLStats("cpu_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("cpu_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Elapsed Time:          " & Format(Format(snpSQLStats("elapsed_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("elapsed_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Application Wait Time: " & Format(Format(snpSQLStats("application_wait_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("application_wait_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Concurrency Wait Time: " & Format(Format(snpSQLStats("concurrency_wait_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("concurrency_wait_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  User IO Wait Time:     " & Format(Format(snpSQLStats("user_io_wait_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("user_io_wait_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Application Wait Time: " & Format(Format(snpSQLStats("application_wait_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("application_wait_time") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Cluster Wait Time:     " & Format(Format(snpSQLStats("cluster_wait_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("cluster_wait_time") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  PL/SQL Execute Time:   " & Format(Format(snpSQLStats("plsql_exec_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("plsql_exec_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Java Execution Time:   " & Format(Format(snpSQLStats("java_exec_time") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("java_exec_time") / snpSQLStats("executions") / 1000000, "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Buffer (Cons.) Gets:   " & Format(Format(snpSQLStats("buffer_gets"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("buffer_gets") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Disk (Block) Reads:    " & Format(Format(snpSQLStats("disk_reads"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("disk_reads") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Direct Writes:         " & Format(Format(snpSQLStats("direct_writes"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("direct_writes") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Rows Processed:        " & Format(Format(snpSQLStats("rows_processed"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("rows_processed") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Fetches:               " & Format(Format(snpSQLStats("fetches"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("fetches") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Loads:                 " & Format(Format(snpSQLStats("loads"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("loads") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf
                                        strOut = strOut & "  Invalidations:         " & Format(Format(snpSQLStats("invalidations"), "#,##0   "), "@@@@@@@@@@@@@@") _
                                            & "    Per Exec:       " & Format(Format(snpSQLStats("invalidations") / snpSQLStats("executions"), "#,##0.00"), "@@@@@@@@@@@@@@") & vbCrLf

                                        strOut = strOut & "" & vbCrLf
                                    End If
                                End If
                                snpSQLStats.Close
                            End If
                        End If
                    End If

                    If (InStr(snpXPLAN(0), "SQL_ID") > 0) And (InStr(snpXPLAN(0), "child number " & Format(intSQLChildNumber)) > 0) Then
                        intFlag = True
                        strOut = strOut & "Plan Used by the Session" & vbCrLf
                        strOut = strOut & String(100, "~") & vbCrLf
                        strOut = strOut & snpXPLAN(0) & vbCrLf
                        strOut = strOut & String(100, "~") & vbCrLf
                    Else
                        strOut = strOut & snpXPLAN(0) & vbCrLf
                    End If

                    snpXPLAN.MoveNext
                Loop
                snpXPLAN.Close
                If intFlag = True Then
                    strOut = strOut & String(100, "~") & vbCrLf
                End If
                strOut = strOut & vbCrLf
            End If
        End If

        Print #intFileNum, strOut
        Close #intFileNum
        Shell "notepad.exe C:\ExcelTimeModelViewer\DBMS_XPLAN.txt", vbNormalFocus
    End If
End Sub

Note that in the above code, if you are running Windows Vista or Window 7 with User Access Control enabled, you will need to replace all instances of C:\ExcelTimeModelViewer in the code with a writeable file location.

Press the F5 key to start up the execution of the UserForm.  You might need to toggle the chkPauseFresh CheckBox to allow the UserForm data to begin updating.  Just as an experiment, I decided to take a look at the execution plan for the SQL_ID that was identified for my Excel session.  The following is the output that was displayed on screen (in the Notepad application window):

****************************************************************************************************
Reason for Child Cursor Creation
**********
Plan Used by the Session
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
SQL_ID  6uw0vzxdsd8f8, child number 0
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
-------------------------------------
SELECT    S.SID,    S.SERIAL#,    S.STATUS,    NVL(S.USERNAME,' ')
USERNAME,    NVL(S.MACHINE,' ') MACHINE,    NVL(S.PROGRAM,' ') PROGRAM,
   NVL(S.SQL_ID,NVL(S.PREV_SQL_ID,' ')) SQL_ID,   
NVL(S.SQL_CHILD_NUMBER,NVL(S.PREV_CHILD_NUMBER,0)) SQL_CHILD_NUMBER,   
STM.VALUE,    STM.STAT_NAME  FROM    V$SESS_TIME_MODEL STM,   
V$SESSION S  WHERE    S.SID=STM.SID  ORDER BY    S.USERNAME,   
S.PROGRAM,    S.SID

Statistics for Execution Plan:
  Last Active: 3/15/2011 11:12:31 PM
  Parses:                         14  
  Executions:                     18       Exec Per Parse:           1.29
  CPU Time:                        0.06    Per Exec:                 0.00
  Elapsed Time:                    0.08    Per Exec:                 0.00
  Application Wait Time:           0.00    Per Exec:                 0.00
  Concurrency Wait Time:           0.00    Per Exec:                 0.00
  User IO Wait Time:               0.01    Per Exec:                 0.00
  Application Wait Time:           0.00    Per Exec:                 0.00
  Cluster Wait Time:               0.00    Per Exec:                 0.00
  PL/SQL Execute Time:             0.00    Per Exec:                 0.00
  Java Execution Time:             0.00    Per Exec:                 0.00
  Buffer (Cons.) Gets:           201       Per Exec:                11.17
  Disk (Block) Reads:              4       Per Exec:                 0.22
  Direct Writes:                   0       Per Exec:                 0.00
  Rows Processed:              8,170       Per Exec:               453.89
  Fetches:                        90       Per Exec:                 5.00
  Loads:                           2       Per Exec:                 0.11
  Invalidations:                   0       Per Exec:                 0.00

Plan hash value: 186343697

------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                    |       |       |     2 (100)|          |        |
|   1 |  SORT ORDER BY               |                    |   273 | 27846 |     2 (100)| 00:00:01 |        |
|*  2 |   HASH JOIN                  |                    |   273 | 27846 |     1 (100)| 00:00:01 |        |
|*  3 |    FIXED TABLE FULL          | X$KEWSSMAP         |    13 |   455 |     0   (0)|          |  OR112 |
|   4 |    NESTED LOOPS              |                    |  1604 |   104K|     0   (0)|          |        |
|   5 |     NESTED LOOPS             |                    |    24 |  1224 |     0   (0)|          |        |
|   6 |      NESTED LOOPS            |                    |    24 |   288 |     0   (0)|          |        |
|   7 |       FIXED TABLE FULL       | X$KSLWT            |    24 |   192 |     0   (0)|          |  OR112 |
|*  8 |       FIXED TABLE FIXED INDEX| X$KSLED (ind:2)    |     1 |     4 |     0   (0)|          |  OR112 |
|*  9 |      FIXED TABLE FIXED INDEX | X$KSUSE (ind:1)    |     1 |    39 |     0   (0)|          |  OR112 |
|* 10 |     FIXED TABLE FIXED INDEX  | X$KEWSSESV (ind:1) |    67 |  1072 |     0   (0)|          |  OR112 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("MAP"."SOFFST"="SESV"."KEWSNUM")
   3 - filter(("MAP"."AGGID"=1 AND INTERNAL_FUNCTION("MAP"."STYPE") AND
              "MAP"."INST_ID"=USERENV('INSTANCE')))
   8 - filter("W"."KSLWTEVT"="E"."INDX")
   9 - filter((BITAND("S"."KSUSEFLG",1)<>0 AND BITAND("S"."KSSPAFLG",1)<>0 AND
              "S"."INST_ID"=USERENV('INSTANCE') AND "S"."INDX"="W"."KSLWTSID"))
  10 - filter((BITAND("SESV"."KSUSEFLG",1)<>0 AND BITAND("SESV"."KSSPAFLG",1)<>0 AND
              "S"."INDX"="SESV"."KSUSENUM"))

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

****************************************************************************************************
Reason for Child Cursor Creation
STATS_ROW_MISMATCH
**********
SQL_ID  6uw0vzxdsd8f8, child number 1
-------------------------------------
SELECT    S.SID,    S.SERIAL#,    S.STATUS,    NVL(S.USERNAME,' ')
USERNAME,    NVL(S.MACHINE,' ') MACHINE,    NVL(S.PROGRAM,' ') PROGRAM,
   NVL(S.SQL_ID,NVL(S.PREV_SQL_ID,' ')) SQL_ID,   
NVL(S.SQL_CHILD_NUMBER,NVL(S.PREV_CHILD_NUMBER,0)) SQL_CHILD_NUMBER,   
STM.VALUE,    STM.STAT_NAME  FROM    V$SESS_TIME_MODEL STM,   
V$SESSION S  WHERE    S.SID=STM.SID  ORDER BY    S.USERNAME,   
S.PROGRAM,    S.SID

Statistics for Execution Plan:
  Last Active: 3/15/2011 11:12:31 PM
  Parses:                         14  
  Executions:                     18       Exec Per Parse:           1.29
  CPU Time:                        0.06    Per Exec:                 0.00
  Elapsed Time:                    0.08    Per Exec:                 0.00
  Application Wait Time:           0.00    Per Exec:                 0.00
  Concurrency Wait Time:           0.00    Per Exec:                 0.00
  User IO Wait Time:               0.01    Per Exec:                 0.00
  Application Wait Time:           0.00    Per Exec:                 0.00
  Cluster Wait Time:               0.00    Per Exec:                 0.00
  PL/SQL Execute Time:             0.00    Per Exec:                 0.00
  Java Execution Time:             0.00    Per Exec:                 0.00
  Buffer (Cons.) Gets:           201       Per Exec:                11.17
  Disk (Block) Reads:              4       Per Exec:                 0.22
  Direct Writes:                   0       Per Exec:                 0.00
  Rows Processed:              8,170       Per Exec:               453.89
  Fetches:                        90       Per Exec:                 5.00
  Loads:                           2       Per Exec:                 0.11
  Invalidations:                   0       Per Exec:                 0.00

Plan hash value: 186343697

------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Inst   |
------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                    |       |       |     2 (100)|          |        |
|   1 |  SORT ORDER BY               |                    |   273 | 27846 |     2 (100)| 00:00:01 |        |
|*  2 |   HASH JOIN                  |                    |   273 | 27846 |     1 (100)| 00:00:01 |        |
|*  3 |    FIXED TABLE FULL          | X$KEWSSMAP         |    13 |   455 |     0   (0)|          |  OR112 |
|   4 |    NESTED LOOPS              |                    |  1604 |   104K|     0   (0)|          |        |
|   5 |     NESTED LOOPS             |                    |    24 |  1224 |     0   (0)|          |        |
|   6 |      NESTED LOOPS            |                    |    24 |   288 |     0   (0)|          |        |
|   7 |       FIXED TABLE FULL       | X$KSLWT            |    24 |   192 |     0   (0)|          |  OR112 |
|*  8 |       FIXED TABLE FIXED INDEX| X$KSLED (ind:2)    |     1 |     4 |     0   (0)|          |  OR112 |
|*  9 |      FIXED TABLE FIXED INDEX | X$KSUSE (ind:1)    |     1 |    39 |     0   (0)|          |  OR112 |
|* 10 |     FIXED TABLE FIXED INDEX  | X$KEWSSESV (ind:1) |    67 |  1072 |     0   (0)|          |  OR112 |
------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("MAP"."SOFFST"="SESV"."KEWSNUM")
   3 - filter(("MAP"."AGGID"=1 AND INTERNAL_FUNCTION("MAP"."STYPE") AND
              "MAP"."INST_ID"=USERENV('INSTANCE')))
   8 - filter("W"."KSLWTEVT"="E"."INDX")
   9 - filter((BITAND("S"."KSUSEFLG",1)<>0 AND BITAND("S"."KSSPAFLG",1)<>0 AND
              "S"."INST_ID"=USERENV('INSTANCE') AND "S"."INDX"="W"."KSLWTSID"))
  10 - filter((BITAND("SESV"."KSUSEFLG",1)<>0 AND BITAND("SESV"."KSSPAFLG",1)<>0 AND
              "S"."INDX"="SESV"."KSUSENUM"))

If you examine the above, you will notice that the output from V$SQLSTATS is identical for both of the child cursors – that is because the PLAN_HASH_VALUE is identical for both of the child cursors.

Where do we head next with the project?  I am a person who prefers looking at raw numbers, but maybe someone reading this blog prefers pictures?

Added August 11, 2011:

The Excel project code to this point, save with a .XLS extension (currently has a .DOC extension, please change):
TimeModelViewerExcelArticle5.xls


Actions

Information

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 140 other followers

%d bloggers like this: