Investigating Enqueues Burns CPU Cycles

March 30, 2011

If you take a look at the Oracle Database Performance Tuning Guide, you will find the following SQL statement to help identify the session waiting in an enqueue and the session that currently prevents that session from continuing:

SELECT DECODE(request,0,'Holder: ','Waiter: ') ||
          sid sess, id1, id2, lmode, request, type
   FROM V$LOCK
 WHERE (id1, id2, type) IN (SELECT id1, id2, type FROM V$LOCK WHERE request > 0)
   ORDER BY id1, request; 

If you look closely, you will see that the version of the query that appeared in the 11.1 release of the Performance Tuning Guide differs a little from what appeared in the 9.0.1 Performance Tuning Guide:

SELECT DECODE(request,0,'Holder: ','Waiter: ')||sid sess
     , id1, id2, lmode, request, type
  FROM V$LOCK
 WHERE (id1, id2, type) IN
             (SELECT id1, id2, type FROM V$LOCK WHERE lmode = 0)
 ORDER BY id1, request; 

The above SQL statements (at least the first one) are helpful, but it might be nice to know a little more about the sessions that are involved in the enqueue wait.  So, you might modify the SQL statement like this (feel free to replace SQL_HASH_VALUE with SQL_ID if you are running Oracle Database 10.1 or greater):

SELECT
  S.SID,
  S.USERNAME,
  S.PROGRAM,
  S.SQL_HASH_VALUE,
  L.REQUEST,
  L.ID1,
  L.ID2,
  L.LMODE,
  L.TYPE,
  L.BLOCK
FROM
  V$LOCK L,
  V$SESSION S
WHERE
  (L.ID1, L.ID2, L.TYPE) IN
  (SELECT
    ID1,
    ID2,
    TYPE
  FROM
    V$LOCK
  WHERE
    REQUEST > 0)
  AND L.SID=S.SID; 

Sometimes helpful is too helpful.  Assume that the above SQL statement is scripted to execute once an hour, once a minute, once a second, or multiple times per second.  What will happen?  Well, you could obtain useful information… but at a cost (we will take a look at that later).  Since we are assuming that the above SQL statement will be scripted, we could possibly use a SQL statement similar to the following, and if any rows are returned we could execute the more useful SQL statement above:

SELECT
  ID1,
  ID2,
  TYPE
FROM
  V$LOCK
WHERE
  REQUEST > 0; 

Another option would be to take advantage of an enhancement added to Oracle Database 10.1 – a couple of additional columns in V$SESSION, specifically the columns BLOCKING_SESSION and BLOCKING_SESSION_STATUS.  With the help of those columns, we could query V$SESSION and then if any rows are returned, use the enhanced version of the above query that returns the lock TYPE.  The SQL statement that would use the two columns from V$SESSION might look like this:

SELECT
  SID,
  BLOCKING_SESSION,
  BLOCKING_SESSION_STATUS
FROM
  V$SESSION
WHERE
  BLOCKING_SESSION IS NOT NULL; 

But now we have a problem.  We have three potential solutions, but no clue which approach will work most efficiently.  We could throw together a PL/SQL loop to help test the performance, but there is a chance that approach will yield performance results that are different from a solution that submits the SQL statements from a client-side application (or script).  But there is a simple solution: create the TEMP_STAT temporary table from the previous article, and then try the following script when several sessions (I used roughly 300) are connected to the database instance (as with previous scripts, replace MyDB, MyUser, and MyPassword with appropriate values:

Const adCmdText = 1
Const adCmdStoredProc = 4
Const adParamInput = 1
Const adVarNumeric = 139
Const adBigInt = 20
Const adDecimal = 14
Const adDouble = 5
Const adInteger = 3
Const adLongVarBinary = 205
Const adNumeric = 131
Const adSingle = 4
Const adSmallInt = 2
Const adTinyInt = 16
Const adUnsignedBigInt = 21
Const adUnsignedInt = 19
Const adUnsignedSmallInt = 18
Const adUnsignedTinyInt = 17
Const adDate = 7
Const adDBDate = 133
Const adDBTimeStamp = 135
Const adDBTime = 134
Const adVarChar = 200
Const adUseClient = 3
Const adOpenKeyset = 1
Const adLockOptimistic = 3

Dim i
Dim lngCntLast
Dim strSQL
Dim snpDataLock1
Dim comDataLock1
Dim snpDataLock2
Dim comDataLock2
Dim snpDataLock3
Dim comDataLock3
Dim comDataInsert
Dim dbDatabase
Dim snpData
Dim objFSO
Dim objFileLog

Dim strDatabase
Dim strUsername
Dim strPassword

Set snpDataLock1 = CreateObject("ADODB.Recordset")
Set comDataLock1 = CreateObject("ADODB.Command")
Set snpDataLock2 = CreateObject("ADODB.Recordset")
Set comDataLock2 = CreateObject("ADODB.Command")
Set snpDataLock3 = CreateObject("ADODB.Recordset")
Set comDataLock3 = CreateObject("ADODB.Command")
Set comDataInsert = CreateObject("ADODB.Command")
Set dbDatabase = CreateObject("ADODB.Connection")
Set snpData = CreateObject("ADODB.Recordset")

strDatabase = "MyDB"
strUsername = "MyUser"
strPassword = "MyPassword"

'Connect to the database
'Oracle connection string
dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";ChunkSize=1000;FetchSize=100;"

dbDatabase.ConnectionTimeout = 40
dbDatabase.CursorLocation = adUseClient
dbDatabase.open

dbDatabase.BeginTrans

With comDataLock1
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  S.SID," & vbCrLf
    strSQL = strSQL & "  S.USERNAME," & vbCrLf
    strSQL = strSQL & "  S.PROGRAM," & vbCrLf
    strSQL = strSQL & "  S.SQL_HASH_VALUE," & vbCrLf
    strSQL = strSQL & "  L.REQUEST," & vbCrLf
    strSQL = strSQL & "  L.ID1," & vbCrLf
    strSQL = strSQL & "  L.ID2," & vbCrLf
    strSQL = strSQL & "  L.LMODE," & vbCrLf
    strSQL = strSQL & "  L.TYPE," & vbCrLf
    strSQL = strSQL & "  L.BLOCK" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$LOCK L," & vbCrLf
    strSQL = strSQL & "  V$SESSION S" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  (L.ID1, L.ID2, L.TYPE) IN " & vbCrLf
    strSQL = strSQL & "  (SELECT" & vbCrLf
    strSQL = strSQL & "    ID1," & vbCrLf
    strSQL = strSQL & "    ID2," & vbCrLf
    strSQL = strSQL & "    TYPE" & vbCrLf
    strSQL = strSQL & "  FROM" & vbCrLf
    strSQL = strSQL & "    V$LOCK" & vbCrLf
    strSQL = strSQL & "  WHERE" & vbCrLf
    strSQL = strSQL & "    REQUEST > 0)" & vbCrLf
    strSQL = strSQL & "  AND L.SID=S.SID"

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

    .ActiveConnection = dbDatabase
End With

With comDataLock2
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  ID1," & vbCrLf
    strSQL = strSQL & "  ID2," & vbCrLf
    strSQL = strSQL & "  TYPE" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$LOCK" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  REQUEST > 0"

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

    .ActiveConnection = dbDatabase
End With

With comDataLock3
    strSQL = "SELECT" & vbCrLf
    strSQL = strSQL & "  SID," & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION," & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION_STATUS" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$SESSION" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  BLOCKING_SESSION IS NOT NULL"

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

    .ActiveConnection = dbDatabase
End With

With comDataInsert
    strSQL = "INSERT INTO TEMP_STAT" & vbCrLf
    strSQL = strSQL & "SELECT" & vbCrLf
    strSQL = strSQL & "  ? CNT," & vbCrLf
    strSQL = strSQL & "  SN.NAME," & vbCrLf
    strSQL = strSQL & "  MS.VALUE" & vbCrLf
    strSQL = strSQL & "FROM" & vbCrLf
    strSQL = strSQL & "  V$STATNAME SN," & vbCrLf
    strSQL = strSQL & "  V$MYSTAT MS" & vbCrLf
    strSQL = strSQL & "WHERE" & vbCrLf
    strSQL = strSQL & "  SN.STATISTIC#=MS.STATISTIC#" & vbCrLf
    strSQL = strSQL & "  AND SN.NAME IN (" & vbCrLf
    strSQL = strSQL & "    'CPU used by this session'," & vbCrLf
    strSQL = strSQL & "    'consistent gets'," & vbCrLf
    strSQL = strSQL & "    'parse count (total)'," & vbCrLf
    strSQL = strSQL & "    'DB time')"

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

    .ActiveConnection = dbDatabase

    .Parameters.Append .CreateParameter("cnt", adNumeric, adParamInput, 8 )
End With

comDataInsert("cnt") = 0
comDataInsert.Execute
'Before
comDataInsert("cnt") = 1
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock1 = comDataLock1.Execute

    If Not (snpDataLock1 Is Nothing) Then
        If Not (snpDataLock1.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock1.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 2
comDataInsert.Execute

'Before
comDataInsert("cnt") = 3
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock2 = comDataLock2.Execute

    If Not (snpDataLock2 Is Nothing) Then
        If Not (snpDataLock2.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock2.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 4
comDataInsert.Execute

'Before
comDataInsert("cnt") = 5
comDataInsert.Execute
For i = 1 To 1000
    Set snpDataLock3 = comDataLock3.Execute

    If Not (snpDataLock3 Is Nothing) Then
        If Not (snpDataLock3.EOF) Then
            'Found one
        Else
            'Did not have a lock
        End If
        snpDataLock3.Close
    End If

    WScript.Sleep 200
Next
'After
comDataInsert("cnt") = 6
comDataInsert.Execute

strSQL = "SELECT" & vbCrLf
strSQL = strSQL & "  TS2.CNT," & vbCrLf
strSQL = strSQL & "  TS2.NAME," & vbCrLf
strSQL = strSQL & "  TS2.VALUE-TS1.VALUE DELTA" & vbCrLf
strSQL = strSQL & "FROM" & vbCrLf
strSQL = strSQL & "  TEMP_STAT TS1," & vbCrLf
strSQL = strSQL & "  TEMP_STAT TS2" & vbCrLf
strSQL = strSQL & "WHERE" & vbCrLf
strSQL = strSQL & "  TS2.CNT=TS1.CNT+1" & vbCrLf
strSQL = strSQL & "  AND TS2.NAME=TS1.NAME" & vbCrLf
strSQL = strSQL & "ORDER BY" & vbCrLf
strSQL = strSQL & "  TS2.CNT," & vbCrLf
strSQL = strSQL & "  TS2.NAME"

Set objFSO = CreateObject("Scripting.FileSystemObject")
Set objFileLog = objFSO.CreateTextFile("C:\LockResourceResults.txt", True)

snpData.open strSQL, dbDatabase
lngCntLast = 0
Do While Not snpData.EOF
    If lngCntLast <> CLng(snpData("cnt")) Then
        lngCntLast = CLng(snpData("cnt"))
        Select Case lngCntLast
            Case 2
                objFileLog.Write vbCrLf & "Full Lock Query with BLOCKED and BLOCKER" & vbCrLf

            Case 4
                objFileLog.Write vbCrLf & "Query of V$LOCK" & vbCrLf

            Case 6
                objFileLog.Write vbCrLf & "Query of V$SESSION" & vbCrLf
        End Select
    End If

    Select Case lngCntLast
        Case 2, 4, 6
            objFileLog.Write "  " & CStr(snpData("name")) & "   " & CStr(snpData("delta")) & vbCrLf
    End Select
    snpData.MoveNext
Loop
snpData.Close
objFileLog.Close

dbDatabase.CommitTrans 

The above script executes each of the three possible solutions 1,000 times, pausing 0.2 seconds between each execution.  Once the test is complete, the test results are written to a text file named C:\LockResourceResults.txt.  I executed the above script (at least) three times, and these are the results that I received for three test executions (note that the results from the tests are not necessarily displayed in the order of execution):

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   13153
  DB time                    13159
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session    1475
  DB time                     1478
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session      66
  DB time                       66
  consistent gets                0
  parse count (total)         1000 

 

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   12526
  DB time                    12531
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session     881
  DB time                      870
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session      17
  DB time                       21
  consistent gets                2
  parse count (total)         1001 

 

Full Lock Query with BLOCKED and BLOCKER
  CPU used by this session   13157
  DB time                    13216
  consistent gets                0
  parse count (total)         1000

Query of V$LOCK
  CPU used by this session    1368
  DB time                     1369
  consistent gets                0
  parse count (total)         1000

Query of V$SESSION
  CPU used by this session     331
  DB time                      340
  consistent gets                0
  parse count (total)         1000 

Just looking at the first resultset of results, 131.53 CPU seconds consumed for the first approach compared to 14.75 CPU seconds for the second approach, and 0.66 CPU seconds for the third approach.  Obviously, the first approach is the best, because it would probably take an extra 5 minutes to code in the logic to see if the SQL statement used in the third approach returned any rows, and if it did to execute the SQL statement used in the first approach – if you don’t use the CPU cycles, you lose them forever.  :-)

Sequence Driven Primary Keys – Which is Better: Call NextVal in the Insert Statement or in a Row Level Trigger?

March 25, 2011 (Updated March 26, 2011)

Occasionally, I see interesting questions being asked about Oracle Database, and it is nice when the person asking the question provides a test case – or at the very least the DDL and DML statements needed to recreate an environment that matches the question.  The question that was asked in this instance is whether or not it is true that calling an Oracle sequence’s NEXTVAL property directly in an INSERT statement is faster/more efficient than relying on a row level trigger to set the primary key value from the Oracle sequence’s NEXTVAL property.  Just as important, a secondary question of “why” was asked.

A slightly modified version of the test script follows:

CREATE TABLE ST ( C1 NUMBER PRIMARY KEY, C2 VARCHAR2(20) );
CREATE SEQUENCE S1 START WITH 1 CACHE 1000;

CREATE OR REPLACE TRIGGER TR1
    BEFORE INSERT
    ON ST
    REFERENCING NEW AS NEW
    FOR EACH ROW
    BEGIN
    SELECT S1.NEXTVAL INTO :NEW.C1 FROM DUAL;
    END;
/   

SET TIMING ON

BEGIN
INSERT INTO ST(C2)
SELECT
     RPAD('A',11,'A')
  FROM
    DUAL
  CONNECT BY
    LEVEL <= 100000;
END;
/   

COMMIT;   

CREATE TABLE NVT ( C1 NUMBER PRIMARY KEY, C2 VARCHAR2(20));
CREATE SEQUENCE S2;

SET TIMING ON

BEGIN
INSERT INTO NVT(C1,C2)
SELECT S2.NEXTVAL,
     RPAD('A',11,'A')
  FROM
    DUAL
  CONNECT BY
    LEVEL <= 100000;
END;
/   

COMMIT;

DROP TABLE ST PURGE;
DROP TABLE NVT PURGE;
DROP SEQUENCE S1;
DROP SEQUENCE S2; 

The above appears to be a good starting point to determine if there is a difference in performance, and by roughly how much the elapsed time will be affected.  So, what were the timing results of the above script?

Row Level Trigger:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO ST(C2)
  3  SELECT
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 100000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:04.24  

Directly Calling NEXTVAL in the INSERT Statement:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO NVT(C1,C2)
  3  SELECT S2.NEXTVAL,
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 100000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.82  

Not too bad, 5.17 times faster in this particular test database (only 3.17 times faster in another ~ 7.79 seconds compared to 2.46 seconds) when directly accessing the sequence’s NEXTVAL property in the INSERT statement.  Is this a fair test case?  Take another look at the two sequence definitions.  Notice that the first sequence that is used by the trigger has a CACHE size of 1,000 while the second sequence has the default cache size of 20.  Does that really matter?  Let’s test to find out.  The replacement creation statement for the S2 sequence will be changed like this:

CREATE SEQUENCE S2 START WITH 1 CACHE 1000; 

Row Level Trigger:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO ST(C2)
  3  SELECT
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 100000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:04.32 

Directly Calling NEXTVAL in the INSERT Statement:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO NVT(C1,C2)
  3  SELECT S2.NEXTVAL,
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 100000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.40 

That helped to level the playing field a bit, now the direct method is 10.8 times faster than the row level trigger (only 7.29 times faster in another database instance ~ 7.73 seconds compared to 1.06 seconds).

There might still be a couple of questions about the test case – is it a fair test?  What if we increase the number of rows inserted by a factor of 10 (append another 0 on the number specified in the CONNECT BY LEVEL clause) and use the original script with the (originally specified) different CACHE values for the sequences?  Let’s take a look at the results:

Row Level Trigger:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO ST(C2)
  3  SELECT
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 1000000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:42.63 

Directly Calling NEXTVAL in the INSERT Statement:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO NVT(C1,C2)
  3  SELECT S2.NEXTVAL,
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 1000000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:08.08 

This change to the test case seemed to scale nearly linearly, 5.28 times faster in this particular test database (only 3.29 times faster in another database instance ~ 81.23 seconds compared to 24.70 seconds).   Let’s fix the sequence defiition for the second sequence and try the test again:

Row Level Trigger:

SQL> BEGIN
  2  INSERT INTO ST(C2)
  3  SELECT
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 1000000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:42.24 

Directly Calling NEXTVAL in the INSERT Statement:

SQL> SET TIMING ON
SQL>
SQL> BEGIN
  2  INSERT INTO NVT(C1,C2)
  3  SELECT S2.NEXTVAL,
  4       RPAD('A',11,'A')
  5    FROM
  6      DUAL
  7    CONNECT BY
  8      LEVEL <= 1000000;
  9  END;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.93 

Once again, having a suitable CACHE value for the sequence helped.  Now the direct method of specifying the primary key value is 10.75 times faster than the row level trigger (only 7.86 times faster in another database instance ~ 80.64 seconds compared to 10.26 seconds).

Are there still minor issues with the test case?  Possibly – how often are rows normally inserted into production database tables using the CONNECT BY LEVEL syntax?  Maybe expanding the test case to use an INSERT INTO … SELECT type syntax would help further differentiate the two approaches.  Maybe expanding the test case to use 100,000 single row INSERT statements would be a reasonable reflection of a real-world test?  Maybe expanding the test case to include other operating system platforms would show a more significant difference in performance (the above test cases were performed on 64 bit Windows – context switching is typically less severe on Windows)?  Maybe expanding the test case to include other Oracle Database release versions would show different performance results (the above test cases were performed on Oracle Database 11.2.0.2 and 10.2.0.2)?  What about the monitoring the differences in the session’s CPU (or other resource) consumption?  What about monitoring the differences when multiple sessions concurrently perform inserts?

I do not have the complete answer why the method using the sequence’s NEXTVAL property in the INSERT statement is 10 times faster.  Context switching due to the row level trigger is certainly part of the cause, and I believe that is part of the reason for the longer execution time with the row level trigger.  What else could impact the execution time?  Think about some of the extra bits of low-level program instruction code that Oracle Database must execute to set up the PL/SQL environment so that the values that are to be inserted are copied into the NEW object.  Then the execution of the trigger code needs to open a cursor (with an initial hard parse, and the rest of the uses likely coming from the session’s cached cursors) to return the value of S1.NEXTVAL into the NEW object, add the cursor to the session’s cached cursors, and finally transfer the NEW object values into rows in the table blocks.  Think about what extra low-level program instruction code we simply avoid by just telling Oracle Database to fetch the S2.NEXTVAL value from the server’s memory.

Anyone else have a better explanation for the performance difference between the two methods of populating the primary key values?  Are there any good reasons why someone should use the row level trigger method to populate the primary key values?

———

Added March 26, 2011 in response to Narendra’s test case that is attached to this article.

I thought that it might be interesting to look at how changing from the CONNECT BY LEVEL syntax to single row inserts would affect the elapsed time, CPU utilization, redo generation, and number of current mode block gets.  As you will see, there is not a straight-forward answer – the effects are different for different Oracle release versions.  Here is the script that will be used:

SET ECHO ON

CREATE GLOBAL TEMPORARY TABLE TEMP_STAT ON COMMIT PRESERVE ROWS AS
SELECT
  0 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

CREATE TABLE T1 ( C1 NUMBER PRIMARY KEY, C2 VARCHAR2(20) );
CREATE SEQUENCE T1_SEQUENCE START WITH 1 CACHE 1000;

CREATE OR REPLACE TRIGGER T1_TRIGGER
    BEFORE INSERT
    ON T1
    REFERENCING NEW AS NEW
    FOR EACH ROW
    BEGIN
    SELECT T1_SEQUENCE.NEXTVAL INTO :NEW.C1 FROM DUAL;
    END;
/  

CREATE TABLE T2 ( C1 NUMBER PRIMARY KEY, C2 VARCHAR2(20));
CREATE SEQUENCE T2_SEQUENCE START WITH 1 CACHE 1000;

SET TIMING ON

INSERT INTO TEMP_STAT
SELECT
  1 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

DECLARE
  V VARCHAR2(11);
BEGIN
  V := RPAD('A',11,'A');
  FOR I IN 1 .. 1000000 LOOP
    INSERT INTO T1(C2) VALUES (V);
  END LOOP;
END;
/  

INSERT INTO TEMP_STAT
SELECT
  2 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

TRUNCATE TABLE T1;

INSERT INTO TEMP_STAT
SELECT
  3 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

BEGIN
INSERT INTO T1(C2)
  SELECT
     RPAD('A',11,'A')
  FROM
    DUAL
  CONNECT BY
    LEVEL <= 1000000;
END;
/

INSERT INTO TEMP_STAT
SELECT
  4 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

COMMIT;  

SET TIMING ON

INSERT INTO TEMP_STAT
SELECT
  5 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

DECLARE
  V VARCHAR2(11);
BEGIN
  V := RPAD('A',11,'A');
  FOR I IN 1 .. 1000000 LOOP
    INSERT INTO T2(C1,C2) VALUES (T2_SEQUENCE.NEXTVAL,V);
  END LOOP;
END;
/  

INSERT INTO TEMP_STAT
SELECT
  6 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

TRUNCATE TABLE T2;

INSERT INTO TEMP_STAT
SELECT
  7 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

BEGIN
INSERT INTO T2(C1,C2)
SELECT T2_SEQUENCE.NEXTVAL,
     RPAD('A',11,'A')
  FROM
    DUAL
  CONNECT BY
    LEVEL <= 1000000;
END;
/

INSERT INTO TEMP_STAT
SELECT
  8 CNT,
  SN.NAME,
  MS.VALUE
FROM
  V$STATNAME SN,
  V$MYSTAT MS
WHERE
  SN.STATISTIC#=MS.STATISTIC#
  AND SN.NAME IN ('CPU used by this session','consistent gets','db block gets','parse count (hard)','parse count (total)','recursive calls','redo size','DB time');

COMMIT;

DROP TABLE T1 PURGE;
DROP TABLE T2 PURGE;
DROP SEQUENCE T1_SEQUENCE;
DROP SEQUENCE T2_SEQUENCE;

COLUMN NAME FORMAT A28
COLUMN DELTA FORMAT 999,999,990
SET PAGESIZE 1000

SELECT
  TS2.CNT,
  TS2.NAME,
  TS2.VALUE-TS1.VALUE DELTA
FROM
  TEMP_STAT TS1,
  TEMP_STAT TS2
WHERE
  TS2.CNT=TS1.CNT+1
  AND TS2.NAME=TS1.NAME
ORDER BY
  TS2.CNT,
  TS2.NAME;

TRUNCATE TABLE TEMP_STAT; 

As you can see from the script, the script will periodically capture several statistics to a global temporary table, and at the end it will output the delta values of the statistics.  From the delta values, we will be interested in the statistics from CNT 2 (SINGLE ROW WITH TRIGGER), CNT 4 (CONNECT BY WITH TRIGGER), CNT 6 (SINGLE ROW WITHOUT TRIGGER), and CNT 8 (CONNECT BY WITHOUT TRIGGER).

I executed the script on Oracle Database 10.2.0.5 (64 bit Windows), 11.1.0.7 (64 bit Windows), 11.2.0.1 (64 bit Windows), 11.1.0.6 (64 bit Linux), and 11.2.0.1 (64 bit Linux) using a systems with identical hardware for both operating system platforms.  I also executed the script on 11.2.0.2 (64 bit Windows – different server #2), and 10.2.0.2 (64 bit Windows – different server #3).  The results were interesting – take a close look at the results for 11.1.0.6 running on 64 bit Linux:

Nested Loops Join – the Smaller Table is the Driving Table, the Larger Table is the Driving Table

March 21, 2011

I occasionally see discussions about Oracle Database behavior that make me wonder… is it true, can I generate a test case that validates the statement, and just as important, can I generate a test case that refutes the statement.  An interesting question was posted the the OTN forums regarding apparently conflicting advice that the original posted had received regarding which table the Oracle Database’s optimizer would select as the driving table in a nested loops join; if there is a large table and a small table to be joined by nested loops, which will be the driving (outer) table?  Jonathan Lewis provided a good deal of insight in the thread, indicating that the optimizer’s decision is not as clear cut as suggested by the OP’s sources.

Not as clear cut as the optimizer always selects the smaller table as the driving (outer) table?  Maybe the documentation is able to provide a little more insight into the topic:

“The optimizer uses nested loop joins when joining small number of rows, with a good driving condition between the two tables. You drive from the outer loop to the inner loop, so the order of tables in the execution plan is important.

The outer loop is the driving row source. It produces a set of rows for driving the join condition. The row source can be a table accessed using an index scan or a full table scan. Also, the rows can be produced from any other operation. For example, the output from a nested loop join can be used as a row source for another nested loop join.

The inner loop is iterated for every row returned from the outer loop, ideally by an index scan. If the access path for the inner loop is not dependent on the outer loop, then you can end up with a Cartesian product; for every iteration of the outer loop, the inner loop produces the same set of rows. Therefore, you should use other join methods when two independent row sources are joined together.”

I guess that helps a little – the driving table (or row source) is the outer table, and the inner table (or row source) is checked for every row returned by the driving table (after the specified filter predicates are applied to the driving table).  However, the documentation does not explicitly state that the outer table must be the smaller table.  Let’s check a couple of books:

• “Oracle Internals: Tips, Tricks, and Techniques for DBAs“
• “Oracle 9i Development by Example”
• “Oracle 9i R2 Data Warehousing”
• “Oracle SQL Tuning & CBO Internals”
• “Oracle 9i Performance Tuning Tips & Techniques”
• “Pro Oracle SQL”

The books were mostly in agreement, except for the last two.  Since it appears that there might be some disagreement whether the smaller table is selected by the optimizer as the driving table or the larger table is selected by the optimizer as the driving table, we need a test case (as repeatedly requested as evidence by Sean in the OTN thread). 

The following noworkload system statistics will be used:

SELECT
  PNAME,
  PVAL1
FROM
  SYS.AUX_STATS$
ORDER BY
  PNAME;

PNAME                PVAL1
--------------- ----------
CPUSPEED
CPUSPEEDNW      2116.57559
DSTART
DSTOP
FLAGS                    1
IOSEEKTIM               10
IOTFRSPEED            4096
MAXTHR
MBRC
MREADTIM
SLAVETHR
SREADTIM
STATUS 

First the tables.  We will start simple, with one table (T3) having 100 rows and another table (T4) having 10 rows:

CREATE TABLE T3 (
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 VARCHAR2(20),
  PADDING VARCHAR2(200));

CREATE TABLE T4 (
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 VARCHAR2(20),
  PADDING VARCHAR2(200));

INSERT INTO
  T3
SELECT
  ROWNUM C1,
  1000000-ROWNUM C2,
  MOD(ROWNUM-1,1000) C3,
  TO_CHAR(SYSDATE+MOD(ROWNUM-1,10000),'DAY') C4,
  LPAD(' ',200,'A') PADDING
FROM
  DUAL
CONNECT BY
  LEVEL<=100;

INSERT INTO
  T4
SELECT
  ROWNUM C1,
  1000000-ROWNUM C2,
  MOD(ROWNUM-1,1000) C3,
  TO_CHAR(SYSDATE+MOD(ROWNUM-1,10000),'DAY') C4,
  LPAD(' ',200,'A') PADDING
FROM
  DUAL
CONNECT BY
  LEVEL<=10;

COMMIT;

CREATE INDEX IND_T3_C1 ON T3(C1);
CREATE INDEX IND_T3_C2 ON T3(C2);
CREATE INDEX IND_T3_C3 ON T3(C3);

CREATE INDEX IND_T4_C1 ON T4(C1);
CREATE INDEX IND_T4_C2 ON T4(C2);
CREATE INDEX IND_T4_C3 ON T4(C3);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL) 

We are able to easily produce an example where the “smallest” table is selected as the driving table (note that I had to add a hint to specify a nested loop join in several of these examples):

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT /*+ USE_NL(T3 T4) */
  T3.C1,
  T3.C2,
  T3.C3,
  T3.C4,
  T4.C1,
  T4.C2,
  T4.C3,
  T4.C4
FROM
  T3,
  T4
WHERE
  T3.C1=T4.C1;

Execution Plan
----------------------------------------------------------
Plan hash value: 567778651

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |    10 |   420 |    13   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                |           |       |       |            |          |
|   2 |   NESTED LOOPS               |           |    10 |   420 |    13   (0)| 00:00:01 |
|   3 |    TABLE ACCESS FULL         | T4        |    10 |   210 |     3   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN          | IND_T3_C1 |     1 |       |     0   (0)| 00:00:01 |
|   5 |   TABLE ACCESS BY INDEX ROWID| T3        |     1 |    21 |     1   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T3"."C1"="T4"."C1") 

If we stop at that point, we could declare quite simply that the optimizer selects the smaller table as the driving table.  But wait a minute, take a look at this example where the optimizer selected the largest table as the driving table:

SELECT /*+ USE_NL(T3 T4) */
  T3.C1,
  T3.C2,
  T3.C3,
  T3.C4,
  T4.C1,
  T4.C2,
  T4.C3,
  T4.C4
FROM
  T3,
  T4
WHERE
  T3.C1=T4.C1
  AND T3.C2=1;

Execution Plan
----------------------------------------------------------
Plan hash value: 4214127300

-------------------------------------------------------------------------------------------
| Id  | Operation                     | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |           |     1 |    42 |     3   (0)| 00:00:01 |
|   1 |  NESTED LOOPS                 |           |       |       |            |          |
|   2 |   NESTED LOOPS                |           |     1 |    42 |     3   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T3        |     1 |    21 |     2   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | IND_T3_C2 |     1 |       |     1   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN           | IND_T4_C1 |     1 |       |     0   (0)| 00:00:01 |
|   6 |   TABLE ACCESS BY INDEX ROWID | T4        |     1 |    21 |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T3"."C2"=1)
   5 - access("T3"."C1"="T4"."C1") 

The above execution plans were generated on 11.2.0.2, which sometimes differs a bit from older Oracle Database release versions when nested loops joins are used (note the two nested loops joins), however we are able to hint the optimizer to generate the older style nested loops join:

SELECT /*+ USE_NL(T3 T4) OPTIMIZER_FEATURES_ENABLE('10.2.0.4') */
  T3.C1,
  T3.C2,
  T3.C3,
  T3.C4,
  T4.C1,
  T4.C2,
  T4.C3,
  T4.C4
FROM
  T3,
  T4
WHERE
  T3.C1=T4.C1;

Execution Plan
----------------------------------------------------------
Plan hash value: 2465588182

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |    10 |   420 |    13   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T3        |     1 |    21 |     1   (0)| 00:00:01 |
|   2 |   NESTED LOOPS              |           |    10 |   420 |    13   (0)| 00:00:01 |
|   3 |    TABLE ACCESS FULL        | T4        |    10 |   210 |     3   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN         | IND_T3_C1 |     1 |       |     0   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T3"."C1"="T4"."C1") 

 

SELECT /*+ USE_NL(T3 T4) OPTIMIZER_FEATURES_ENABLE('10.2.0.4') */
  T3.C1,
  T3.C2,
  T3.C3,
  T3.C4,
  T4.C1,
  T4.C2,
  T4.C3,
  T4.C4
FROM
  T3,
  T4
WHERE
  T3.C1=T4.C1
  AND T3.C2=1;

Execution Plan
----------------------------------------------------------
Plan hash value: 3446668716

-------------------------------------------------------------------------------------------
| Id  | Operation                     | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |           |     1 |    42 |     3   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID  | T4        |     1 |    21 |     1   (0)| 00:00:01 |
|   2 |   NESTED LOOPS                |           |     1 |    42 |     3   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T3        |     1 |    21 |     2   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | IND_T3_C2 |     1 |       |     1   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN           | IND_T4_C1 |     1 |       |     0   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T3"."C2"=1)
   5 - access("T3"."C1"="T4"."C1") 

We found one case where the larger table was selected as the driving table, so the books and articles that simply state absolutely that the smallest table will be the driving table are not completely correct.  Maybe the larger table is only selected as the driving table when both tables are small?  Let’s test that theory by creating a couple of more tables:

SET AUTOTRACE OFF

CREATE TABLE T1 (
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 VARCHAR2(20),
  PADDING VARCHAR2(200));

CREATE TABLE T2 (
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 VARCHAR2(20),
  PADDING VARCHAR2(200));

INSERT INTO
  T1
SELECT
  ROWNUM C1,
  1000000-ROWNUM C2,
  MOD(ROWNUM-1,1000) C3,
  TO_CHAR(SYSDATE+MOD(ROWNUM-1,10000),'DAY') C4,
  LPAD(' ',200,'A') PADDING
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

INSERT INTO
  T2
SELECT
  ROWNUM C1,
  1000000-ROWNUM C2,
  MOD(ROWNUM-1,1000) C3,
  TO_CHAR(SYSDATE+MOD(ROWNUM-1,10000),'DAY') C4,
  LPAD(' ',200,'A') PADDING
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE INDEX IND_T1_C1 ON T1(C1);
CREATE INDEX IND_T1_C2 ON T1(C2);
CREATE INDEX IND_T1_C3 ON T1(C3);

CREATE INDEX IND_T2_C1 ON T2(C1);
CREATE INDEX IND_T2_C2 ON T2(C2);
CREATE INDEX IND_T2_C3 ON T2(C3);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL) 

The above script created table T1 with 1,000,000 rows and table T2 with 100,000 rows.  We will now use queries that are similar to those that were used with the 100 and 10 row tables.

The smaller table (T2) as the driving table:

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT /*+ USE_NL(T1 T2) */
  T1.C1,
  T1.C2,
  T1.C3,
  T1.C4,
  T2.C1,
  T2.C2,
  T2.C3,
  T2.C4
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1;

Execution Plan
----------------------------------------------------------
Plan hash value: 2610346857

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |   100K|  4687K|   300K  (1)| 01:00:12 |
|   1 |  NESTED LOOPS                |           |       |       |            |          |
|   2 |   NESTED LOOPS               |           |   100K|  4687K|   300K  (1)| 01:00:12 |
|   3 |    TABLE ACCESS FULL         | T2        |   100K|  2343K|   889   (1)| 00:00:11 |
|*  4 |    INDEX RANGE SCAN          | IND_T1_C1 |     1 |       |     2   (0)| 00:00:01 |
|   5 |   TABLE ACCESS BY INDEX ROWID| T1        |     1 |    24 |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T1"."C1"="T2"."C1") 

The larger table as the driving table:

SELECT /*+ USE_NL(T1 T2) */
  T1.C1,
  T1.C2,
  T1.C3,
  T1.C4,
  T2.C1,
  T2.C2,
  T2.C3,
  T2.C4
FROM
  T1,
  T2
WHERE
  T1.C1=T2.C1
  AND T1.C2 BETWEEN 1 AND 10000;

Execution Plan
----------------------------------------------------------
Plan hash value: 2331401024

-------------------------------------------------------------------------------------------
| Id  | Operation                     | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |           | 10001 |   468K| 11353   (1)| 00:02:17 |
|   1 |  NESTED LOOPS                 |           |       |       |            |          |
|   2 |   NESTED LOOPS                |           | 10001 |   468K| 11353   (1)| 00:02:17 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1        | 10001 |   234K|   348   (0)| 00:00:05 |
|*  4 |     INDEX RANGE SCAN          | IND_T1_C2 | 10001 |       |    25   (0)| 00:00:01 |
|*  5 |    INDEX RANGE SCAN           | IND_T2_C1 |     1 |       |     1   (0)| 00:00:01 |
|   6 |   TABLE ACCESS BY INDEX ROWID | T2        |     1 |    24 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T1"."C2">=1 AND "T1"."C2"<=10000)
   5 - access("T1"."C1"="T2"."C1") 

So, what is happening?  Is it simply the case that it is the expected number of rows that will be returned from each table that determines which table will be the driving table?  Let’s test:

SET AUTOTRACE OFF

SELECT
  COUNT(*)
FROM
  T1
WHERE
  T1.C1 BETWEEN 890000 AND 1000000;

  COUNT(*)
----------
    110001

SELECT
  COUNT(*)
FROM
  T2
WHERE
 T2.C2 BETWEEN 900000 AND 1000000;

  COUNT(*)
----------
    100000 

The above shows that if we specify T1.C1 BETWEEN 890000 AND 1000000 in the WHERE clause there will be 110,001 rows from the larger table that match the criteria. If we specify T2.C2 BETWEEN 900000 AND 1000000 in the WHERE clause there will be 100,000 rows from the smaller table that match the criteria. If we execute the following query, which table will be the driving table, the 10 times larger T1 table where we are retrieving 110,001 rows or the smaller T2 table where we are retrieving 100,000 rows?

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT /*+ USE_NL(T1 T2) */
  T1.C1,
  T1.C2,
  T1.C3,
  T1.C4,
  T2.C1,
  T2.C2,
  T2.C3,
  T2.C4
FROM
  T1,
  T2
WHERE
  T1.C3=T2.C3
  AND T1.C1 BETWEEN 890000 AND 1000000
  AND T2.C2 BETWEEN 900000 AND 1000000; 

This is the result that I received, which seems to demonstrate that it is not just the size of the tables, nor is it the number of expected rows to be returned from the tables, that determines which table will be the driving table:

-------------------------------------------------------------------------------------------
| Id  | Operation                     | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |           |    11M|   503M|    11M  (1)| 37:03:27 |
|   1 |  NESTED LOOPS                 |           |       |       |            |          |
|   2 |   NESTED LOOPS                |           |    11M|   503M|    11M  (1)| 37:03:27 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1        |   110K|  2578K|  3799   (1)| 00:00:46 |
|*  4 |     INDEX RANGE SCAN          | IND_T1_C1 |   110K|       |   248   (1)| 00:00:03 |
|*  5 |    INDEX RANGE SCAN           | IND_T2_C3 |   100 |       |     1   (0)| 00:00:01 |
|*  6 |   TABLE ACCESS BY INDEX ROWID | T2        |   100 |  2400 |   101   (0)| 00:00:02 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T1"."C1">=890000 AND "T1"."C1"<=1000000)
   5 - access("T1"."C3"="T2"."C3")
   6 - filter("T2"."C2">=900000 AND "T2"."C2"<=1000000) 

110,001 rows from T1 is still somewhat close in number to the 100,000 rows from T2, so let’s try an experiment selecting 992,701 rows from T1:

SELECT /*+ USE_NL(T1 T2) */
  T1.C1,
  T1.C2,
  T1.C3,
  T1.C4,
  T2.C1,
  T2.C2,
  T2.C3,
  T2.C4
FROM
  T1,
  T2
WHERE
  T1.C3=T2.C3
  AND T1.C1 BETWEEN 7300 AND 1000000
  AND T2.C2 BETWEEN 900000 AND 1000000;

Execution Plan
----------------------------------------------------------
Plan hash value: 3718770616

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |    99M|  4544M|   100M  (1)|334:20:23 |
|   1 |  NESTED LOOPS                |           |       |       |            |          |
|   2 |   NESTED LOOPS               |           |    99M|  4544M|   100M  (1)|334:20:23 |
|*  3 |    TABLE ACCESS FULL         | T1        |   992K|    22M|  8835   (1)| 00:01:47 |
|*  4 |    INDEX RANGE SCAN          | IND_T2_C3 |   100 |       |     1   (0)| 00:00:01 |
|*  5 |   TABLE ACCESS BY INDEX ROWID| T2        |   100 |  2400 |   101   (0)| 00:00:02 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("T1"."C1">=7300 AND "T1"."C1"<=1000000)
   4 - access("T1"."C3"="T2"."C3")
   5 - filter("T2"."C2">=900000 AND "T2"."C2"<=1000000) 

As shown above, table T1 is still the driving table in the nested loops join.  Let’s test retrieving 993,001 rows from T1:

SELECT /*+ USE_NL(T1 T2) */
  T1.C1,
  T1.C2,
  T1.C3,
  T1.C4,
  T2.C1,
  T2.C2,
  T2.C3,
  T2.C4
FROM
  T1,
  T2
WHERE
  T1.C3=T2.C3
  AND T1.C1 BETWEEN 7000 AND 1000000
  AND T2.C2 BETWEEN 900000 AND 1000000;

------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |    99M|  4545M|   100M  (1)|334:26:13 |
|   1 |  NESTED LOOPS                |           |       |       |            |          |
|   2 |   NESTED LOOPS               |           |    99M|  4545M|   100M  (1)|334:26:13 |
|*  3 |    TABLE ACCESS FULL         | T2        |   100K|  2343K|   889   (1)| 00:00:11 |
|*  4 |    INDEX RANGE SCAN          | IND_T1_C3 |  1000 |       |     3   (0)| 00:00:01 |
|*  5 |   TABLE ACCESS BY INDEX ROWID| T1        |   993 | 23832 |  1003   (0)| 00:00:13 |
------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("T2"."C2">=900000 AND "T2"."C2"<=1000000)
   4 - access("T1"."C3"="T2"."C3")
   5 - filter("T1"."C1">=7000 AND "T1"."C1"<=1000000) 

As shown above, table T2 is now the driving table for the nested loops join.  So, there must be other factors beyond table (or better worded row source) size and the number of rows that will be retrieved from the tables.  You might be wondering if the CLUSTERING_FACTOR of the indexes also plays a role in determining which table is the driving table:

SET AUTOTRACE OFF
 
SELECT
  TABLE_NAME,
  INDEX_NAME,
  CLUSTERING_FACTOR,
  NUM_ROWS
FROM
  USER_INDEXES
WHERE
  TABLE_NAME IN ('T1','T2')
ORDER BY
  TABLE_NAME,
  INDEX_NAME;

TABLE_NAME INDEX_NAME CLUSTERING_FACTOR   NUM_ROWS
---------- ---------- ----------------- ----------
T1         IND_T1_C1              32259    1000000
T1         IND_T1_C2              32259    1000000
T1         IND_T1_C3            1000000    1000000
T2         IND_T2_C1               3226     100000
T2         IND_T2_C2               3226     100000
T2         IND_T2_C3             100000     100000 

I suggested (without checking) in the OTN thread that the CLUSTERING_FACTOR of the index on columns C2 would be higher than the CLUSTERING_FACTOR of the index on columns C1 because of the reverse (descending) order in which the C2 column values were inserted into the tables.  Surprisingly (at least to me), the optimizer set the CLUSTERING_FACTOR of the C1 and C2 columns to be the same values, and set the CLUSTERING_FACTOR of column C3 to be the same as the number of rows in the table.  Maybe one of the readers of this blog article can explain what happened to the CLUSTERING_FACTOR.

So, the answer to the OP’s question is not as simple as “the Smaller Table is the Driving Table” or “the Larger Table is the Driving Table”, but that there are other factors involved.  I think that it might be time for a third read through of the book “Cost-Based Oracle Fundamentals”.  In the mean time, anyone care to share more insight (yes we could look inside a 10053 trace file, but there must be at least one other tip that can be provided without referencing such a trace file).

Oracle Database Time Model Viewer in Excel 5

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

What is the Difference Between the FIRST_ROWS Hint and ROWNUM in the WHERE Clause?

March 10, 2011

A couple of days ago I saw an interesting question that asked what is the difference between using the FIRST_ROWS(100) hint in a SQL statement and using ROWNUM<=100 in the WHERE clause with the original SQL statement moved to an inline view.   For example:

SELECT /*+ FIRST_ROWS(100) */
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN 1 AND 1000
ORDER BY
  C1; 

 

SELECT
  *
FROM
  (SELECT
     C1,
     C2
   FROM
     T1
   WHERE
     C1 BETWEEN 1 AND 1000
   ORDER BY
     C1)
WHERE
  ROWNUM<=100; 

My first thought was that the difference is actually quite simple to explain, and then I started to wonder, how could someone logically come to the conclusion that the two approaches would yield the same results?  Do developers look at explain plan output?  Could that explain how someone might look at these two approaches and question whether or not the two approaches are equivalent?  Let’s see:

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT /*+ FIRST_ROWS(100) */
  C1,
  C2
FROM
  T1
WHERE
  C1 BETWEEN 1 AND 1000
ORDER BY
  C1;

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |   102 |  1020 |     5   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |   102 |  1020 |     5   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | SYS_C0020704 |  1000 |       |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1">=1 AND "C1"<=1000) 

 

SET AUTOTRACE TRACEONLY EXPLAIN

SELECT
  *
FROM
  (SELECT
     C1,
     C2
   FROM
     T1
   WHERE
     C1 BETWEEN 1 AND 1000
   ORDER BY
     C1)
WHERE
  ROWNUM<=100;

----------------------------------------------------------------------------------------------
| Id  | Operation                     | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |              |   100 |  2600 |     5   (0)| 00:00:01 |
|*  1 |  COUNT STOPKEY                |              |       |       |            |          |
|   2 |   VIEW                        |              |   102 |  2652 |     5   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID| T1           |   102 |  1020 |     5   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN          | SYS_C0020704 |  1000 |       |     3   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=100)
   4 - access("C1">=1 AND "C1"<=1000) 

So, the FIRST_ROWS hinted plan shows that 102 rows will be returned, while the plan with ROWNUM in the WHERE clause shows that 100 of 102 rows will be returned.  So, this is the first clue that the two approaches might not be equivalent.  Other people have written extensively about what the FIRST_ROWS hint (and OPTIMIZER_MODE) mean and also how ROWNUM in the WHERE clause works (and a potentially significant bug that is present prior to Oracle Database 11.2.0.1).  Is it possible to simplify the explanation of the difference, something like this?

The short answer is that the FIRST_ROWS hint tells the query optimizer: I really do not care to know if more than 1, 10, 100, or 1000 rows could be returned by the query, just plan the query execution as if my application will only retrieve 1, 10, 100, or 1000 rows – my application might still retrieve all of the rows, but just plan on the specified number being read. 

The ROWNUM predicate in the WHERE clause tells the query optimizer: I really do not care if more than 1, 10, 100, or 1000 rows could be returned by the original query, plan the query execution as if my application will only retrieve 1, 10, 100, or 1000 rows and make certain that my application cannot retrieve more than the specified number of rows.

Simple, maybe just a little too simple?

Let’s put together a little test script to demonstrate.  First, we will create a table with a primary key index, insert 500,000 rows, and then collect statistics with a 100% sample size:

CREATE TABLE T1(
  C1 NUMBER,
  C2 NUMBER,
  C3 NUMBER,
  C4 DATE,
  C5 DATE,
  C6 DATE,
  C7 VARCHAR2(20),
  C8 VARCHAR2(20),
  C9 VARCHAR2(20),
  PRIMARY KEY(C1));

INSERT INTO
  T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  DECODE(MOD(ROWNUM,5),0,NULL,ROWNUM),
  TRUNC(SYSDATE)+TRUNC(ROWNUM/100),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  DECODE(MOD(ROWNUM,5),0,NULL,TRUNC(SYSDATE)+TRUNC(ROWNUM/100)),
  RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A')),
  DECODE(MOD(ROWNUM,5),0,NULL,
   RPAD(CHR(MOD(ROWNUM-1,26)+65)||
    CHR(MOD(ROWNUM,26)+65)||
    CHR(MOD(ROWNUM+1,26)+65)||
    CHR(MOD(ROWNUM+2,26)+65),20,'A'))
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>NULL) 

Now the test script:

SPOOL TestFirstRowsAndRownum.txt
ALTER SYSTEM FLUSH BUFFER_CACHE;
SET AUTOTRACE TRACEONLY STATISTICS EXPLAIN
SET ARRAYSIZE 1000
SET TIMING ON
SET LINESIZE 140
SET PAGESIZE 1000
SET TRIMSPOOL ON

SELECT /*+ INDEX(T1) */
  C1,
  C2,
  C3,
  C4,
  C5,
  C6
FROM
  T1
WHERE
  C1 BETWEEN 10000 AND 100000;

ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT /*+ INDEX(T1) FIRST_ROWS(100) */
  C1,
  C2,
  C3,
  C4,
  C5,
  C6
FROM
  T1
WHERE
  C1 BETWEEN 10000 AND 100000;

ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT /*+ INDEX(T1) */
  C1,
  C2,
  C3,
  C4,
  C5,
  C6
FROM
  T1
WHERE
  C1 BETWEEN 10000 AND 100000
  AND ROWNUM<=100;

ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT /*+  */
  *
FROM
  (SELECT
    C1,
    C2,
    MAX(C3) C3
  FROM
    T1
  GROUP BY
    C1,
    C2
  ORDER BY
    C1,
    C2)
WHERE
  C1 BETWEEN 10000 AND 100000;

ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT /*+  FIRST_ROWS(100) */
  *
FROM
  (SELECT
    C1,
    C2,
    MAX(C3) C3
  FROM
    T1
  GROUP BY
    C1,
    C2
  ORDER BY
    C1,
    C2)
WHERE
  C1 BETWEEN 10000 AND 100000;

ALTER SYSTEM FLUSH BUFFER_CACHE;

SELECT /*+  */
  *
FROM
  (SELECT
    C1,
    C2,
    MAX(C3) C3
  FROM
    T1
  GROUP BY
    C1,
    C2
  ORDER BY
    C1,
    C2)
WHERE
  C1 BETWEEN 10000 AND 100000
  AND ROWNUM<=100;

SPOOL OFF 

The output of the first query, without the hint and without the ROWNUM restriction:

SQL> SELECT /*+ INDEX(T1) */
  2    C1,
  3    C2,
  4    C3,
  5    C4,
  6    C5,
  7    C6
  8  FROM
  9    T1
 10  WHERE
 11    C1 BETWEEN 10000 AND 100000;

90001 rows selected.

Elapsed: 00:00:00.43

Execution Plan
----------------------------------------------------------
Plan hash value: 2459953871

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              | 90002 |  3252K|  1359   (1)| 00:00:07 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           | 90002 |  3252K|  1359   (1)| 00:00:07 |
|*  2 |   INDEX RANGE SCAN          | SYS_C0020704 | 90002 |       |   174   (2)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1">=10000 AND "C1"<=100000)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1534  consistent gets
       1354  physical reads
          0  redo size
    1994612  bytes sent via SQL*Net to client
       1324  bytes received via SQL*Net from client
         92  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      90001  rows processed 

Note in the plain (unmodified) query that 90,001 rows were returned to SQL*Plus, while the optimizer predicted that 90,002 rows would be returned.  It required 0.43 seconds for the rows to be returned to the SQL*Plus session.

Now the second query of the test case, hinted with FIRST_ROWS:

SQL> SELECT /*+ INDEX(T1) FIRST_ROWS(100) */
  2    C1,
  3    C2,
  4    C3,
  5    C4,
  6    C5,
  7    C6
  8  FROM
  9    T1
 10  WHERE
 11    C1 BETWEEN 10000 AND 100000;

90001 rows selected.

Elapsed: 00:00:00.43

Execution Plan
----------------------------------------------------------
Plan hash value: 2459953871

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |   103 |  3811 |     5   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |   103 |  3811 |     5   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | SYS_C0020704 | 90002 |       |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1">=10000 AND "C1"<=100000)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
       1534  consistent gets
       1354  physical reads
          0  redo size
    1994612  bytes sent via SQL*Net to client
       1324  bytes received via SQL*Net from client
         92  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      90001  rows processed 

Note in the FIRST_ROWS(100) hinted query that 90,001 rows were returned to SQL*Plus, while the optimizer predicted that 103 rows would be returned due to the hint.  It required 0.43 seconds for the rows to be returned to the SQL*Plus session.

Now the third query of the test case:

SQL> SELECT /*+ INDEX(T1) */
  2    C1,
  3    C2,
  4    C3,
  5    C4,
  6    C5,
  7    C6
  8  FROM
  9    T1
 10  WHERE
 11    C1 BETWEEN 10000 AND 100000
 12    AND ROWNUM<=100;

100 rows selected.

Elapsed: 00:00:00.01

Execution Plan
----------------------------------------------------------
Plan hash value: 3250543521

---------------------------------------------------------------------------------------------
| Id  | Operation                    | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |              |   100 |  3700 |     5   (0)| 00:00:01 |
|*  1 |  COUNT STOPKEY               |              |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1           |   103 |  3811 |     5   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | SYS_C0020704 | 90002 |       |     3   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=100)
   3 - access("C1">=10000 AND "C1"<=100000)

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          8  consistent gets
          6  physical reads
          0  redo size
       2787  bytes sent via SQL*Net to client
        334  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
        100  rows processed 

Note in the query with the ROWNUM predicate in the WHERE clause that 100 rows were returned to SQL*Plus, while the optimizer predicted that 100 rows (103 rows before the COUNT STOPKEY operation) would be returned.  It required 0.01 seconds for the rows to be returned to the SQL*Plus session.

Now for the second half of the output (created on Oracle Database 10.2.0.2 – your results may be a bit different).  The first query:

SQL> SELECT /*+  */
  2    *
  3  FROM
  4    (SELECT
  5      C1,
  6      C2,
  7      MAX(C3) C3
  8    FROM
  9      T1
 10    GROUP BY
 11      C1,
 12      C2
 13    ORDER BY
 14      C1,
 15      C2)
 16  WHERE
 17    C1 BETWEEN 10000 AND 100000;

90001 rows selected.

Elapsed: 00:00:00.56

Execution Plan
----------------------------------------------------------
Plan hash value: 915463192

------------------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      | 90002 |  3427K|       |   904   (5)| 00:00:05 |
|   1 |  VIEW               |      | 90002 |  3427K|       |   904   (5)| 00:00:05 |
|   2 |   SORT GROUP BY     |      | 90002 |  2197K|  7080K|   904   (5)| 00:00:05 |
|*  3 |    TABLE ACCESS FULL| T1   | 90002 |  2197K|       |   352   (8)| 00:00:02 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("C1"<=100000 AND "C1">=10000)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       6563  consistent gets
       6555  physical reads
          0  redo size
    1307436  bytes sent via SQL*Net to client
       1324  bytes received via SQL*Net from client
         92  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
      90001  rows processed 

Nothing too out of the ordinary in the above, the WHERE clause predicate was pushed into the inline view, although I thought that the inline view (indicated by the VIEW line in the explain plan output) might disappear.

The second query with the FIRST_ROWS hint:

SQL> SELECT /*+  FIRST_ROWS(100) */
  2    *
  3  FROM
  4    (SELECT
  5      C1,
  6      C2,
  7      MAX(C3) C3
  8    FROM
  9      T1
 10    GROUP BY
 11      C1,
 12      C2
 13    ORDER BY
 14      C1,
 15      C2)
 16  WHERE
 17    C1 BETWEEN 10000 AND 100000;

90001 rows selected.

Elapsed: 00:00:00.50

Execution Plan
----------------------------------------------------------
Plan hash value: 915463192

------------------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      | 90002 |  3427K|       |   904   (5)| 00:00:05 |
|   1 |  VIEW               |      | 90002 |  3427K|       |   904   (5)| 00:00:05 |
|   2 |   SORT GROUP BY     |      | 90002 |  2197K|  7080K|   904   (5)| 00:00:05 |
|*  3 |    TABLE ACCESS FULL| T1   | 90002 |  2197K|       |   352   (8)| 00:00:02 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter("C1"<=100000 AND "C1">=10000)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       6563  consistent gets
       6555  physical reads
          0  redo size
    1307436  bytes sent via SQL*Net to client
       1324  bytes received via SQL*Net from client
         92  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
      90001  rows processed 

The WHERE clause predicate was pushed into the inline view again, but notice that the optimizer did not predict that 100 or 103 rows would be returned by the query.  Do you see the same results on other Oracle Database release versions?  It is slightly interesting to see that the available index access path was not selected… almost as if the FIRST_ROWS hint had no effect… of course you know the reason why.  :-)  (Edit: March 10, 2011: The same result was achieved when moving the hint to the inline view, and same result was achieved when specifying the hint as FIRST_ROWS(1).  I guess that it is time to review the 10053 trace to see what happened.)

Now the query with the ROWNUM predicate:

SQL> SELECT /*+  */
  2    *
  3  FROM
  4    (SELECT
  5      C1,
  6      C2,
  7      MAX(C3) C3
  8    FROM
  9      T1
 10    GROUP BY
 11      C1,
 12      C2
 13    ORDER BY
 14      C1,
 15      C2)
 16  WHERE
 17    C1 BETWEEN 10000 AND 100000
 18    AND ROWNUM<=100;

100 rows selected.

Elapsed: 00:00:00.31

Execution Plan
----------------------------------------------------------
Plan hash value: 2221909342

----------------------------------------------------------------------------------------
| Id  | Operation               | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT        |      |   100 |  3900 |       |   748   (5)| 00:00:04 |
|*  1 |  COUNT STOPKEY          |      |       |       |       |            |          |
|   2 |   VIEW                  |      | 90002 |  3427K|       |   748   (5)| 00:00:04 |
|*  3 |    SORT GROUP BY STOPKEY|      | 90002 |  1318K|  4968K|   748   (5)| 00:00:04 |
|*  4 |     TABLE ACCESS FULL   | T1   | 90002 |  1318K|       |   352   (8)| 00:00:02 |
----------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(ROWNUM<=100)
   3 - filter(ROWNUM<=100)
   4 - filter("C1"<=100000 AND "C1">=10000)

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       6563  consistent gets
       6555  physical reads
          0  redo size
       2275  bytes sent via SQL*Net to client
        334  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
        100  rows processed 

The standard WHERE clause predicate used in all of the queries was pushed into the inline view again, and the ROWNUM predicate was also pushed into the inline view.  Does this demonstrate the potential bug – what if instead of a full table scan, the primary key index access path were used to read the data from table T1?

Oracle Database Time Model Viewer in Excel 4

March 6, 2011 (Updated March 15, 2011)

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

In the previous three parts of this series we started building an Oracle Database time model statistics viewer using nothing more than Microsoft Excel.  The end result will hopefully duplicate some of the functionality that is found in a portion of a program that I have been building over the course of the last several years.  My program’s window that shows the Oracle Database time model statistics looks like this:

If you have been following along with the previous articles in this series,  at this point your Excel UserForm project should look something like the following screen capture:

We still need to add the wait events to the project.  While we could display the wait events information in a TreeView control, there would not be much sense to display the wait event information in a grid type control when we are able to just push that information out to a worksheet in the Excel workbook.  So that we are able to control which worksheet that information will be push to, we should begin by naming the worksheet.  In the main Excel window, right-click Sheet1 and select Rename.  Change the name to Wait Events.

Now switch back to the code window for the project (note that you can display the code window by right-click a worksheet tab and selecting View Code).  Right-click frmTimeModel (under the Forms heading which is below Microsoft Excel Objects) and select View Object.  The Caption property of the UserForm likely still shows UserForm1 – change the Caption property to something that is more meaningful (I will change my Caption to I Can’t Believe I Build an Oracle Database Time Model Viewer in Excel - yes, that typo is intentional).  Double-click the background of the UserForm to show the code for the UserForm’s Initialize event.  Locate the following text in the Initialize event:

    'More code will be copied here
    '
    '
    ' 

Move the cursor just above that text and press the Enter key a couple of times.  Add the following code above the ‘More code will be copied here line.  Note that the second of the SQL statements uses bind variables:

    'Added in Article 4
    With comDataWait
        strSQL = "SELECT" & vbCrLf
        strSQL = strSQL & "  WAIT_CLASS," & vbCrLf
        strSQL = strSQL & "  EVENT," & vbCrLf
        strSQL = strSQL & "  TOTAL_WAITS," & vbCrLf
        strSQL = strSQL & "  TOTAL_TIMEOUTS," & vbCrLf
        strSQL = strSQL & "  TIME_WAITED" & vbCrLf
        strSQL = strSQL & "FROM" & vbCrLf
        strSQL = strSQL & "  V$SYSTEM_EVENT" & vbCrLf
        strSQL = strSQL & "ORDER BY" & vbCrLf
        strSQL = strSQL & "  WAIT_CLASS," & vbCrLf
        strSQL = strSQL & "  EVENT"

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

    With comSessionWait
        strSQL = "SELECT" & vbCrLf
        strSQL = strSQL & "  S.SID," & vbCrLf
        strSQL = strSQL & "  S.SERIAL#," & vbCrLf
        strSQL = strSQL & "  S.STATUS," & vbCrLf
        strSQL = strSQL & "  NVL(S.USERNAME,' ') USERNAME," & vbCrLf
        strSQL = strSQL & "  NVL(S.MACHINE,' ') MACHINE," & vbCrLf
        strSQL = strSQL & "  NVL(S.PROGRAM,' ') PROGRAM," & vbCrLf
        strSQL = strSQL & "  NVL(S.SQL_ID,NVL(S.PREV_SQL_ID,' ')) SQL_ID," & vbCrLf
        strSQL = strSQL & "  NVL(S.SQL_CHILD_NUMBER,NVL(S.PREV_CHILD_NUMBER,0)) SQL_CHILD_NUMBER," & vbCrLf
        strSQL = strSQL & "  SE.EVENT," & vbCrLf
        strSQL = strSQL & "  SE.TOTAL_WAITS," & vbCrLf
        strSQL = strSQL & "  SE.TOTAL_TIMEOUTS," & vbCrLf
        strSQL = strSQL & "  SE.TIME_WAITED" & vbCrLf
        strSQL = strSQL & "FROM" & vbCrLf
        strSQL = strSQL & "  V$SESSION_EVENT SE," & vbCrLf
        strSQL = strSQL & "  V$SESSION S" & vbCrLf
        strSQL = strSQL & "WHERE" & vbCrLf
        strSQL = strSQL & "  SE.EVENT = ?" & vbCrLf
        strSQL = strSQL & "  AND SE.SID=S.SID" & vbCrLf
        strSQL = strSQL & "ORDER BY" & vbCrLf
        strSQL = strSQL & "  S.SID"

        .CommandText = strSQL
        .CommandType = adCmdText
        .ActiveConnection = dbDatabase

        'Add the bind variables
        .Parameters.Append .CreateParameter("event", adVarChar, adParamInput, 40, "")
    End With 

Scroll up in the code until you locate the ReadData subroutine.  Locate the following line at the bottom of that subroutine:

dteLastLoopStart = Now

Move the cursor just above that line and press the Enter key a couple of times.  In the blank area that was just created paste the following code which will read in the system-wide wait event statistics and store those statistics in variables:

    'Added in Article 4
    Set snpDataWait = comDataWait.Execute
    If Not (snpDataWait Is Nothing) Then
        Do While Not (snpDataWait.EOF)
            intWaitCurrent = intWaitCount + 1
            'Find the previous entry for this wait event
            For j = 1 To intWaitCount
                If strWaitEventName(j) = CStr(snpDataWait("event")) Then
                    intWaitCurrent = j
                    Exit For
                End If
            Next j
            If intWaitCurrent = intWaitCount + 1 Then
                'New entry
                intWaitCount = intWaitCount + 1
                strWaitEventName(intWaitCurrent) = CStr(snpDataWait("event"))
                strWaitEventClass(intWaitCurrent) = snpDataWait("wait_class")
            End If
            dblWaitValueLast(intWaitCurrent) = dblWaitValue(intWaitCurrent)
            dblWaitValue(intWaitCurrent) = CDbl(snpDataWait("time_waited"))
            dblWaitWaitsValueLast(intWaitCurrent) = dblWaitWaitsValue(intWaitCurrent)
            dblWaitWaitsValue(intWaitCurrent) = CDbl(snpDataWait("total_waits"))
            dblWaitTOValueLast(intWaitCurrent) = dblWaitTOValue(intWaitCurrent)
            dblWaitTOValue(intWaitCurrent) = CDbl(snpDataWait("total_timeouts"))

            snpDataWait.MoveNext
        Loop
        snpDataWait.Close
    End If 

Note in the above code the snpDataWait.Close command that is below the Loop and above the End If lines.  That command closes the snpDataWait recordset, which is necessary to prevent cursor leaks.  Review the other code sections that are in the ReadData subroutine and verify that the recordset is always closed between the Loop and End If lines, and if it is not, fix that problem (hint: there is at least one code section that needs to be corrected).

Find the UpdateDisplay subroutine and locate the following line near the start of the subroutine:

On Error Resume Next 

Just above that line, press the Enter key a couple of times and add the following variable declaration – this variable will be used to control where the output is placed on the worksheet:

Dim lngRow As Long 

Scroll down to the bottom of the UpdateDisplay subroutine and locate the following line:

intCurrentSessionIndex = -1 

Move the cursor just above that line, press the Enter key a couple of times.  Paste in the following code on the blank lines:

    'Added in Article 4
    lngRow = 1
    Sheets("Wait Events").Rows("1:10000").Delete Shift:=xlUp
    Sheets("Wait Events").Cells(lngRow, 1).Value = "Wait Event Name"
    Sheets("Wait Events").Cells(lngRow, 2).Value = "Wait Time"
    Sheets("Wait Events").Cells(lngRow, 3).Value = "Waits"
    Sheets("Wait Events").Cells(lngRow, 4).Value = "Timeouts"
    Sheets("Wait Events").Cells(lngRow, 5).Value = "Session Description"

    For j = 1 To intWaitCount
        If (strWaitEventClass(j) <> "Idle") Or (intExcludeIdleWaits = False) Then
            If strLastWaitClass <> strWaitEventClass(j) Then
                If strLastWaitClass <> "" Then
                    'Do not write out on the first pass
                    Sheets("Wait Events").Cells(intLastWaitClassRow, 2).Value = Format(sglWaitClassTime / 100, "0.00")
                End If

                strLastWaitClass = strWaitEventClass(j)
                lngRow = lngRow + 1
                Sheets("Wait Events").Cells(lngRow, 1).Value = strLastWaitClass & " Wait Class"
                Sheets("Wait Events").Cells(lngRow, 1).Font.Bold = True
                Sheets("Wait Events").Cells(lngRow, 2).Font.Bold = True
                intLastWaitClassRow = lngRow
                sglWaitClassTime = 0
            End If

            If (dblWaitValue(j) - dblWaitValueLast(j)) <> 0 Then
                sglWaitClassTime = sglWaitClassTime + (dblWaitValue(j) - dblWaitValueLast(j))

                If strWaitEventClass(j) <> "Idle" Then
                    sglTotalWaitTime = sglTotalWaitTime + (dblWaitValue(j) - dblWaitValueLast(j))
                End If

                lngRow = lngRow + 1
                Sheets("Wait Events").Cells(lngRow, 1).Value = "-- " & strWaitEventName(j)
                Sheets("Wait Events").Cells(lngRow, 2).Value = Format((dblWaitValue(j) - dblWaitValueLast(j)) / 100, "0.00")
                Sheets("Wait Events").Cells(lngRow, 3).Value = Format((dblWaitWaitsValue(j) - dblWaitWaitsValueLast(j)), "0")
                Sheets("Wait Events").Cells(lngRow, 4).Value = Format((dblWaitTOValue(j) - dblWaitTOValueLast(j)), "0")
                Sheets("Wait Events").Cells(lngRow, 5).Value = ""

                If (intDisplaySessionDetail = True) Then
                    comSessionWait("event") = strWaitEventName(j)
                    Set snpSessionWait = comSessionWait.Execute

                    If Not (snpSessionWait Is Nothing) Then
                        If snpSessionWait.State = 1 Then
                            Do While Not (snpSessionWait.EOF)
                                intSessionCurrent = 0
                                For k = 1 To intSessionCount
                                    If (lngSID(k) = CLng(snpSessionWait("sid"))) And (lngSerial(k) = CLng(snpSessionWait("serial#"))) Then
                                        intSessionCurrent = k

                                        'Output the session wait information
                                        If (snpSessionWait("time_waited") - dblSessionWaitValue(j, intSessionCurrent) > 0) Then
                                            'Output only if time change is more that the sglSessionMinimumPercent value
                                            If ((CDbl(snpSessionWait("time_waited")) - dblSessionWaitValue(j, intSessionCurrent)) > 0) And (CDbl(snpSessionWait("time_waited")) - dblSessionWaitValue(j, intSessionCurrent)) / (dblWaitValue(j) - dblWaitValueLast(j)) >= sglSessionMinimumPercent Then
                                                lngRow = lngRow + 1
                                                Sheets("Wait Events").Cells(lngRow, 1).Value = "---- session level wait " & Format((CDbl(snpSessionWait("time_waited")) - dblSessionWaitValue(j, intSessionCurrent)) / (dblWaitValue(j) - dblWaitValueLast(j)), "0.00%") & " of system wait event"
                                                Sheets("Wait Events").Cells(lngRow, 2).Value = Format((CDbl(snpSessionWait("time_waited")) - dblSessionWaitValue(j, intSessionCurrent)) / 100, "0.00")
                                                Sheets("Wait Events").Cells(lngRow, 3).Value = Format((CDbl(snpSessionWait("total_waits")) - dblSessionWaitWaitsValue(j, intSessionCurrent)), "0")
                                                Sheets("Wait Events").Cells(lngRow, 4).Value = Format((CDbl(snpSessionWait("total_timeouts")) - dblSessionWaitTOValue(j, intSessionCurrent)), "0")

                                                strOut = "SID:" & Format(snpSessionWait("sid")) & " SERIAL#:" & Format(snpSessionWait("serial#"))
                                                strOut = strOut & " ~ Machine: " & snpSessionWait("machine") & " ~ " & snpSessionWait("username") & " ~ " & snpSessionWait("program")
                                                If snpSessionWait("sql_id") <> " " Then
                                                    strOut = strOut & " ~ SQL_ID/Child: " & snpSessionWait("sql_id") & "/" & Format(snpSessionWait("sql_child_number"), "0") & " "
                                                    If UCase(snpSessionWait("status")) = "ACTIVE" Then
                                                        strOut = strOut & " (A)"
                                                    End If
                                                End If
                                                Sheets("Wait Events").Cells(lngRow, 5).Value = strOut
                                            End If
                                        End If
                                        dblSessionWaitValue(j, intSessionCurrent) = CDbl(snpSessionWait("time_waited"))
                                        dblSessionWaitWaitsValue(j, intSessionCurrent) = CDbl(snpSessionWait("total_waits"))
                                        dblSessionWaitTOValue(j, intSessionCurrent) = CDbl(snpSessionWait("total_timeouts"))

                                        Exit For
                                    End If
                                Next k

                                snpSessionWait.MoveNext
                            Loop
                            snpSessionWait.Close
                        End If
                    End If
                End If
            End If
        End If
    Next j

    If strLastWaitClass <> "" Then
        Sheets("Wait Events").Cells(intLastWaitClassRow, 2).Value = Format(sglWaitClassTime / 100, "0.00")
    End If

    Sheets("Wait Events").Columns("A:A").EntireColumn.AutoFit
    Sheets("Wait Events").Columns("B:B").EntireColumn.AutoFit
    Sheets("Wait Events").Columns("C:C").EntireColumn.AutoFit
    Sheets("Wait Events").Columns("D:D").EntireColumn.AutoFit
    Sheets("Wait Events").Columns("E:E").EntireColumn.AutoFit
    Sheets("Wait Events").Columns("B:B").NumberFormat = "0.00"
    Sheets("Wait Events").Range("B2").Select
    ActiveWindow.FreezePanes = True 

'    lblTotalWaitTime = Format(sglTotalWaitTime / 100, "0.00")

You may have noticed that the chkPauseRefresh CheckBox (with caption Pause Refresh) does not work quite as expected – this is a simple logic problem that needs to be addressed.  Find the chkPauseRefresh CheckBox on the UserForm and double-click it to show the code that is behind the CheckBox control.  You will see a line of code that looks like this:

If intKillFlag <> False Then

Change the <> characters to an = character so that the line appears as follows:

If intKillFlag = False Then 

If you then show the UserForm (switch to the Initialize event of the UserForm and press the F5 key, you may then need to toggle the chkPauseRefresh check box between checked and not checked) you should see something like this after the second 60 second delay:

We still have a slight problem that needs to be addressed.  We need another Label control on the UserForm, with the name lblTotalWaitTime.  Once you have created that Label control, you can go back to the UpdateDisplay subroutine and remove the single quote (‘) that is in front of the following line:

'    lblTotalWaitTime = Format(sglTotalWaitTime / 100, "0.00") 

When the single quote is removed, the text color should change from green to black.

What more are we able to do with this project?  We could display the execution plans for the captured SQL_ID and CHILD_NUMBER (stored in the strSQLID() array), we could enable/disable 10046 tracing for sessions, we could write out the statistics in real-time to another worksheet and then graph the results, or maybe we could just sit back and stare at the screen in amazement that this project was built in Microsoft Excel ;-)

—-

Added March 15, 2011:

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

Oracle Database Time Model Viewer in Excel 3

March 3, 2011 (Updated March 5, 2011)

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

In the previous articles of this series we started building a solution in Microsoft Excel that duplicates some of the functionality in one of my programs – the Oracle Database Time Model viewer.  So far, the project only works at just the system-wide level.  Hopefully, not too many people are having difficulty following along with this article series – it has been more than a decade since I professionally taught programming and Microsoft Excel, so I might be overlooking a couple of “obviously” difficult points. 

If you have not done so yet, you may need to change Excel’s default behavior when an error occurs in the code, since some errors are expected and should be handled appropriately within our programming code.  To check the error trapping setting in the Excel code editor window, select from the menu Tools – Options.  On the General tab, find and select the setting Break on Unhandled Errors, then click the OK button.  If you plan to do much programming in Excel, I also suggest setting the Require Variable Declaration option on the Editor tab – setting that option helps to avoid some forms of typing errors (all used variables must be officially declared before use).

If you find that the macro seems to pause unexpectedly when first started, there is a simple solution for that issue, and we will apply the simple solution later in this article.

We will start by adding a couple of more controls to the UserForm to add a little more functionality to the programming code.  In my sample project I will be adding the extra controls at the top of the UserForm.  We need to add three CheckBox controls to the UserForm with the (Name) property set to: chkPauseRefresh, chkDisplaySessionDetail, and chkExcludeIdleWaits (one name for each CheckBox).  Change the Caption property of those checkboxes to describe the function of the CheckBoxes (I used: Pause Refresh, Show Session Detail, and No Idle Waits).  Add two ComboBox controls to the UserForm with the (Name) property set to: cboUpdateFrequency and cboSessionMinimumPercent.  Set the Text property of the cboUpdateFrequency ComboBox to 60.  Set the Text property of the cboSessionMinimumPercent ComboBox to 10.  Add a Label control near each of the ComboBox controls, and change the Caption property of the Label controls to describe the purpose of the ComboBox controls (I used: Update Freq (S) and Min Utilization to Inc. Session %).  Your UserForm should look something like this when finished with the above instructions:

The extra controls at this point do nothing, other than occupy space on the UserForm, so we need to add functionality to the extra controls.  Double-click the chkPauseRefresh CheckBox to show the default code event for the CheckBox – the “Click” event.  The TimerEvent subroutine that we modified in the previous article is set to abort re-executing the TimerEvent subroutine any time the intKillFlag variable is set to something other than False (a value of 0).  So, the code for the chkPauseRefresh CheckBox’s Click event will simply toggle this intKillFlag variable between the values of True and False – if the value becomes True we need to restart the re-execution of the TimerEvent procedure.  The easiest way to accomplish this task is with the following code in the chkPauseRefresh CheckBox’s Click event (note that in Visual Basic versions 4.0 through 6.0 this same code will toggle the intKillFlag variable between the values of 0 and 1, but the code as written will behave the same way.  Value is the default property of a CheckBox control, so technically we could have omitted the .Value portion of the code):

Private Sub chkPauseRefresh_Click()
    intKillFlag = chkPauseRefresh.Value

    If intKillFlag <> False Then
        TimerEvent
    End If
End Sub 

The chkDisplaySessionDetail CheckBox technically does not require any special programming code in its Click event, so we will come back to this program functionality later.

The Click event for the chkExcludeIdleWaits CheckBox is similar to that of the same event for the chkPauseRefresh CheckBox.  On the UserForm, double-click the chkExcludeIdleWaits CheckBox (or simply select that name from the left ComboBox (drop-down list) in the code editor).  Change the Click event for that CheckBox to the following:

Private Sub chkExcludeIdleWaits_Click()
    intExcludeIdleWaits = chkExcludeIdleWaits.Value
End Sub

We need to add a little code to the two ComboBox controls in order to prevent the user of this tool from entering silly values, such as Sixty for the update frequency or 1,000,000 for the minimum utilization percent – we will check the entered values only when the user “tabs” out of the controls (or clicks something else).  Double-click the cboUpdateFrequency ComboBox, then select the Exit event from the ComboBox (drop-down list) that is at the top-right of the code window.  Add the following code to that event:

Private Sub cboUpdateFrequency_Exit(ByVal Cancel As MSForms.ReturnBoolean)
    Dim intResult As Integer

    If IsNumeric(cboUpdateFrequency.Text) Then
        If (Val(cboUpdateFrequency.Text) >= 1) And (Val(cboUpdateFrequency.Text) <= 18000) Then
            'OK
            lngTimerTriggerSeconds = Val(cboUpdateFrequency.Text)
        Else
            intResult = MsgBox(cboUpdateFrequency.Text & " is an invalid value." & vbCrLf & _
                "Must enter a number between 1 and 18000", vbCritical, "Charles Hooper's Oracle Database Time Model Viewer") 

            cboUpdateFrequency.Text = "60"
            lngTimerTriggerSeconds = 60
        End If
    Else
        intResult = MsgBox(cboUpdateFrequency.Text & " is an invalid value." & vbCrLf & _
            "Must enter a number between 1 and 18000", vbCritical, "Charles Hooper's Oracle Database Time Model Viewer")

        cboUpdateFrequency.Text = "60"
        lngTimerTriggerSeconds = 60
    End If
End Sub 

We need similar code in the Exit event of the cboUpdateFrequency ComboBox.  Double-click the cboUpdateFrequency ComboBox, and switch to the Exit event.  Add the following code:

Private Sub cboSessionMinimumPercent_Exit(ByVal Cancel As MSForms.ReturnBoolean)
    Dim intResult As Integer

    If IsNumeric(cboSessionMinimumPercent.Text) Then
        If (Val(cboSessionMinimumPercent.Text) >= 0.001) And (Val(cboSessionMinimumPercent.Text) <= 100) Then
            'OK
        Else
            intResult = MsgBox(cboSessionMinimumPercent.Text & " is an invalid value." & vbCrLf & _
                "Must enter a number between 0.001 and 100.0", vbCritical, "Charles Hooper's Oracle Database Time Model Viewer")

            cboSessionMinimumPercent.Text = "10"
        End If
    Else
        intResult = MsgBox(cboSessionMinimumPercent.Text & " is an invalid value." & vbCrLf & _
            "Must enter a number between 0.001 and 100.0", vbCritical, "Charles Hooper's Oracle Database Time Model Viewer")

        cboSessionMinimumPercent.Text = "10"
    End If
End Sub 

We still need to add the functionality for the chkDisplaySessionDetail CheckBox and the cboSessionMinimumPercent ComboBox, and we have not done anything with the wait events yet (that feature will be added in the next article in this series).  Find the following code section in the UpdateDisplay subroutine:

'    If chkDisplaySessionDetail = 0 Then
'        intDisplaySessionDetail = False
'    Else
'        intDisplaySessionDetail = True
'    End If
'    sglSessionMinimumPercent = Val(cboSessionMinimumPercent.Text) / 100 

Remove the single quote characters (‘) in front of each of those lines so that the code appears like this:

    If chkDisplaySessionDetail = 0 Then
        intDisplaySessionDetail = False
    Else
        intDisplaySessionDetail = True
    End If
    sglSessionMinimumPercent = Val(cboSessionMinimumPercent.Text) / 100 

The above simple fix adds the functionality to the chkDisplaySessionDetail CheckBox and the cboSessionMinimumPercent ComboBox.  We still need to provide a list of items in the ComboBoxes that the users are able to select from, and fix the problem where the macro seems to pause unexpectedly when first started.  Switch to the Initialize event in the UserForm (double-click the UserForm’s background area), and then locate the following code in that subroutine:

    'More code will be copied here
    '
    '
    ' 

Just below that section of the code (and above the TimerEvent line), add the following code:

    cboUpdateFrequency.AddItem "5"
    cboUpdateFrequency.AddItem "10"
    cboUpdateFrequency.AddItem "30"
    cboUpdateFrequency.AddItem "60"
    cboUpdateFrequency.AddItem "120"
    cboUpdateFrequency.AddItem "600"
    cboUpdateFrequency.AddItem "3600"
    cboUpdateFrequency.AddItem "7200"
    cboUpdateFrequency.Text = "60"
    lngTimerTriggerSeconds = 60

    cboSessionMinimumPercent.AddItem "1"
    cboSessionMinimumPercent.AddItem "5"
    cboSessionMinimumPercent.AddItem "10"
    cboSessionMinimumPercent.AddItem "15"
    cboSessionMinimumPercent.AddItem "20"
    cboSessionMinimumPercent.AddItem "25"
    cboSessionMinimumPercent.AddItem "50"
    cboSessionMinimumPercent.AddItem "75"
    cboSessionMinimumPercent.Text = "10"

    DoEvents 

In the above, the lines containing .AddItem add entries to the list that is suggested to the user of the tool that we are building.  The lines containing .Text set the default text that appears in each of the ComboBoxes, and the lngTimerTriggerSeconds value must be identical to the numeric value that is assigned to the cboUpdateFrequency.Text property.  Save the project and press the F5 key on the keyboard to display the UserForm and start updating the statistics (after a 60 second delay).  Place a check in the chkDisplaySessionDetail CheckBox (identified as Show Session Detail in the sample project).  You should see something like this (up to 60 seconds after placing a check in that CheckBox):

By looking at the above screen capture it is probably obvious that those sessions which had consumed a small percentage of a Time Model Statistic are displayed with a yellow background, those sessions that had consumed 50% of a Time Model Statistic are displayed with a deep orange background, and sessions that had consumed 100% of a Time Model Statistic are displayed with a solid red background.

We still have a bit more to add to this tool, so keep an eye open for the next article in this series.

—-

Added March 5, 2011:

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