Parent-Child Relationships and the Questions Left Unanswered by TKPROF, Re-Learning Something Old

30 01 2012

January 30, 2012

As we have seen in the past, TKPROF output sometimes lies, and in a recent OTN thread I was reminded of another case or two where TKPROF output may be misleading.  In the OTN thread, the original poster (OP) started the thread by asking a simple question about an execution plan that appeared in a TKPROF output.  Below is an execution plan that is similar to the one posted by the OP:

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
         1          1          1   INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)(object id 102460) 

For the above execution plan, the trace file was created on Oracle Database 11.2.0.2 and processed with a 11.2.0.1 client with the patch that fixes the ODBC problem.  The original poster (OP) in the OTN thread posed a question about the cr= (consistent gets blocks) and pr= (physical read blocks) statistics.  In the above, the INDEX RANGE SCAN operation shows cr=2 pr=8, and the TABLE ACCESS BY INDEX ROWID operation shows cr=3 pr=16.  The OP questioned whether the TABLE ACCESS BY INDEX ROWID operation statistics included the INDEX RANGE SCAN operation statistics for a total of 3 consistent gets and 16 physical blocks read from disk, or if the TABLE ACCESS BY INDEX ROWID operation statistics are in addition to the INDEX RANGE SCAN operation statistics for a total of 5 consistent gets and 24 physical blocks read from disk.  As sometimes happens with Internet forums, people responding to questions sometimes provide conflicting answers; in this case, at least one person stated that each interpretation is correct.

The OP’s actual Row Source Operation execution plan showed the following:

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS BY INDEX ROWID T (cr=5 pr=11 pw=0 time=0 us cost=4 size=8092 card=1)
      1   INDEX UNIQUE SCAN T_PK (cr=3 pr=6 pw=0 time=0 us cost=2 size=0 card=1)(object id 83084) 

In an attempt to provide the OP with answers to all of his unanswered questions to that point in the thread, I provided the following response:

In the above, the “TABLE ACCESS BY INDEX ROWID” operation is the parent operation and the “INDEX UNIQUE SCAN” is the child operation. The child’s statistics are rolled into the parent’s statistics. In Oracle Database 11.1 and above, the default behavior is to output the STAT lines (that is the Row Source Operation execution plan) after the first execution of the SQL statement. For the first execution of the SQL statement, there were 11 physical block reads, 6 from the index and 5 from the table. There were 5 consistent gets, 3 from the index and 2 from the table. The estimated cost for the index access is 2, and the estimated cost for just the table access is 2.
 
I see that you also used the EXPLAIN option of TKPROF – that can lead to misleading execution plans being written to the TKPROF output, especially when bind variables are involved. The 1 parse call should be expected – it would be bad if there were 72,181 parses, because that would mean that there would be 1 parse per execution – a sign that the cursor was not held open either by the application or by the session cursor cache. Simply enabling a 10046 trace in a session changes the environment for the session, which will typically require a hard parse of previously parsed SQL statements when those SQL statements are re-executed. Note that “recursive depth: 1” appears in the output, which suggests that this SQL statement is found in a PL/SQL block.
 
db file scattered read waits indicate that more than 1 block is read from disk at a time. You can refer to the raw 10046 trace file to determine how many blocks are read on average in the db file scattered read waits.

OK, so if you believe the above quote, the child statistics are rolled into the parent’s statistics, the EXPLAIN option of TKPROF may write incorrect execution plans to the output file especially when bind variables are used, and the original trace file included SQL statements marked with dep=0 or dep=1.  In the thread there was disagreement on the first point, so let’s throw together a very short test case to determine if that point is correct.

First, we will create a simple table with a primary key index, insert  200 rows into the table, and collect statistics on that table:

CREATE TABLE T3 (
  C1 NUMBER,
  C2 VARCHAR2(300),
  PRIMARY KEY(C1));

INSERT INTO
  T3
SELECT
  ROWNUM C1,
  RPAD('A',300,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=200;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,NO_INVALIDATE=>FALSE) 

Next, I want to make certain that the two SQL statements that will be used in the test script will already exist in the library cache (so that we can test whether or not enabling a 10046 trace will cause a hard parse when the SQL statements are re-executed).  I also will set the fetch array size to 1000 to minimize the number of round trips between the server and client (the default fetch array size is 15 for SQL*Plus, and that value would make the generated trace file a bit more difficult to read due to the extra FETCH and SQL*Net wait events).  The second SQL statement, intended to make certain that the STAT lines for the first SQL statement will be written to the 10046 trace file, is only necessary prior to Oracle Database 11.1.0.6:

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000

Now for the final section of the test case script: flush the buffer cache, enable a 10046 trace, and execute the two SQL statements:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING';

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';  

Let’s start by taking a look at the raw 10046 trace file, slightly marked up:

=====================
PARSING IN CURSOR #371254768 len=53 dep=0 uid=62 oct=3 lid=62 tim=184435767875 hv=1334288504 ad='7ffb8c1be40' sqlid='a75xc757sg83s'
SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200
END OF STMT
PARSE #371254768:c=0,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=216260220,tim=184435767874                                <--- hard parse
EXEC #371254768:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=216260220,tim=184435767947
WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=184435767976
WAIT #371254768: nam='db file scattered read' ela= 320 file#=4 block#=4145624 blocks=8 obj#=73036 tim=184435768358          <--- 8 for index
WAIT #371254768: nam='db file scattered read' ela= 276 file#=4 block#=4145616 blocks=8 obj#=73035 tim=184435768704          <--- 8 for table
FETCH #371254768:c=0,e=764,p=16,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=216260220,tim=184435768757
WAIT #371254768: nam='SQL*Net message from client' ela= 110 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768890
WAIT #371254768: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184435768916
WAIT #371254768: nam='db file scattered read' ela= 283 file#=4 block#=4145632 blocks=8 obj#=73035 tim=184435769273          <--- 8 for table
FETCH #371254768:c=0,e=443,p=8,cr=10,cu=0,mis=0,r=199,dep=0,og=1,plh=216260220,tim=184435769349
STAT #371254768 id=1 cnt=200 pid=0 pos=1 obj=73035 op='TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)'
STAT #371254768 id=2 cnt=200 pid=1 pos=1 obj=73036 op='INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)'

*** 2012-01-25 09:17:32.639
WAIT #371254768: nam='SQL*Net message from client' ela= 1142603 driver id=1413697536 #bytes=1 p3=0 obj#=73035 tim=184436912005
CLOSE #371254768:c=0,e=19,dep=0,type=0,tim=184436912120
===================== 

The above shows a hard parse, 8 blocks read by multi-block read for the index, and 16 blocks read by multi-block read for the table.  If we process the trace file with TKPROF, a portion of the TKPROF output should look like this:

********************************************************************************
SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00         24         12          0         200
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00         24         12          0         200

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 62 
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       200        200        200  TABLE ACCESS BY INDEX ROWID T3 (cr=12 pr=24 pw=0 time=762 us cost=10 size=60800 card=200)
       200        200        200   INDEX RANGE SCAN SYS_C008672 (cr=2 pr=8 pw=0 time=1012 us cost=1 size=0 card=200)(object id 73036)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3        1.14          1.14
  db file scattered read                          3        0.00          0.00
******************************************************************************** 

By examining the raw trace file, we are able to confirm that the pr=24 statistic in the first row of the Row Source Execution plan includes the 16 blocks for the table and the 8 blocks from the index, as identified in the raw 10046 trace file.

The OP later asked a handful of questions, including whether or not he should add the statistics found in the OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS section of the TKPROF output to the statistics found in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section.  My first thought was to modify my original test case script shown above like this, so that there is a logging trigger on the T3 table that records changes made to the T3 table in the T4 table:

DROP TABLE T3 PURGE;
DROP TABLE T4 PURGE;

CREATE TABLE T3 (
  C1 NUMBER,
  C2 VARCHAR2(300),
  PRIMARY KEY(C1));

CREATE TABLE T4(
  NEW_C1 NUMBER,
  OLD_C2 VARCHAR2(300),
  NEW_C2 VARCHAR2(300),
  LOG_MODIFIED_USER_ID VARCHAR2(30) DEFAULT USER,
  LOG_MODIFIED_DATE DATE DEFAULT SYSDATE,
  LOG_TRANSACTION_TYPE VARCHAR2(1))
  PCTFREE 0
  PCTUSED 99;

CREATE OR REPLACE TRIGGER HPM_T3 AFTER
INSERT OR DELETE OR UPDATE OF C1, C2 ON T3
REFERENCING OLD AS OLDDATA NEW AS NEWDATA FOR EACH ROW
BEGIN
  IF UPDATING THEN
    IF (NVL(:OLDDATA.C1,0.0000019) <> NVL(:NEWDATA.C1,0.0000019)) OR (NVL(:OLDDATA.C2,'3!3D$FF') <> NVL(:NEWDATA.C2,'3!3D$FF'))  THEN
     INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
     VALUES (
      :NEWDATA.C1,
      :OLDDATA.C2,
      :NEWDATA.C2,
      'U');
    END IF;
  END IF;

  IF DELETING THEN
    INSERT INTO T4 (
      NEW_C1,
      OLD_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :OLDDATA.C1,
      :OLDDATA.C2,
      'D');
  END IF;

  IF INSERTING THEN
    INSERT INTO T4 (
      NEW_C1,
      NEW_C2,
      LOG_TRANSACTION_TYPE)
    VALUES (
      :NEWDATA.C1,
      :NEWDATA.C2,
      'I');
  END IF;
END;
/

INSERT INTO
  T3
SELECT
  ROWNUM C1,
  RPAD('A',300,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=200;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

SET ARRAYSIZE 1000 

Then I would add a new section to the second half of the original test script to update 50 rows of table T3:

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING2';

SELECT /*+ INDEX(T3) */
  *
FROM
  T3
WHERE
  C1<=200;

SELECT
  SYSDATE
FROM
  DUAL;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046TESTING3';

UPDATE
  T3
SET
  C1=C1+1000,
  C2='UPDATED BY 1000'
WHERE
  C1<=50;

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF'; 

-

I decided to abandon that approach, and instead try to reproduce the test script that the OP was attempting to use.  My best guess is that the OP’s test script looks similar to the following:

CREATE TABLE T4 AS
SELECT
  *
FROM
  ALL_OBJECTS;

ALTER TABLE T4 ADD (
  PADDING1 VARCHAR2(4000),
  PADDING2 VARCHAR2(4000));

CREATE INDEX IND_T4_OBJECT_ID ON T4(OBJECT_ID);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

ALTER SESSION SET TRACEFILE_IDENTIFIER = '10046_FIND_ME';
EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );

DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;

        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
/

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE; 

In the script I set the NO_INVALIDATE parameter of the DBMS_STATS.GATHER_TABLE_STATS procedure to FALSE so that the session cursor cache would be flushed of all references to the T4 table, which then leads to the SQL statements appearing in the trace file on repeated executions if you need to execute the script a couple of times from that line of the test script to the end.  I also moved the DBMS_MONITOR.SESSION_TRACE_ENABLE call outside of the anonymous PL/SQL block so that PL/SQL block would be included in the trace file.

After executing the test script, I found the following lines near the start of the generated 10046 trace file:

PARSING IN CURSOR #481810328 len=63 dep=0 uid=64 oct=47 lid=64 tim=2302523409025 hv=2690357649 ad='3edbc1610' sqlid='dsvxr0ah5r6cj'
BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
END OF STMT 

In the above, note the tim=2302523409025 value.  Near the end of the 10046 trace file I found the following lines:

PARSING IN CURSOR #481810424 len=48 dep=0 uid=64 oct=47 lid=64 tim=2302533226450 hv=3127860446 ad='3eb311428' sqlid='80u1a4kx6yr6y'
BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;
END OF STMT

In the above, note the tim=2302533226450 value.

We are able to determine the elapsed time between these two calls with simple mathematics: (2302533226450 – 2302523409025) / 1000000 = 9.817425 seconds elapsed time in the trace file between the start of the 10046 trace and the call to end the 10046 trace.

Now, let’s see if we are able to find another case where TKPROF lies.  We are able to find a hint of the problems in the book “Optimizing Oracle Performance” (see page xv and page 90).  Here is the TKPROF summary for my execution of the test script (generated with this command: tkprof or1122p_ora_19180_10046_FIND_ME.trc or1122p_ora_19180_10046_FIND_ME.txt):

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

Misses in library cache during parse: 2
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.10          0.10

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                      1047        0.00          0.25
  db file scattered read                        182        0.00          0.10
  asynch descriptor resize                      291        0.00          0.00

    4  user  SQL statements in session.
    0  internal SQL statements in session.
    4  SQL statements in session.
********************************************************************************
Trace file: or1122p_ora_19180_10046_FIND_ME.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       4  SQL statements in trace file.
       4  unique SQL statements in trace file.
  220086  lines in trace file.
       9  elapsed seconds in trace file. 

Does the above output indicate that my anonymous PL/SQL block completed in 5.35 seconds, and that the recursive call accounted for 2.1 seconds of that time?  Or, should we add the non-recursive and recursive elapsed times together to determine the total time?  Should we add the total blocks read from disk displayed in the non-recursive portion (0) to the total blocks read from disk displayed in the recursive portion (1240) to determine the total number of blocks read from disk during the execution?  The above statistics indicate that there were 1047 waits for the db file sequential read wait event and 182 waits for the db file scattered read wait event in the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output.  We know that each db file sequential read wait event represents reading one block from disk, and that each db file scattered read wait event represents reading at least 2 blocks from disk.  Let’s try some simple mathematics: 1047 + (2 * 182) = 1411 – the wait event statistics for the OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS section of the TKPROF output indicate that at least 1,411 blocks should have been read from disk, while the TKPROF output only shows 1,240 blocks.  Is TKPROF lying?

Let’s take another look at the raw 10046 trace file.  Very close to the end of the trace file I found the following line:

EXEC #481810328:c=9266459,e=9631079,p=3231,cr=267427,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=2302533148184 

The above indicates that cursor number 481810328 consumed 9.266459 seconds of CPU time, 9.631079 seconds of elapsed time, read 3,231 blocks from disk, and performed 267,427 consistent gets when that cursor was executed – yet that is not in agreement with the above TKPROF output (the numbers are greater than even the non-recursive plus recursive statistics would suggest).  If we search upward in the trace file, we are able to find the code that is associated with cursor number 481810328:

PARSING IN CURSOR #481810328 len=610 dep=0 uid=64 oct=47 lid=64 tim=2302523516952 hv=468044383 ad='3edbc2e48' sqlid='8zytk5ndybkkz'
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
END OF STMT 

That is our anonymous PL/SQL block, which would fall into the non-recursive totals that shows a total of 5.36 seconds of CPU time, 5.35 seconds of elapsed time, 0 blocks read from disk, and 0 consistent gets.

So, did TKPROF answer more questions than it generated?

I was curious, so I processed the trace file using my Hyper-Extended Oracle Performance Monitor program (AKA: Toy Project for Performance Monitoring).  This is the what was written to one of the output files:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      3|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Wait Event Summary:
SQL*Net message to client           0.000010  On Client/Network   Min Wait:     0.000003  Avg Wait:     0.000005  Max Wait:     0.000007  Waits:      2
SQL*Net message from client         0.107469  On Client/Network   Min Wait:     0.006123  Avg Wait:     0.053735  Max Wait:     0.101346  Waits:      2
db file sequential read             0.254673  On DB Server        Min Wait:     0.000023  Avg Wait:     0.000243  Max Wait:     0.001280  Waits:   1047
db file scattered read              0.100087  On DB Server        Min Wait:     0.000088  Avg Wait:     0.000550  Max Wait:     0.004496  Waits:    182
asynch descriptor resize            0.000359  On DB Server        Min Wait:     0.000000  Avg Wait:     0.000001  Max Wait:     0.000004  Waits:    291

Total for Similar SQL Statements in Each Group:
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%
  *    0.101349 seconds of time related to client/network events

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
  *    0.006130 seconds of time related to client/network events
|    ++++++++++++++++||    ++++++++++++++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
  *    0.075437 seconds of time related data file I/O
|                ++++||                ++++|

----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1 
First Reference: Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

End of Summary, Detail Follows
--------------------------------------------------------------------------------------------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 1   Parse at 0.000000 SQL_ID='dsvxr0ah5r6cj'  Similar Cnt 1
|PARSEs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|EXECs        1|CPU S    0.000000|CLOCK S    0.000941|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.01%

BEGIN DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true ); END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 621   Ver 2   Parse at 0.107927 SQL_ID='8zytk5ndybkkz'  (TD Prev 0.107927)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.004720|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    9.266459|CLOCK S    9.631079|ROWs        1|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 82.16%  CLOCK S 82.05%
|    ++++++++++++++++||    ++++++++++++++++|
DECLARE
        type array is table of t4%ROWTYPE index by binary_integer;
        l_data array;
        l_rec t4%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        FOR rs IN 1 .. l_data.count
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM t4 WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 1 (Trigger Code)
Cursor 648   Ver 1   Parse at 2.291806 SQL_ID='5k52u3cqwkkmw'  (TD Prev 2.183879)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.000441|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs    72720|CPU S    0.998405|CLOCK S    1.081928|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|ROWs    72719|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 17.84%  CLOCK S 17.92%
|                ++++||                ++++|
SELECT * FROM T4 WHERE OBJECT_ID = :B1

       (Rows 1)   TABLE ACCESS BY INDEX ROWID T4 (cr=3 pr=16 pw=0 time=1274 us cost=2 size=97 card=1)
       (Rows 1)    INDEX RANGE SCAN IND_T4_OBJECT_ID (cr=2 pr=8 pw=0 time=620 us cost=1 size=0 card=1)

------------
----------------------------------------------------------------------------------
Similar SQL Statements in Group: 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|

Statement Depth 0 (Application Code)
Cursor 717   Ver 1   Parse at 9.817425 SQL_ID='80u1a4kx6yr6y'  (TD Prev 7.525619)  Similar Cnt 1
|PARSEs       1|CPU S    0.000000|CLOCK S    0.001312|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|EXECs        1|CPU S    0.000000|CLOCK S    0.001095|ROWs        1|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0|
  CPU S 0.00%  CLOCK S 0.02%

BEGIN DBMS_MONITOR.SESSION_TRACE_DISABLE; END;

So, what does the above indicate when compared with the TKPROF output?

Let’s look at the summary again from TKPROF:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.00          0          0          0           0
Execute      3      5.36       5.34          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      5.36       5.35          0          0          0           3

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  72720      0.99       1.08          0          0          0           0
Fetch    72720      1.01       1.02       1240     218319          0       72719
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   145441      2.01       2.10       1240     218319          0       72719 

And the summary from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319| 

My program double counted the CPU time and elapsed time (and ? … see below) from the recursive calls.  TKPROF only reported the consistent gets (218,319) and physical blocks read from disk (1,240) from the recursive FETCH lines in the trace file, but discarded those statistics from the non-recursive EXEC lines in the trace file.  That possibly explans why the number of db file single block read waits plus two times the number of db file scattered read waits exceeds the number reported in the disk column of the TKPROF output:

1047 + (2 * 182) = 1411 > 1200

The partially interesting item is that the db file scattered read waits, on average, read 12.00 blocks at a time, and the many of the db file scattered read waits are attributed to a mysterious cursor #482246872.  Another output of my program is an Excel spreadsheet that lists all wait events found in the trace file.  I added the following formula in cell F2 and copied that formula down to the last wait event line:

=IF(C2="db file sequential read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

I added the following formula in cell G2 and copied that formula down to the last wait event line:

=IF(C2="db file scattered read",VALUE(MID(D2,FIND("blocks=",D2)+7,FIND(" ",D2,FIND("blocks",D2)+1) - (FIND("blocks=",D2)+7))),"")

With those two formulas in place, I was able to determine the actual number of physical block reads, and whether or not the blocks were read one at a time, or more than one block at a time.  The resulting Excel spreadsheet looks like this:

 

So, the above screen captures show that there were 9.8159 seconds in the trace file between the first and last tim= values.  The last of the above screen captures shows there were in total 1,047 single block reads (db file sequential read waits) and 182 multi-block reads (db file scattered read waits), with a total of 2,184 blocks read by multi-block read for an average of 12 blocks per multi-block read.

Let’s take another look at the other output file from my program:

Total for Trace File:
|PARSEs       3|CPU S    0.000000|CLOCK S    0.006473|PHY RD BLKs         0|CON RD BLKs (Mem)         0|
|EXECs    72723|CPU S   10.264864|CLOCK S   10.715043|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|
|FETCHs   72720|CPU S    1.014008|CLOCK S    1.021754|PHY RD BLKs      1240|CON RD BLKs (Mem)    218319|  

Well, it seems that the recursive SQL has caused a bit of a problem for my program.  The 1,240 physical block reads found on the FETCHs line are actually included in the 3,231 (1,047 + 2,184) physical block reads found on the EXECs line.

As a final self-answering question, which is worse: that TKPROF reports only 1,240 physical block reads, or that my program double-counts these 1,240 physical block reads and suggest that there were 4,471 physical block reads?  Maybe we should just ignore the recursive SQL statistics by checking an option box in my program:

Total for Trace File:
|PARSEs       2|CPU S    0.000000|CLOCK S    0.006032|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      2|
|EXECs        3|CPU S    9.266459|CLOCK S    9.633115|ROWs        3|PHY RD BLKs      3231|CON RD BLKs (Mem)    267427|CUR RD BLKs (Mem)         0|SHARED POOL MISs      1|
|FETCHs       0|CPU S    0.000000|CLOCK S    0.000000|ROWs        0|PHY RD BLKs         0|CON RD BLKs (Mem)         0|CUR RD BLKs (Mem)         0|SHARED POOL MISs      0| 

That option in my program fixed the CPU seconds, elapsed time, total physical blocks read, and total consistent gets, but now the number of EXECsFETCHs, and ROWs do not match what is found in the raw 10046 trace file.

As the above Excel output and my program’s fixed output demonstrates, sometimes there is no replacement for examining the raw 10046 trace files.





Non-Specific Index Hints

24 01 2012

January 24, 2012 (Modified January 25, 2012)

As I read the “Troubleshooting Oracle Performance” book for the second time a couple of months ago, I made note on page 385 that it was possible to specify table columns in an index hint, rather than specifying specific index names (or just specifying the table name).  This might be useful, for example, if you have tables in your database with primary key columns with system assigned names for the supporting indexes, and an index hint is needed to correct specific performance issues.  I was again reminded that it was possible to create non-specific index hints that specify table columns when a recent quiz was posted that asked to find specific cases where the behavior is other than expected with the newer index hint syntax.

As an example of the newer syntax, I put together a brief demonstration.  First, the test table and index creation script:

CREATE TABLE T2 (
  C1 NUMBER,
  C2 NUMBER,
  C3 VARCHAR2(100),
  PRIMARY KEY(C1));

INSERT INTO
  T2
SELECT
  ROWNUM C1,
  MOD(ROWNUM-1,20)+1 C2,
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE INDEX IND_T2_C2 ON T2(C2);

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

SET AUTOTRACE TRACEONLY EXPLAIN
SET LINESIZE 120
SET PAGESIZE 1000 

Let’s try a simple query that specifies columns C1 and C2 in the WHERE clause:

SELECT
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Plan hash value: 906133967

------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |             |   500 | 54500 |   121   (1)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID     | T2          |   500 | 54500 |   121   (1)| 00:00:01 |
|   2 |   BITMAP CONVERSION TO ROWIDS    |             |       |       |            |          |
|   3 |    BITMAP AND                    |             |       |       |            |          |
|   4 |     BITMAP CONVERSION FROM ROWIDS|             |       |       |            |          |
|*  5 |      INDEX RANGE SCAN            | IND_T2_C2   |       |       |    10   (0)| 00:00:01 |
|   6 |     BITMAP CONVERSION FROM ROWIDS|             |       |       |            |          |
|   7 |      SORT ORDER BY               |             |       |       |            |          |
|*  8 |       INDEX RANGE SCAN           | SYS_C008661 |       |       |    20   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------

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

The above shows that if this SQL statement were actually executed, the index IND_T2_C2, and the index SYS_C008661 (that is used to help enforce the primary key) would be used when executing the SQL statement.  You will only see the above execution plan in the Enterprise Edition of Oracle Database.  Let’s try again with a hint that prohibits the BITMAP CONVERSION TO FROM ROWIDS operation:

SELECT /*+ OPT_PARAM('_B_TREE_BITMAP_PLANS','FALSE') */
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Execution Plan
----------------------------------------------------------
Plan hash value: 1513984157

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   500 | 54500 |   131   (2)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T2   |   500 | 54500 |   131   (2)| 00:00:01 |
--------------------------------------------------------------------------

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

The above execution plan shows that without the ability to perform the  the BITMAP CONVERSION TO FROM ROWIDS operation to allow the BITMAP AND operation, a full table scan was selected, so this is a case where the Standard Edition of Oracle Database and the Enterprise Edition might exhibit different execution performance.

Let’s use the previous SQL statement with hint as a starting point, and use a non-specific index hint to instruct the optimizer to use an index on the T2 table:

SELECT /*+ INDEX(T2) OPT_PARAM('_B_TREE_BITMAP_PLANS','FALSE') */
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Plan hash value: 3350885058

-------------------------------------------------------------------------------------------
| Id  | Operation                   | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |             |   500 | 54500 |   179   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS BY INDEX ROWID| T2          |   500 | 54500 |   179   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | SYS_C008661 | 10000 |       |    20   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

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

As shown by the above, the optimizer selected to use the SYS_C008661 primary key index, which would require it to retrieve 10,000 ROWID values from the index, rather than using the index on the T2 column which would have retrieved 5,000 (100,000 * 1/20) ROWIDs from the IND_T2_C2 index (the clustering factor of the IND_T2_C2 index was likely the deciding factor).  Let’s specifically request (demand) that the optimizer use the IND_T2_C2 index by adjusting the hint:

SELECT /*+ INDEX(T2 IND_T2_C2) OPT_PARAM('_B_TREE_BITMAP_PLANS','FALSE') */
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Plan hash value: 174424276

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |   500 | 54500 |  1596   (1)| 00:00:01 |
|*  1 |  TABLE ACCESS BY INDEX ROWID| T2        |   500 | 54500 |  1596   (1)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T2_C2 |  5000 |       |    10   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

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

Notice in the above that the IND_T2_C2 index was selected, is expected to return 5,000 ROWID values from the index, and the execution plan now has a calculated cost of 1,596.  The calculated cost is a simple explanation why the optimizer did not select to use this index automatically.

Now, consider a situation where the optimizer insists on using the IND_T2_C2 index, rather than the SYS_C008661 primary key index for this SQL statement, which could happen if the CLUSTERING_FACTOR of the indexes are not set correctly:

SET AUTOTRACE OFF

SELECT
  INDEX_NAME,
  CLUSTERING_FACTOR
FROM
  USER_INDEXES
WHERE
  TABLE_NAME='T2';

INDEX_NAME   CLUSTERING_FACTOR
------------ -----------------
SYS_C008661               1585
IND_T2_C2                31700

EXEC DBMS_STATS.SET_INDEX_STATS (OWNNAME=>USER,INDNAME=>'IND_T2_C2',CLSTFCT=>1585,NO_INVALIDATE=>FALSE)

SELECT
  INDEX_NAME,
  CLUSTERING_FACTOR
FROM
  USER_INDEXES
WHERE
  TABLE_NAME='T2';

INDEX_NAME   CLUSTERING_FACTOR
------------ -----------------
SYS_C008661               1585
IND_T2_C2                 1585 

We started with the primary key index having a clustering factor of 1,585 and the IND_T2_C2 index having a clustering factor of 31,700.  After using DBMS_STATS.SET_INDEX_STATS, the optimizer is convinced that the IND_T2_C2 index also has a clusting factor of 1,585.  Now both of the indexes have the same CLUSTERING_FACTOR statistic value, what happens if we execute the SQL statement again that specifies an index should be used to access table T1, but does not specify the exact index name?:

SELECT /*+ INDEX(T2) OPT_PARAM('_B_TREE_BITMAP_PLANS','FALSE') */
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Execution Plan
----------------------------------------------------------
Plan hash value: 174424276

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |   500 | 54500 |    90   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS BY INDEX ROWID| T2        |   500 | 54500 |    90   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | IND_T2_C2 |  5000 |       |    10   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

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

So, now that the CLUSTERING_FACTOR values are the same for both indexes, the optimizer is selecting the IND_T2_C2 index for the SQL statement.  We have successfully painted ourselves into a corner, telling the optimizer that the IND_T2_C2 index really is helpful for this SQL statement.  We are fairly certain that the IND_T2_C2 index is not ideal, and that the the SYS_C008661 primary key index is a better choice if an index access path is determined to be better than a full table scan, based on the order in which the data was inserted into the table’s blocks.  The problem now is that the SYS_C008661 index name is not consistent from one database to the next, or even in the same database if you drop table T2 and repeat the test.  How do we tell the optimizer to pick the index that is on the primary key column, column C1?  Oracle Database 10.1 introduced new syntax for index hints, which allows us to specify the column name(s), rather than the index name in the hint:

SELECT /*+ INDEX(T2 (C1)) OPT_PARAM('_B_TREE_BITMAP_PLANS','FALSE') */
  C1,
  C2,
  C3
FROM
  T2
WHERE
  C1 BETWEEN 1 AND 10000
  AND C2=1;

Plan hash value: 3350885058

-------------------------------------------------------------------------------------------
| Id  | Operation                   | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |             |   500 | 54500 |   179   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS BY INDEX ROWID| T2          |   500 | 54500 |   179   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | SYS_C008661 | 10000 |       |    20   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------

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

As can be seen by the above, the index on column C1, which happens to be the primary key index, was selected by the optimizer at the request of the index hint.

Let’s take a look at the documentation for Oracle Database 10.2:

“Hints that specify an index can use either a simple index name or a parenthesized list of columns as follows:

index (table (column))
  • table specifies the name
  • columnspecifies the name of a column in the specified table
    • The columns can optionally be prefixed with table qualifiers allowing the hint to specify bitmap join indexes where the index columns are on a different table than the indexed table. If tables qualifiers are present, they must be base tables, not aliases in the query.
    • Each column in an index specification must be a base column in the specified table, not an expression. Function-based indexes cannot be hinted using a column specification unless the columns specified in the index specification form the prefix of a function-based index.
  • index specifies an index name

The hint is resolved as follows:

  • If an index name is specified, only that index is considered.
  • If a column list is specified and an index exists whose columns match the specified columns in number and order, only that index is considered. If no such index exists, then any index on the table with the specified columns as the prefix in the order specified is considered. In either case, the behavior is exactly as if the user had specified the same hint individually on all the matching indexes.

For example, in Example 16-3 the job_history table has a single-column index on the employee_id column and a concatenated index on employee_id and start_date columns. To specifically instruct the optimizer on index use, the query can be hinted as follows:

SELECT /*+ INDEX(v.j jhist_employee_ix (employee_id start_date)) */ * FROM v;

That is almost crystal clear (I probably poorly translated the diagram), even though it seems that the cost calculation might not have an impact (“If no such index exists, then any index on the table with the specified columns as the prefix in the order specified is considered“).  If you have the sample database schema loaded into a database, jump to the view definition in Example 16-3, create the view, and then see if the index hint in the documentation (at the bottom of the above quote block) actually works – it did not work for me.  The same hint example is found in the Oracle Database 11.2 documentation.

However, in the example above, where I used the hint syntax INDEX (TABLE (COLUMN)), the hint worked as expected.  Interestingly, the hint reference for Oracle Database 11.2 does not specifically mention this new syntax, and that might be why I was slow to recognize the new hint syntax.

Now that the basics are covered, let’s see if we are able to confuse the optimizer with index hints, taking up the challenge proposed by the blog article mentioned at the start of this article.  Below is a slightly modified version of the test script that I posted as a comment in the other blog article (with an additional column in the table, an additional index, and an enabled 10053 trace).  First, we will create the table, a couple of indexes on the table, change a couple of SQL*Plus parameters, and then enable a 10053 trace:

CREATE TABLE T1 (
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(30) NOT NULL,
  C4 VARCHAR2(200),
  C5 VARCHAR2(10));

INSERT INTO T1
SELECT
  MOD(ROWNUM-1, 90) * 4 C1,
  ROWNUM - 1 C2,
  TO_CHAR(ROWNUM - 1, 'RN') C3,
  LPAD('A',200,'A') C4,
  LPAD('B',10,'B') C5
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

CREATE INDEX IND_T1_C1_C2 ON T1(C1,C2);
CREATE INDEX IND_T1_C1_C2_C5 ON T1(C1,C2,C5);
CREATE INDEX IND_T1_C2_C1_C3 ON T1(C2,C1,C3);
CREATE INDEX IND_T1_C3_C1_C2 ON T1(C3,C1,C2);

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

SET AUTOTRACE TRACEONLY EXPLAIN
SET LINESIZE 120
SET PAGESIZE 1000
ALTER SESSION SET EVENTS '10053 TRACE NAME CONTEXT FOREVER, LEVEL 1';

Let’s begin the process of trying to confuse the Oracle Database 11.2.0.2 optimizer.  Unhinted, the following query accesses the index on columns C2, C1, and C3 to avoid accessing the table, and uses an INDEX FAST FULL SCAN operation that employs multi-block reads :

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'UNHINTED';

SELECT
  C1,
  C2,
  C3
FROM
  T1;

Plan hash value: 2374279026

----------------------------------------------------------------------------------------
| Id  | Operation            | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                 |  1000K|    23M|   387   (2)| 00:00:01 |
|   1 |  INDEX FAST FULL SCAN| IND_T1_C2_C1_C3 |  1000K|    23M|   387   (2)| 00:00:01 |
----------------------------------------------------------------------------------------

Let’s hint the optimizer to use the index on the columns C1 and C2:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2';

SELECT /*+ INDEX(T1 (C1 C2)) */
  C1,
  C2,
  C3
FROM
  T1;

Plan hash value: 3388050039
--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |  1000K|    23M|  1012K  (1)| 00:06:46 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |  1000K|    23M|  1012K  (1)| 00:06:46 |
|   2 |   INDEX FULL SCAN           | IND_T1_C1_C2 |  1000K|       |  3026  (10)| 00:00:02 |
--------------------------------------------------------------------------------------------

In the above, the optimizer obeyed the hint, even though the calculated cost from the unhinted plan increased from 387 to 1,012,000, and the optimizer selected to perform an INDEX FULL SCAN operation.

Let’s reverse the order of the columns in the index hint:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C2_C1';

SELECT /*+ INDEX(T1 (C2 C1)) */
  C1,
  C2,
  C3
FROM
  T1;

Execution Plan
----------------------------------------------------------
Plan hash value: 1746297295

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |  1000K|    23M|  4851   (1)| 00:00:01 |
|   1 |  INDEX FULL SCAN | IND_T1_C2_C1_C3 |  1000K|    23M|  4851   (1)| 00:00:01 |
------------------------------------------------------------------------------------

In the above, note that the index on columns C2, C1, and C3 was used, but the cost is now calculated at 4,851 rather than 387 as it was in the unhinted plan. The INDEX FAST FULL SCAN operation is now shown as an INDEX FULL SCAN operation.  So, we have now convinced the optimizer to use an access path that employs single block reads of an index rather than multi-block reads of an index, simply by telling the optimizer to use the index that it would have used without the hint.  Have we confused the optimizer already?  Someone should probably take a look at the 10053 trace files.  :-)

We have an index on columns C2, C1, and C3, but we also have an index on columns C3, C1, and C2. What happens when we specify the columns C3, C1, and C2 in the index hint in that order?

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C3_C1_C2';

SELECT /*+ INDEX(T1 (C3 C1 C2)) */
  C1,
  C2,
  C3
FROM
  T1;

Plan hash value: 2273443829

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |  1000K|    23M|  4943   (1)| 00:00:01 |
|   1 |  INDEX FULL SCAN | IND_T1_C3_C1_C2 |  1000K|    23M|  4943   (1)| 00:00:01 |
------------------------------------------------------------------------------------

An index full scan was selected to be performed on the IND_T1_C3_C1_C2 index with a calculated cost of 4,943, rather than using the IND_T1_C2_C1_C3 index that previously resulted in a cost of 4,851 – so the optimizer will not alter the order of the columns in the index hint to reduce the calculated cost.

Let’s try another example where we select all of the columns that are present in the IND_T1_C1_C2_C5 index – will the optimizer use that index, or will it obey the expected behavior of the index hint?:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_WC5';

SELECT /*+ INDEX(T1 (C1 C2)) */
  C1,
  C2,
  C5
FROM
  T1;

Execution Plan
----------------------------------------------------------
Plan hash value: 3388050039

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |  1000K|    19M|  1003K  (1)| 00:00:23 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |  1000K|    19M|  1003K  (1)| 00:00:23 |
|   2 |   INDEX FULL SCAN           | IND_T1_C1_C2 |  1000K|       |  2750   (1)| 00:00:01 |
--------------------------------------------------------------------------------------------

The index that exactly included the columns specified in the index hint was selected, with a calculated cost of 1,003,000.

So, what happens if we are less specific in the index hint, and just list the first column, where there are two composite indexes that start with the specified column:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_WC2_C5';

SELECT /*+ INDEX(T1 (C1)) */
  C1,
  C2,
  C5
FROM
  T1;

Execution Plan
----------------------------------------------------------
Plan hash value: 2942389535

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |  1000K|    19M|  4293   (1)| 00:00:01 |
|   1 |  INDEX FULL SCAN | IND_T1_C1_C2_C5 |  1000K|    19M|  4293   (1)| 00:00:01 |
------------------------------------------------------------------------------------

As shown in the above execution plan, the optimizer arrived at a cost of 4,293 by selecting to use the IND_T1_C1_C2_C5 index, which avoided the access to the T1 table.  So, sometimes the performance will be better with slightly less specific hints.

Out of curiosity, what do you think will happen if we completely eliminate the index hint?  Let’s test:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'UNHINTED_C1_C2_C5';

SELECT
  C1,
  C2,
  C5
FROM
  T1;

Execution Plan
----------------------------------------------------------
Plan hash value: 2722951733

----------------------------------------------------------------------------------------
| Id  | Operation            | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |                 |  1000K|    19M|   343   (3)| 00:00:01 |
|   1 |  INDEX FAST FULL SCAN| IND_T1_C1_C2_C5 |  1000K|    19M|   343   (3)| 00:00:01 |
----------------------------------------------------------------------------------------

In the above execution plan, the IND_T1_C1_C2_C5 index is still selected for use as it was in the previous execution plan, but notice that the access path has changed to an INDEX FAST FULL SCAN operation and the calculated cost dropped from 4,293 to 343.  So, the above output implies that sometimes the performance will be better if we simply do not hint an index access path, if the index access path would have been selected otherwise.  Someone want to take a look at the 10053 trace files and explain why?

If we add a WHERE clause that places a restriction on column C2 to be less than 10, the optimizer could use a couple of different access paths. Let’s specify the columns C1 and C2 in the index hint to see which index is selected:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_C2_WHERE';

SELECT /*+ INDEX(T1 (C1 C2)) */
  C1,
  C2,
  C3
FROM
  T1
WHERE
   C2<10;

Plan hash value: 1883798457

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |    10 |   250 |   103   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |    10 |   250 |   103   (0)| 00:00:01 |
|*  2 |   INDEX SKIP SCAN           | IND_T1_C1_C2 |    10 |       |    92   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"<10)
       filter("C2"<10)

In the above, an INDEX SKIP SCAN operation was selected because the index with columns C1 and C2 was specified in the hint.

Let’s try another example that possibly might be considered a case where the optimizer disobeys the hint or is free to change the order of the columns specified in the index hint (this might be incorrectly considered an edge case):

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_C3_C2_WHERE';

SELECT /*+ INDEX(T1 (C1 C2 C3)) */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2<10;

Plan hash value: 4150417361

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |    10 |   250 |     3   (0)| 00:00:01 |
|*  1 |  INDEX RANGE SCAN| IND_T1_C2_C1_C3 |    10 |   250 |     3   (0)| 00:00:01 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("C2"<10)

A quick peek at the above output might suggest that the optimizer could potentially decide to locate an index with columns C1, C2, and C3 in any order – but I do not believe that this is the case. I believe that the optimizer considered the index hint specified in the SQL statement as being invalid (a check of the 10053 trace might confirm).

Let’s create another index and then repeat the above SQL statement:

CREATE INDEX IND_T1_C1_C2_C3 ON T1(C1,C2,C3);

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_C3_C2_WHERE2';

SELECT /*+ INDEX(T1 (C1 C2 C3)) */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2<10;

Plan hash value: 212907557

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |    10 |   250 |    92   (0)| 00:00:01 |
|*  1 |  INDEX SKIP SCAN | IND_T1_C1_C2_C3 |    10 |   250 |    92   (0)| 00:00:01 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("C2"<10)
       filter("C2"<10)

The index with the columns that matched the order of the columns in the index hint was selected, even though the calculated cost would have been lower if the optimizer were permitted to select any index with the columns listed in the index hint.

What about a case where there is an exact match between an index definition and an index hint, and there is also another index with one additional column which would avoid the table access:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_C2_WHERE2';

SELECT /*+ INDEX(T1 (C1 C2)) */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2<10;

Plan hash value: 1883798457

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |    10 |   250 |   103   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |    10 |   250 |   103   (0)| 00:00:01 |
|*  2 |   INDEX SKIP SCAN           | IND_T1_C1_C2 |    10 |       |    92   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C2"<10)
       filter("C2"<10)

The index that exactly matched the index hint was selected by the optimizer.

What if we only specify in the index hint a leading column, when there are two indexes with that leading column, one of which allows the optimizer to avoid the table access:

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C1_C2_WHERE';

SELECT /*+ INDEX(T1 (C1)) */
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C2<10;

Plan hash value: 212907557

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |    10 |   250 |    92   (0)| 00:00:01 |
|*  1 |  INDEX SKIP SCAN | IND_T1_C1_C2_C3 |    10 |   250 |    92   (0)| 00:00:01 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("C2"<10)
       filter("C2"<10)

The optimizer selected the lowest cost access path from the two indexes that matched the hint.

What if we specify a column in the index hint that is not listed in the SELECT or WHERE clauses?

ALTER SESSION SET TRACEFILE_IDENTIFIER = 'HINT_C3_C2_WHERE';

SELECT /*+ INDEX(T1 (C3)) */
  C1,
  C2
FROM
  T1
WHERE
  C2<10;

Plan hash value: 1328421701

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |    10 |    90 |  4039   (1)| 00:00:02 |
|*  1 |  INDEX SKIP SCAN | IND_T1_C3_C1_C2 |    10 |    90 |  4039   (1)| 00:00:02 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("C2"<10)
       filter("C2"<10)

The above shows the original execution plan (captured a couple of days ago without column C5 in the table definition, without index IND_T1_C1_C2_C5, and without an enabled 10053 trace), which shows that the optimizer still obeyed the intention of the hint – it found an index that started with the specified column and selected to perform an INDEX SKIP SCAN operation even though column C2, specified in the WHERE clause, is the third column in the index definition.

As luck would have it, with the slightly altered table definition (and possibly different statistics estimates) the execution plan has changed to use an INDEX FULL SCAN operation rather than an INDEX SKIP SCAN operation, and now the execution plan has a higher calculated cost.  So, why did the execution plan change from an INDEX SKIP SCAN?  Here is the current execution plan:

Execution Plan
----------------------------------------------------------
Plan hash value: 2273443829

------------------------------------------------------------------------------------
| Id  | Operation        | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |                 |    10 |    90 |  4945   (1)| 00:00:01 |
|*  1 |  INDEX FULL SCAN | IND_T1_C3_C1_C2 |    10 |    90 |  4945   (1)| 00:00:01 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("C2"<10)
       filter("C2"<10)

So, for the challenge, try to explain the oddities that I pointed out above.  I have not yet reviewed the 10053 trace files, but I will later.





Finding the Next Primary Key Value, a Pre-fixed Solution

20 01 2012

January 20, 2012

A request for assistance came in from an ERP mailing list.  The original poster (OP) is running an unspecified version of Oracle Database 9i, and is in need of a solution to generate new part numbers with prefixed characters that describe the type of part, followed by a sequential number that is unique to the prefix.  The prefixes might be PAINT, BAR, BEARING, DRILL, etc.  Sample part numbers might include BAR0599, PAINT012, BEARING012345, etc.

When I first saw the request, my first thought was to create sequences for the different prefixes, similar to the following:

CREATE SEQUENCE PART_PAINT_ID START WITH 13 NOCACHE;
CREATE SEQUENCE PART_BAR_ID START WITH 600 NOCACHE;
CREATE SEQUENCE PART_BEARING_ID START WITH 12346 NOCACHE;
CREATE SEQUENCE PART_DRILL_ID START WITH 999 NOCACHE;
...

Once the above sequences are created, we could then find the next part number with a SQL statement similar to the following:

SELECT
  'PAINT'||PART_PAINT_ID.NEXTVAL NEXT_PART_ID
FROM
  DUAL;

NEXT_PART_ID
------------
PAINT13 

I suspected that there was a catch – for some reason the sample part numbers included a 0 before the sequence number, and I assumed that there could be a variable number of 0 digits before that sequence number for the different prefixes.  To fix the above, we might try working with the LPAD function to add leading zeros to the sequence number:

SELECT
  'PAINT'||LPAD(TO_CHAR(PART_PAINT_ID.NEXTVAL), 3, '0') NEXT_PART_ID
FROM
  DUAL;

NEXT_PAR
--------
PAINT014 

Need more leading zeros?  No problem, just adjust the number in the LPAD function:

SELECT
  'PAINT'||LPAD(TO_CHAR(PART_PAINT_ID.NEXTVAL), 6, '0') NEXT_PART_ID
FROM
  DUAL;

NEXT_PART_I
-----------
PAINT000015 

Need fewer zeros?:

SELECT
  'PAINT'||LPAD(TO_CHAR(PART_PAINT_ID.NEXTVAL), 1, '0') NEXT_PART_ID
FROM
  DUAL;

NEXT_P
------
PAINT1 

The above shows the first of several potential problems with this approach.  What else could go wrong?  What if a smart person decides that he does not need this “crutch” solution and creates 30 part numbers using the method of best guess or cheat sheet in the side drawer?  Because these are primary key values, the smart person might cause a number of problems that might not be detected for some time… until the Oracle sequence reaches one of the unexpected sequence numbers that were already used.

In addition to the suggestion of Oracle sequences, I offered a couple of other suggestions.  The ERP system offers a macro language that is a lot like VBScript.  The OP could create a VBScript that builds a HTML web page in real time, or possibly pull the next sequence number from a ASP (or similar) web page.  As an example of a HTML web page built in real time, this is an example that I created roughly three years ago:

Dim objIE
Dim objShell
Dim strHTML
Dim intFlag

On Error Resume Next

Set objShell = CreateObject("WScript.Shell")
strHTML = strHTML & "<form name=""Visual"">" & vbCrLf
strHTML = strHTML & "<input type=hidden id=txtOK value="" "">" & vbCrLf

strHTML = strHTML & "<table>" & vbCrLf
strHTML = strHTML & "<tr><td>Component<td><select size=""1"" id=""cboComponent"" name=""cboComponent"" style=""width:150"">" & vbCrLf
strHTML = strHTML & "<option value=""ACTIVATOR"">ACTIVATOR</option>" & vbCrLf
strHTML = strHTML & "<option value=""ACCELERATOR"">ACCELERATOR</option>" & vbCrLf
strHTML = strHTML & "<option value=""CATALYST"">CATALYST</option>" & vbCrLf
strHTML = strHTML & "<option value=""EPOXY PRIMER"">EPOXY PRIMER</option>" & vbCrLf
strHTML = strHTML & "<option value=""PRIMER"">PRIMER</option>" & vbCrLf
strHTML = strHTML & "<option value=""REDUCER"">REDUCER</option>" & vbCrLf
strHTML = strHTML & "<option value=""TOP COAT"">TOP COAT</option>" & vbCrLf
strHTML = strHTML & "</select></td></tr>" & vbCrLf

strHTML = strHTML & "<tr><td>Vendor<td><select size=""1"" id=""cboVendor"" name=""cboVendor"" style=""width:150"">" & vbCrLf
strHTML = strHTML & "<option value=""DUPONT"">DUPONT</option>" & vbCrLf
strHTML = strHTML & "<option value=""LILLY"">LILLY</option>" & vbCrLf
strHTML = strHTML & "<option value=""NILES CHEMICAL"">NILES CHEMICAL</option>" & vbCrLf
strHTML = strHTML & "<option value=""MANITOWOC"">MANITOWOC</option>" & vbCrLf
strHTML = strHTML & "<option value=""MAUTZ"">MAUTZ</option>" & vbCrLf
strHTML = strHTML & "<option value=""PAINTS AND SOLVENTS"">PAINTS AND SOLVENTS</option>" & vbCrLf
strHTML = strHTML & "<option value=""SHEBOYGAN"">SHEBOYGAN</option>" & vbCrLf
strHTML = strHTML & "</select></td></tr>" & vbCrLf

strHTML = strHTML & "<tr><td>Type<td><select size=""1"" id=""cboType"" name=""cboType"" style=""width:150"">" & vbCrLf
strHTML = strHTML & "<option value=""FLAT"">FLAT</option>" & vbCrLf
strHTML = strHTML & "<option value=""GLOSS"">GLOSS</option>" & vbCrLf
strHTML = strHTML & "<option value=""MED. GLOSS"">MED. GLOSS</option>" & vbCrLf
strHTML = strHTML & "</select></td></tr>" & vbCrLf

strHTML = strHTML & "<tr><td>Color<td><select size=""1"" id=""cboColor"" name=""cboColor"" style=""width:150"">" & vbCrLf
strHTML = strHTML & "<option value=""RED"">RED</option>" & vbCrLf
strHTML = strHTML & "<option value=""YELLOW"">YELLOW</option>" & vbCrLf
strHTML = strHTML & "<option value=""GREEN"">GREEN</option>" & vbCrLf
strHTML = strHTML & "<option value=""BLUE"">BLUE</option>" & vbCrLf
strHTML = strHTML & "<option value=""BLACK"">BLACK</option>" & vbCrLf
strHTML = strHTML & "<option value=""WHITE"">WHITE</option>" & vbCrLf
strHTML = strHTML & "<option value=""GRAY"">GRAY</option>" & vbCrLf
strHTML = strHTML & "</select></td></tr>" & vbCrLf
strHTML = strHTML & "</table>" & vbCrLf

strHTML = strHTML & "<p><center><input type=button value=""OK"" id=cmdOK onclick=""document.getElementById('txtOK').value='OK';""></center>" & vbCrLf
strHTML = strHTML & "</form>" & vbCrLf

Set objIE = CreateObject("InternetExplorer.Application")
objIE.Navigate "about:blank"
objIE.Document.Body.InnerHTML = strHTML
objIE.Document.Title="Get Part Info"
objIE.Left = 0
objIE.Top = 0
objIE.Width = 400
objIE.Height = 400
objIE.Statusbar = False
objIE.Menubar = False
objIE.Toolbar = False

objIE.Visible = True

Do While objIE.Busy <> False
    objShell.Sleep 200
Loop

intFlag = 0

'loop until the button is clicked
Do While intFlag = 0
    If Err <> 0 Then
        IntFlag = -1
    End If   
    If objIE is Nothing Then
        'User closed ID
        intFlag = -1
    Else
        If objIE.Document.All.txtOK.Value <> " " Then
            intFlag = 1
        End If
    End If
    'objShell.Sleep 250 'Throws an error?
Loop

If intFlag = 1 Then
    'Copy in the values from the web page
    USER_1 = objIE.Document.Body.All.cboComponent.Value
    USER_2 = objIE.Document.Body.All.cboVendor.Value
    USER_3 = objIE.Document.Body.All.cboType.Value
    USER_4 = objIE.Document.Body.All.cboColor.Value

    objIE.Quit
End If

Set objIE = Nothing
Set objShell = Nothing
 

The result of the above VBScript is an interactive interface that appears similar to the following:

Another option that I suggested to the OP is to use Excel to keep track of the last sequence number for each prefix – and use an Excel dialog displayed from a VBScript macro.  Roughly three years ago I created a sample macro with the following code:

Dim objExcel
Dim objForm
Dim objShell

On Error Resume Next

Set objExcel = CreateObject("Excel.Application")

'with the help of custom program, set a 1 second delay, then force the window to the top
Set objShell = CreateObject("WScript.Shell")
objShell.Run("C:\BringToTop.exe " & Chr(34) & "Paint Naming" & Chr(34) & " 2")
Set objShell = Nothing

With objExcel
    .Workbooks.Open "C:\ExcelMacroDialog.xls"

    If .Sheets("CalculateArea").Cells(1, 1).Value <> "" Then
        ID = .Sheets("CalculateArea").Cells(1, 1).Value
        DESCRIPTION = .Sheets("CalculateArea").Cells(2, 1).Value
        PRODUCT_CODE = .Sheets("CalculateArea").Cells(3, 1).Value
        COMMODITY_CODE = .Sheets("CalculateArea").Cells(4, 1).Value
        USER_5 = .Sheets("CalculateArea").Cells(5, 1).Value
        PURCHASED = True
        FABRICATED = False
    End If
End With

objExcel.DisplayAlerts = False
objExcel.ActiveWorkbook.Saved = True
objExcel.Quit
Set objExcel = Nothing  

The above macro is quite short, because most of the work is performed in the Excel spreadsheet.  The resulting Excel dialog appeared similar to this:

My first suggestion to the OP, not knowing the full scope of the problem, was to try coding a VBScript macro similar to the following:

Dim strPartID
Dim strPartIDNew
Dim strNumberOld
Dim strNumberNew
Dim i

strPartID = PART_ID
strNumberOld = ""

'strPartID = "PAINT0599"  'Remove this line after testing
strPartID = "PAINT0089"  'Remove this line after testing

For i = Len(strPartID) to 1 Step -1
  If (Mid(strPartID, i, 1) >= "0") And (Mid(strPartID, i, 1) <= "9") Then
    strNumberOld = Mid(strPartID, i, 1) & strNumberOld
  Else
    strNumberNew = cStr(cInt(strNumberOld) + 1)

    strPartIDNew = Left(strPartID, i)
    If Len(strNumberOld) > Len(strNumberNew) Then
      'Add Padding 0s
      strPartIDNew = strPartIDNew & String((Len(strNumberOld) - Len(strNumberNew)), "0")
    End If

    strPartIDNew = strPartIDNew & strNumberNew

    Exit For
  End If
Next

If strPartIDNew <> "" Then
  Msgbox "The New Part ID is " & strPartIDNew
Else
  Msgbox "Not a Valid Starting Point" & strPartID
End If 

The intention of the above macro is to locate the number 89 in the supplied strPartID variable, recognize that a 4 digit serial number is expected, and output:

The New Part ID is PAINT0090 

Nice, but that is not what the OP needs.  The highest currently sequenced number will not be provided – that value must be looked up in the database.  So close…

Let’s try a different approach, starting by creating a sample table with three sequences of part numbers with different prefixes:

CREATE TABLE T1 (
  ID VARCHAR2(30),
  DESCRIPTION VARCHAR2(40),
  PRIMARY KEY(ID));

INSERT INTO
  T1
SELECT
  'PAINT'||LPAD(TO_CHAR(ROWNUM), 6, '0') ID,
  'TESTING ' || TO_CHAR(ROWNUM) DESCRIPTION
FROM
  DUAL
CONNECT BY
  LEVEL<=35000;

INSERT INTO
  T1
SELECT
  'BAR'||LPAD(TO_CHAR(ROWNUM), 6, '0') ID,
  'TESTING ' || TO_CHAR(ROWNUM) DESCRIPTION
FROM
  DUAL
CONNECT BY
  LEVEL<=45000;

INSERT INTO
  T1
SELECT
  'BEARING'||LPAD(TO_CHAR(ROWNUM), 6, '0') ID,
  'TESTING ' || TO_CHAR(ROWNUM) DESCRIPTION
FROM
  DUAL
CONNECT BY
  LEVEL<=888;

COMMIT; 

Let’s find the next sequence number for the BAR prefix:

SELECT
  MAX(TO_NUMBER(SUBSTR(ID,4))) + 1 NN
FROM
  T1
WHERE
  ID BETWEEN 'BAR0' AND 'BAR99999999';

        NN
----------
     45001 

As long as ALL of the characters after the BAR keyword prefix are numbers, the above would tell us that the next number with BAR as the prefix is 45001.  On Oracle Database 10.1 and higher it would be a good idea to add an additional predicate to the WHERE clause that uses regular expressions to avoid potential problems where some unrelated ID column values start with the letters BAR, a number character, and then at some position to the right contain a letter character (that condition would cause the above SQL statement to fail).

Building onto the above SQL statement, we could just retrieve the next part number in the sequence from the database, when provided any existing prefixed part number as the starting point:

SELECT
  'BAR' || LPAD(TO_CHAR(MAX(TO_NUMBER(SUBSTR(ID,4))) + 1), 6, '0') NEXT_PART_ID
FROM
  T1
WHERE
  ID BETWEEN 'BAR0' AND 'BAR99999999';

NEXT_PART
---------
BAR045001 

We are able to take the above SQL statement and incorporate it into a VBScript macro to find the next prefixed sequential number for the primary key column:

Dim strPartID
Dim strPartIDNew
Dim strNumberOld
Dim strNumberNew
Dim i
Dim strUserName
Dim strPassword
Dim strDatabase
Dim strSQL
Dim dbDatabase
Dim snpData

On Error Resume Next

strUsername = "MyUserID"
strPassword = "MyPassword"
strDatabase = "MyDatabase"

Set snpData = CreateObject("ADODB.Recordset")
Set dbDatabase = CreateObject("ADODB.Connection")

dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUserName & ";Password=" & strPassword & ";"
dbDatabase.Open

strNumberOld = ""

'strPartID = PART_ID
strPartID = "BEARING0599"  'Remove when finished testing
'strPartID = "BAR0089"  'Remove when finished testing
'strPartID = "PAINT0089"  'Remove when finished testing

For i = Len(strPartID) to 1 Step -1
  If (Mid(strPartID, i, 1) >= "0") And (Mid(strPartID, i, 1) <= "9") Then
    strNumberOld = Mid(strPartID, i, 1) & strNumberOld
  Else
    strPartIDNew = Left(strPartID, i)

    strSQL = "SELECT" & VBCrLf
    strSQL = strSQL & "  '" & strPartIDNew & "' || LPAD(TO_CHAR(MAX(TO_NUMBER(SUBSTR(ID," & (i+1) &"))) + 1), 6, '0') NEXT_PART_ID" & VBCrLf
    strSQL = strSQL & "FROM" & VBCrLf
    strSQL = strSQL & "  T1" & VBCrLf
    strSQL = strSQL & "WHERE" & VBCrLf
    strSQL = strSQL & "  ID BETWEEN '" & strPartIDNew & "0' AND '" & strPartIDNew & "99999999'"

    snpData.Open strSQL, dbDatabase

    If snpData.State = 1 Then
      If Not(snpData.EOF) Then
        strPartIDNew = snpData("next_part_id")
      End If
      snpData.Close
    End If
    Exit For
  End If
Next

If strPartIDNew <> "" Then
  Msgbox "The New Part ID is " & strPartIDNew
Else
  Msgbox "Not a Valid Starting Point" & strPartID
End If

dbDatabase.Close
Set snpData = Nothing
Set dbDatabase = Nothing 

The OP put together a parallel solution that also used a VBScript macro.  The macro sent a SQL statement very similar to the following to the database:

SELECT
  ID
FROM
  T1
WHERE
  ID LIKE 'BAR%'; 

In the macro code the OP parsed each of the returned ID values to determine the highest sequence number, added 1 to that value, padded the new highest sequence number with “0′ digits and output the result.  Most likely due to curiosity, the OP asked why I did not simply use his VBScript macro as part of my proposed solution.  What reasons do you think that I gave to the OP?





What Number Immediately Follows 3,999? Oracle Database Refuses to Answer

16 01 2012

January 16, 2012

I put together a test case to demonstrate how the physical reads autotrace statistic could exceed the consistent gets autotrace statistic if a single-pass or multi-pass workarea execution were performed during the execution of the SQL statement.  If you are interested, you can see the test case in this recent OTN thread.  If I recall correctly, index pre-fetching could also result in a similar situation where the physical reads autotrace statistic could exceed the consistent gets autotrace statistic.

The result in the OTN test case left me a little concerned.  It might not be well known, however it is possible to instruct Oracle Database to format normal base 10 numbers as Roman numerals with the RN format specification.  For example:

SELECT
  TO_CHAR(1, 'RN') ROMAN_NUMBER
FROM
  DUAL;

ROMAN_NUMBER
---------------
              I

SELECT
  TO_CHAR(12, 'RN') ROMAN_NUMBER
FROM
  DUAL;

ROMAN_NUMBER
---------------
            XII

SELECT
  TO_CHAR(123, 'RN') ROMAN_NUMBER
FROM
  DUAL;

ROMAN_NUMBER
---------------
         CXXIII

SELECT
  TO_CHAR(1234, 'RN') ROMAN_NUMBER
FROM
  DUAL;

ROMAN_NUMBER
---------------
       MCCXXXIV 

I personally think that is a neat feature.  In the OTN test case I created a table that would hopefully contain the first 9,999,999 Roman numbers:

CREATE TABLE T1 (
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 VARCHAR2(30) NOT NULL,
  C4 VARCHAR2(200));

INSERT INTO T1
SELECT
  MOD(ROWNUM-1, 90) * 4 C1,
  ROWNUM - 1 C2,
  TO_CHAR(ROWNUM - 1, 'RN') C3,
  LPAD('A',200,'A') C4
FROM
  (SELECT
     ROWNUM RN
   FROM
     DUAL
   CONNECT BY
     LEVEL<=1000000),
  (SELECT
     ROWNUM RN
   FROM
     DUAL
   CONNECT BY
     LEVEL<=10);

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1') 

As part of the OTN test case, I thought that I would demonstrate a non-optimal work area execution by determining how many unique Roman numbers made it into the T1 test table:

SELECT
  COUNT(DISTINCT C3)
FROM
  T1;

COUNT(DISTINCTC3)
-----------------
             4000 

Just 4,000?  There are 10,000,000 rows in that test table.  So, maybe we should ask Oracle Database what number immediately follows 3,999 by querying the table:

SELECT
  C2,
  C3
FROM
  T1
WHERE
  C2 BETWEEN 3950 AND 4050
ORDER BY
  C2;

---------- ------------------------------
      3950          MMMCML
      3951         MMMCMLI
      3952        MMMCMLII
      3953       MMMCMLIII
      3954        MMMCMLIV
      3955         MMMCMLV
      3956        MMMCMLVI
      3957       MMMCMLVII
      3958      MMMCMLVIII
      3959        MMMCMLIX
      3960         MMMCMLX
      3961        MMMCMLXI
      3962       MMMCMLXII
      3963      MMMCMLXIII
      3964       MMMCMLXIV
      3965        MMMCMLXV
      3966       MMMCMLXVI
      3967      MMMCMLXVII
      3968     MMMCMLXVIII
      3969       MMMCMLXIX
      3970        MMMCMLXX
      3971       MMMCMLXXI
      3972      MMMCMLXXII
      3973     MMMCMLXXIII
      3974      MMMCMLXXIV
      3975       MMMCMLXXV
      3976      MMMCMLXXVI
      3977     MMMCMLXXVII
      3978    MMMCMLXXVIII
      3979      MMMCMLXXIX
      3980       MMMCMLXXX
      3981      MMMCMLXXXI
      3982     MMMCMLXXXII
      3983    MMMCMLXXXIII
      3984     MMMCMLXXXIV
      3985      MMMCMLXXXV
      3986     MMMCMLXXXVI
      3987    MMMCMLXXXVII
      3988   MMMCMLXXXVIII
      3989     MMMCMLXXXIX
      3990         MMMCMXC
      3991        MMMCMXCI
      3992       MMMCMXCII
      3993      MMMCMXCIII
      3994       MMMCMXCIV
      3995        MMMCMXCV
      3996       MMMCMXCVI
      3997      MMMCMXCVII
      3998     MMMCMXCVIII
      3999       MMMCMXCIX
      4000 ###############
      4001 ###############
      4002 ###############
      4003 ###############
      4004 ###############
      4005 ###############
      4006 ###############
      4007 ###############
      4008 ###############
      4009 ###############
      4010 ###############
      4011 ###############
      4012 ###############
      4013 ###############
      4014 ###############
      4015 ###############
      4016 ###############
      4017 ###############
      4018 ###############
      4019 ###############
      4020 ###############
      4021 ###############
      4022 ###############
      4023 ###############
      4024 ###############
      4025 ###############
      4026 ###############
      4027 ###############
      4028 ###############
      4029 ###############
      4030 ###############
      4031 ###############
      4032 ###############
      4033 ###############
      4034 ###############
      4035 ###############
      4036 ###############
      4037 ###############
      4038 ###############
      4039 ###############
      4040 ###############
      4041 ###############
      4042 ###############
      4043 ###############
      4044 ###############
      4045 ###############
      4046 ###############
      4047 ###############
      4048 ###############
      4049 ###############
      4050 ############### 

You heard it here first, in Roman times 4,000 is equivalent to infinity.  An obvious extension to this rule is that in Roman times the value of PI had exactly 3999 digits to the right of the decimal point.   :-)





OT: Do Search Terms Describe the Visitor?

12 01 2012

January 12, 2012

I thought that I would start this slightly off topic blog article with a bit of humor.  Seven months ago I wrote a blog article that refuses to move from the first position in the most visited articles on this blog.  In the process of trying to understand why a mathematics focused article is the most popular article on an Oracle Database specific blog, I regularly review the search keywords that bring people to my blog.  Yesterday alone, the search keywords that apparently pointed to the popular blog article included (not a complete list):

  • finding distance between two points lat long (2)
  • distance spherical points coordinates oracle (2)
  • find distance between two longitude latitude points (1)
  • calculate distance between points in a feature (1)
  • calculate speed longitude latitude (1)
  • distance between two lattitude points (1)
  • how to get distance between two latitudes in meter (1)
  • access table that converts latitude and longitude (1)
  • calculate time and distance between two longitudes (1)
  • distance between two points latitude and longitude transact sql (1)
  • converting to oracle degree minutes (1)
  • distance between latitude (1)
  • select sdo_geom.sdo_distance (1)
  • oracle sdo_geom.dos_distance (1)
  • calculate distance longitude latitude (1)
  • method of measuring distance using plain (1)
  • oracle spatial calculate distance (1)
  • how to calculate distance between two latitude and longitude (1)
  • to calculate distance between two points (1)
  • oracle spatial sort lat lon coordinates (1)
  • longitude and latitude distance between 2 points (1)
  • solve this:find distance between (35 degrees 21′) and (29 degrees 57′) and given that the radius is 3960 (1)
  • distance between two points wordpress (1)
  • how to get distance between two longitudes (1)
  • calculate distance between two lat long points (1)
  • how to find distance between points of longitude (1)
  • sql function calculate distance gps kilometers (1)
  • calculate distance between lattitute longitude (1)
  • excel calculate distance from lat long (1)
  • calculate distance from lat long sql (1) 

I think that the above keywords point to one and only one conclusion: the majority of the visitors to this blog are lost, know only their latitude and longitude coordinates (and the coordinates of where they are supposed to be), and are able to VPN in to their Oracle Database at work to determine how long it will take to become unlost.  :-)

While on the topic of interesting search keywords, I thought that I would mention a favorite search keyword that appeared in the WordPress statistics.  My all time favorite interesting search keyword that was used to access this blog appeared shortly after I reviewed a red covered Oracle related book – the search keywords were “Charles Hooper is getting sued”.  Needless to say, it is interesting that the search keywords found an article on my blog.

Moving on to the point of this blog article, I have also noticed a curious trend in some of the search keywords.  WordPress makes it a bit diffcult to go back in time to tabulate somewhat popular search keywords when there are a lot of commonly used keywords that access this site.  However, with a bit of effort, I attempted to locate search keywords that share a common pattern.  Those search keywords that I located (with the minimum number of hits indicated) follow: 

  • oracle core essential internals for dbas and developers pdf (8)
  • oracle core essential internals for dbas and developers download (6)
  • oracle core: essential internals for dbas and developers pdf (4)
  • oracle core: essential internals for dbas and developers download (1)
  • oracle tuning the definitive reference second edition pdf (99)
  • oracle tuning: the definitive reference pdf (3)
  • oracle tuning the definitive reference pdf (1)
  • oracle tuning the definitive reference 2nd edition pdf download (2)
  • oracle performance firefighting pdf (18)
  • expert oracle practices download (1)
  • apress.oracle.core.essential.internals.for.dbas.and.developers.nov.2011.rar (1)

Undoubtedly, in the above cases the searcher likely found my review of a particular book.  The above list has me wondering about a couple of items.  I was a full time college student for five years to obtain my degree.  I remember the pain of signing a check for what seemed to be (U.S.) $500 every semester – it did not seem to matter much if I was buying mathematics books (a $204 Calculus book from Amazon oddly seems approproate here) , computer books, or psychology books – the total was always about the same.  Was that money for books a waste?  Maybe I could have just found the book out on the Internet somewhere… they had that neat Gopher tool way back then, but not the WYSIWYG interface that is common now.

I am left wondering what the people searching for the above keywords might have been thinking.  I assume that some of the searchers have spent some time in college, and might even be Oracle developers or DBAs.  So, do you think that search terms describe vistors?  If so, how do you think the above search keywords might describe the searchers?





Dumping Trace Events – What You See is Not Necessarily What You Get

9 01 2012

January 9, 2012

A recent thread in the comp.databases.oracle.server Usenet group brought back memories of when Randolf Geist and I worked on the two chapters for the “Expert Oracle Practices” book.  In the chapters, among other things, we demonstrated how to enable 10046 trace files for sessions using various approaches (some of the approaches change the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION to indicate that a 10046 trace is active, and other methods do not), and how to use ORADEBUG to see which events are enabled in other sessions.

The OP in the thread mentioned that the ORADEBUG EVENTDUMP session command, when executed in SQL*Plus by a SYSDBA user, showed no events enabled for another session when the DBMS_MONITOR package was used to enable a 10046 trace at level 12 for the other session.  I have a vague memory of reading (somewhere) that the ORADEBUG EVENTDUMP session command will only show newly enabled events for another session after that other session issues another call to the database (parse, execute, fetch, etc.).  In the Usenet group thread I stated something that is slightly less complete: “I believe that the session with the trace enabled through DBMS_MONITOR must execute at least one SQL statement after tracing is enabled for the session, before ORADEBUG will report that the trace is enabled.”

In the Usenet thread I put together a quick test case script that demonstrated that after the second session (Session 1) issued a SELECT statement, the first session (Session 2) was able to issue a ORADEBUG EVENTDUMP session command and determine that a 10046 trace at level 12 was enabled for the other session.  I believe that the OP answered his own question after a bit of experimentation and searching.  I thought that I would provide an extended version of the test case script in case anyone would like to experiment a bit.  In this test case, Session 1 will be the target of the tracing – that session must be able to query V$SESSION and V$PROCESS during the script execution, while Session 2 will be connected as the SYS user.  In the test case script I have removed the SQL> prompts to make it easier for you to copy and paste the scripts into SQL*Plus, and when the returned output is important, that information also appears in the test case script (all commands executed begin with UPPERCASE keywords).

In Session 1, execute the following SQL statement to pick up the SID, SERIAL# and PID for Session 1, along with the columns in V$SESSION that indicate whether or not a 10046 trace at level 1, 4, 8, or 12 is enabled.  The SID and SERIAL# will be used in Session 2 to enable a trace in Session 1, and the PID will be used with ORADEBUG in Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

As can be determined by the above output, the SID is 4, PID is 24, and a 10046 trace is not enabled for the session (fair warning, the SQL_TRACE column can be misleading).

In Session 2, enable a 10046 trace using the DBMS_MONITOR package for Session 1 at level 12, and dump the events for Session 1 (note that this test case script is being executed on a Windows server with Oracle Database 11.2.0.2):

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG SETORAPID 24

ORADEBUG EVENTDUMP session
Statement processed. 

The output of the ORADEBUG EVENTDUMP session command is significant – the Statement processed. note indicates that the statement executed successfully with no return output. 

In Session 1, let’s execute the same SQL statement as was executed earlier, to not only confirm that the DBMS_MONITOR.SESSION_TRACE_ENABLE call executed by Session 2 was successful, but also to issue another database call in the session (the significance will be seen later):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

The above output shows that the DBMS_MONITOR.SESSION_TRACE_ENABLE call was successful, as indicated by the changed values in the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns – a level 12 10046 trace is enabled.

In Session 2, let’s check again which events are enabled for Session 1:

ORADEBUG EVENTDUMP session
sql_trace level=12 

Notice in the above output that ORADEBUG now indicates that a 10046 trace at level 12 is enabled for Session 1, because another database call (initiated when the SQL statement was executed) was performed in Session 1 after the trace was enabled.

Let’s try a bit more experimentation.  In Session 2, let’s disable the trace in Session 1 using the DBMS_MONITOR package, and verify whether or not tracing is enabled in Session 1 by using ORADEBUG:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)
PL/SQL procedure successfully completed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

The above output shows that ORADEBUG still indicates that a 10046 trace at level 12 is enabled for Session 1.  In Session 2, let’s check the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns for Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

ORADEBUG EVENTDUMP session
sql_trace level=12 

So, the query of V$SESSION indicates that a 10046 trace for Session 1 is disabled, yet ORADEBUG still insists that a 10046 trace at level 12 is enabled.  WYSIWYG (What You See Is What You Get) is taking a bit of a vacation.  Let’s issue another database call in Session 1 so that ORADEBUG provides correct output about whether or not a 10046 trace is enabled.  In Session 1:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

Let’s confirm in Session 2 that ORADEBUG now reports that a 10046 trace is not enabled in Session 1:

ORADEBUG EVENTDUMP session
Statement processed.  

OK, but what happens if we use ORADEBUG in Session 2 to enable a 10046 trace is Session 1?  In Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

The above shows that if ORADEBUG enables a 10046 trace in Session 1, the ORADEBUG EVENTDUMP session command will correctly indicate that a 10046 trace is enabled for Session 1.  Nice, but what about the SQL_TRACE, SQL_TRACE_WAITS, and SQL_TRACE_BINDS columns in V$SESSION for Session 1?  Let’s check using Session 2:

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE 

The above output suggests that a 10046 trace at level 12 is not enabled for Session 1.  Let’s check again from within Session 1 and then determine today’s date (if that second SQL statement appears in the 10046 trace file, then we know that the 10046 trace was in fact enabled for Session 1):

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 DISABLED FALSE FALSE

SELECT SYSDATE FROM DUAL;

SYSDATE
---------
08-JAN-12  

The above still suggests that a 10046 trace is not enabled for Session 1 and that today’s date is January 8, 2012.  Let’s jump back to Session 2 and disable the 10046 trace using ORADEBUG:

ORADEBUG session_event 10046 trace name context off
Statement processed. 

Out of curiosity, let’s repeat a portion of the initial test, just to confirm that the initial test results were not a fluke:

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(SESSION_ID=>4,SERIAL_NUM=>143,WAITS=>TRUE,BINDS=>TRUE)

ORADEBUG EVENTDUMP session
Statement processed.

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed. 

Once again, the above shows that ORADEBUG does not initially report that a 10046 trace is enabled in Session 1 when the officially supported method for enabling a 10046 trace in another session is used.  Let’s disable the 10046 trace using the DBMS_MONITOR package and then confirm that ORADEBUG still indicates that a 10046 trace is not enabled in Session 1:

EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(SESSION_ID=>4,SERIAL_NUM=>143)

ORADEBUG EVENTDUMP session
Statement processed. 

So, what about the unsupported method of enabling a 10046 trace in another session, using SYS.DBMS_SYSTEM.SET_EV?  In Session 2:

EXEC SYS.DBMS_SYSTEM.SET_EV(4, 143, 10046, 12, '')

SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=4
  AND S.PADDR=P.ADDR;

SID    SERIAL#        PID SQL_TRAC SQL_T SQL_T
--- ---------- ---------- -------- ----- -----
  4        143         24 ENABLED  TRUE  TRUE

ORADEBUG EVENTDUMP session
Statement processed. 

The SYS.DBMS_SYSTEM.SET_EV call changed the value of the columns in V$SESSION for Session 1, but still did not alter the output of ORADEBUG EVENTDUMP session.

One final test in Session 2:

ORADEBUG session_event 10046 trace name context forever,level 12
Statement processed.

ORADEBUG EVENTDUMP session
sql_trace level=12 

Once again, if we enable the 10046 trace using ORADEBUG, then ORADEBUG is able to show that the trace is enabled for Session 1.

———————————————

At this point you might be curious why I mentioned that the above test case script was performed on a Windows server running Oracle Database 11.2.0.2.  Does the Oracle Database version make a difference in the results?  Does the operating system (Windows, Linux, or Unix) make a difference in the results?  It appears that a part 2 is required for this blog article, where I will compare the above results with the results obtained with 10.2.0.5 on a Windows server and 11.1.0.6 on a Linux server.

———————————————

You are probably curious to see the contents of the trace file for Session 1.  Here is the trace file (if you need help in reading the trace file, see this three part article series):

*** 2012-01-08 09:47:51.686
*** SESSION ID:(4.143) 2012-01-08 09:47:51.686
*** CLIENT ID:() 2012-01-08 09:47:51.686
*** SERVICE NAME:(OR1122) 2012-01-08 09:47:51.686
*** MODULE NAME:(SQL*Plus) 2012-01-08 09:47:51.686
*** ACTION NAME:() 2012-01-08 09:47:51.686

Received ORADEBUG command (#1) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:47:51.686
Finished processing ORADEBUG command (#1) 'EVENTDUMP session'

*** 2012-01-08 09:48:18.426
Received ORADEBUG command (#2) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:48:18.426
Finished processing ORADEBUG command (#2) 'EVENTDUMP session'

*** 2012-01-08 09:49:16.415
CLOSE #3:c=0,e=20,dep=0,type=0,tim=488596106412
=====================
PARSING IN CURSOR #2 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596107091 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #2:c=0,e=264,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=488596107088
BINDS #2:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0010.0001
EXEC #2:c=0,e=550,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=3684871272,tim=488596107744
FETCH #2:c=0,e=25,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596107790
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #2:c=0,e=501,dep=1,type=0,tim=488596108309
=====================
PARSING IN CURSOR #5 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596108602 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #5:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108602
BINDS #5:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000273.0012.0001
EXEC #5:c=0,e=47,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596108701
FETCH #5:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596108727
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #5:c=0,e=23,dep=1,type=0,tim=488596108766
=====================
PARSING IN CURSOR #3 len=37 dep=1 uid=0 oct=3 lid=0 tim=488596109217 hv=1398610540 ad='7ffb8e4b250' sqlid='grwydz59pu6mc'
select text from view$ where rowid=:1
END OF STMT
PARSE #3:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109217
BINDS #3:
 Bind#0
  oacdty=11 mxl=16(16) mxlc=00 mal=00 scl=00 pre=00
  oacflg=18 fl2=0001 frm=00 csi=00 siz=16 off=0
  kxsbbbfp=1dbe86d8  bln=16  avl=16  flg=05
  value=00000274.0010.0001
EXEC #3:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3684871272,tim=488596109318
FETCH #3:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3684871272,tim=488596109344
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=69 op='TABLE ACCESS BY USER ROWID VIEW$ (cr=1 pr=0 pw=0 time=0 us cost=1 size=15 card=1)'
CLOSE #3:c=0,e=21,dep=1,type=0,tim=488596109385
=====================
PARSING IN CURSOR #4 len=204 dep=0 uid=91 oct=3 lid=91 tim=488596111910 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #4:c=0,e=5410,p=0,cr=6,cu=0,mis=1,r=0,dep=0,og=1,plh=1985757361,tim=488596111909
EXEC #4:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596112094
WAIT #4: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596112181
FETCH #4:c=0,e=1190,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=488596113404
WAIT #4: nam='SQL*Net message from client' ela= 232 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596113665
FETCH #4:c=0,e=397,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=488596114102
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #4 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #4 id=3 cnt=810 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=346 us cost=0 size=16146 card=598)'
STAT #4 id=4 cnt=30 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #4 id=5 cnt=810 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=130 us cost=0 size=184 card=23)'
STAT #4 id=6 cnt=27 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=26 us cost=0 size=184 card=23)'
STAT #4 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #4 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #4 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #4 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #4 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #4: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488596114237

*** 2012-01-08 09:50:22.069
Received ORADEBUG command (#3) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:50:22.069
Finished processing ORADEBUG command (#3) 'EVENTDUMP session'

*** 2012-01-08 09:51:24.578
Received ORADEBUG command (#4) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:51:24.578
Finished processing ORADEBUG command (#4) 'EVENTDUMP session'

*** 2012-01-08 09:54:05.768
Received ORADEBUG command (#5) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:54:05.768
Finished processing ORADEBUG command (#5) 'EVENTDUMP session'

*** 2012-01-08 09:55:01.068
WAIT #4: nam='SQL*Net message from client' ela= 344636055 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=488940750307

*** 2012-01-08 09:55:48.744
Received ORADEBUG command (#6) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:55:48.744
Finished processing ORADEBUG command (#6) 'EVENTDUMP session'

*** 2012-01-08 09:56:50.964
Received ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 09:56:50.964
Finished processing ORADEBUG command (#7) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 09:57:18.634
Received ORADEBUG command (#8) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 09:57:18.634
Finished processing ORADEBUG command (#8) 'EVENTDUMP session'

*** 2012-01-08 10:00:01.094
WAIT #2: nam='SQL*Net message from client' ela= 300017366 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770346
CLOSE #2:c=0,e=19,dep=0,type=0,tim=489240770476
=====================
PARSING IN CURSOR #5 len=204 dep=0 uid=91 oct=3 lid=91 tim=489240770687 hv=1585533233 ad='7ffb7578ec0' sqlid='dk42yjjg82n9j'
SELECT
  S.SID,
  S.SERIAL#,
  P.PID,
  S.SQL_TRACE,
  S.SQL_TRACE_WAITS,
  S.SQL_TRACE_BINDS
FROM
  V$SESSION S,
  V$PROCESS P
WHERE
  S.SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1)
  AND S.PADDR=P.ADDR
END OF STMT
PARSE #5:c=0,e=130,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770686
EXEC #5:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240770814
WAIT #5: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240770862
FETCH #5:c=0,e=7007,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1985757361,tim=489240777893
WAIT #5: nam='SQL*Net message from client' ela= 192 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240778675
FETCH #5:c=0,e=336,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1985757361,tim=489240779049
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=53 card=1)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=0 size=49 card=1)'
STAT #5 id=3 cnt=700 pid=2 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=0 pr=0 pw=0 time=349 us cost=0 size=16146 card=598)'
STAT #5 id=4 cnt=28 pid=3 pos=1 obj=0 op='FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=0 us cost=0 size=494 card=26)'
STAT #5 id=5 cnt=700 pid=3 pos=2 obj=0 op='BUFFER SORT (cr=0 pr=0 pw=0 time=81 us cost=0 size=184 card=23)'
STAT #5 id=6 cnt=25 pid=5 pos=1 obj=0 op='FIXED TABLE FULL X$KSLWT (cr=0 pr=0 pw=0 time=0 us cost=0 size=184 card=23)'
STAT #5 id=7 cnt=1 pid=2 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSUSE (ind:1) (cr=0 pr=0 pw=0 time=0 us cost=0 size=22 card=1)'
STAT #5 id=8 cnt=1 pid=7 pos=1 obj=0 op='COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)'
STAT #5 id=9 cnt=1 pid=8 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=0 us cost=0 size=40 card=2)'
STAT #5 id=10 cnt=1 pid=9 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
STAT #5 id=11 cnt=1 pid=1 pos=2 obj=0 op='FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489240779190

*** 2012-01-08 10:00:49.694
WAIT #5: nam='SQL*Net message from client' ela= 48590415 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289369620
CLOSE #5:c=0,e=16,dep=0,type=0,tim=489289369744
=====================
PARSING IN CURSOR #3 len=24 dep=0 uid=91 oct=3 lid=91 tim=489289370485 hv=124468195 ad='7ffb78cd410' sqlid='c749bc43qqfz3'
SELECT SYSDATE FROM DUAL
END OF STMT
PARSE #3:c=0,e=704,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=489289370484
EXEC #3:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=489289370563
WAIT #3: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370620
FETCH #3:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=489289370661
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #3: nam='SQL*Net message from client' ela= 189 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370905
FETCH #3:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=489289370957
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=489289370997

*** 2012-01-08 10:09:13.997
Received ORADEBUG command (#9) 'session_event 10046 trace name context off' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:09:13.997
Finished processing ORADEBUG command (#9) 'session_event 10046 trace name context off'

*** 2012-01-08 10:11:16.960
Received ORADEBUG command (#10) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:11:16.960
Finished processing ORADEBUG command (#10) 'EVENTDUMP session'

*** 2012-01-08 10:12:42.528
Received ORADEBUG command (#11) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:12:42.528
Finished processing ORADEBUG command (#11) 'EVENTDUMP session'

*** 2012-01-08 10:15:29.621
Received ORADEBUG command (#12) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:15:29.621
Finished processing ORADEBUG command (#12) 'EVENTDUMP session'

*** 2012-01-08 10:19:54.941
Received ORADEBUG command (#13) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:19:54.941
Finished processing ORADEBUG command (#13) 'EVENTDUMP session'

*** 2012-01-08 10:21:25.459
Received ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12' from process 'Windows thread id: 12292, image: <none>'

*** 2012-01-08 10:21:25.459
Finished processing ORADEBUG command (#14) 'session_event 10046 trace name context forever,level 12'

*** 2012-01-08 10:21:40.549
Received ORADEBUG command (#15) 'EVENTDUMP session' from process 'Windows thread id: 12292, image: <none>'
Dumping Event (group=SESSION)

*** 2012-01-08 10:21:40.549
Finished processing ORADEBUG command (#15) 'EVENTDUMP session' 




Faulty Quotes 7 – Deadlock Kills Sessions?

4 01 2012

January 4, 2012

(Back to the Previous Post in the Series)

I thought that I would begin this blog article with a bit of a test case that demonstrates a very simple deadlock between two sessions.

In Session 1 (create the test table with a primary key and insert a single row):

CREATE TABLE T1 (
  C1 NUMBER PRIMARY KEY,
  C2 VARCHAR2(10));

INSERT INTO T1 VALUES (1,'1');

In Session 2 (insert a row that does not conflict with session 1 and then insert a row with the same primary key value as the uncommitted row in Session 1):

INSERT INTO T1 VALUES (2,'2');

INSERT INTO T1 VALUES (1,'3');

(Session 2 hangs while waiting for Session 1 to COMMIT or ROLLBACK)

In Session 1 (insert a row with the same primary key value as the uncommitted row in Session 2):

INSERT INTO T1 VALUES (2,'2');

(Session 1 hangs while waiting for Session 2 to COMMIT or ROLLBACK)

In Session 2 (an ORA-00060 is returned, deadlock between the two sessions ends):

INSERT INTO T1 VALUES (1,'3')
            *
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

(Session 1 still hangs while waiting for Session 2 to COMMIT or ROLLBACK the first row that was inserted)

In Session 2 (confirming that the session was not killed/terminated and that the first row inserted still exists – indicates that the current TRANSACTION was not rolled back, just the statement that was involved in the deadlock):

SELECT
  *
FROM
  T1;

        C1 C2
---------- ----------
         2 2

While recently reading an OTN thread I was reminded of a bit of information that several sources simply miss-state about Oracle deadlocks.  The incorrect information is repeated, seemingly quite frequently, in various books and forum threads.  As luck would have it, several of the books that I have read about Oracle Database also repeat this incorrect information.  For instance, a quote from page 352 of the book “Expert Oracle Database 11g Administration” (a book that I reviewed and gave 4 out of 5 stars, maybe I need to re-evaluate that rating?):

“This is a catch-22 situation, because the stalemate can’t be broken by either session unilaterally. In such circumstances, Oracle steps in, terminates one of the sessions, and rolls back its statement. Oracle quickly recognizes that two sessions are deadlocked and terminates the session that issued the most recent request for a lock. This will release the object locks that the other session is waiting for.”

A second book, “Secrets of the Oracle Database” (another book that I reviewed and gave 4 out of 5 stars, actually it was probably worth about 4.4 stars), states the following on page 57:

“Hence, the ORACLE DBMS detects circular chains pertaining to interdependent locks, signals the error ‘ORA-00060: deadlock detected while waiting for resource’, and rolls back one of the sessions involved in the would-be deadlock.”

A third book, “Oracle SQL Recipes” (another book that I reviewed and gave 4 out of 5 stars), states the following on page 217:

“The immediate solution to the problem requires no user intervention: Oracle detects the deadlock and automatically rolls back one of the transactions, releasing one of the sets of row locks so that the other session’s DML will complete.”

A fourth book, “Oracle Database 11g Performance Tuning Recipes” (another book that I reviewed and gave 2 out of 5 stars), states on page 227:

“While the database can automatically resolve deadlocks between sessions (by killing one of the sessions holding a needed lock)…”

The Google book search found that the above four books were not alone in their statements of deadlocks that do not match the test case results at the start of this blog article.  One of the books found by Google is one that I have not read yet (and probably never will), “Oracle PL/SQL for Dummies”, which states the following on page 298:

“This is a deadlock. Oracle resolves it by raising a deadlock exception (ORA-00060: deadlock detected while waiting for resource) in user 1’s session. This terminates the procedure and allows user 2’s procedure to successfully complete.”

A second book found by the Google search is a bit old, “Oracle 9i DBA 101″, which on page 194 states:

“A deadlock occurs when two or more users wait for data that is locked by each other. Oracle will kill the first server process that detects the deadlock, so you should always look for and fix code that can cause deadlocks.”

There are certainly many other statements in other books regarding deadlocks, both correct and incorrect.  A quick search through the OTN forums found several threads in addition to the one at the start of this blog article that also drifted a bit from an accurate picture of what happens when a deadlock is broken in Oracle Database.

https://forums.oracle.com/forums/thread.jspa?threadID=2196282

“That is the deadlock. Oracle will then immediately choose arbitrarlly a victim session (542 or 548) and kill its process letting the remaining session continuing its work.”

https://forums.oracle.com/forums/thread.jspa?threadID=2152646

“There should be a simple wait, not a deadlock which would killed one of the session.”

https://forums.oracle.com/forums/thread.jspa?threadID=2261367

“If two sessions are actually deadlocked, Oracle should always kill one of the blocked sessions, raising an ORA-00060 error. It sounds like you’re saying this is not the expected behavior.”

https://forums.oracle.com/forums/thread.jspa?threadID=2227420

“The two session are inserting records in the same table with a unique index on it. With the same database version on another server and the same treatment, the deadlocks are correctly handled (one session is killed with ora-00060) and the process can continue.”

https://forums.oracle.com/forums/thread.jspa?threadID=1072665

“In oracle, when session1 and session2 make a deadlock, the oracle will kill one session , but I want know how to let oracle kill session1 and session2 both, is there way to do that?”

https://forums.oracle.com/forums/thread.jspa?threadID=2169563

“NO. Oracle already broke the deadlock by terminating one of these sessions. By the time trace file was closed, the deadlock no longer existed.”

https://forums.oracle.com/forums/thread.jspa?threadID=953308

“Oracle itself resolve the deadlock by killing the session.”

While reading the book “Oracle Core Essential Internals for DBAs and Developers” I almost flagged a sentence in a discussion of deadlocks as potentially containing an error.  That statement is found on page 82 near the end of the third to the last paragraph on the page.  After reading that paragraph about 10 times I decided that the statement is probably specific to TM locks, and probably is correct (the thought of TX locks maintained at the individual block level that contains the table rows kept running through my head the first nine times I read the paragraph).  This section of the book is interesting, as it not only avoids the mistakes mentioned in the above books, but it also highlights an inaccurate statement or two found in the Oracle Database documentation.








Follow

Get every new post delivered to your Inbox.

Join 140 other followers