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
Charles Hooper's Oracle Notes 
Leave a comment