Buffer Busy Waits – Reason Codes and Block Classes

16 04 2010

April 16, 2010

A couple of years ago the following question was asked in an OTN forum thread:

Does anyone know where I can find the reason codes for all the different wait events?

Sometimes questions need a but more detail to avoid confusion, where the correct answer is given to the wrong question.  The original poster was actually asking about the meaning of the P3 parameter of a ‘direct path write‘ wait event, while the phrase “reason codes” seems to typically imply ‘buffer busy waits’ wait events.  The thread eventually transitioned to a brief discussion of the P3 parameter of buffer busy waits.

For Oracle Database 10g R1 and above, the P3 parameter describes the block class, the type of block, involved in the buffer busy wait (source http://www.juliandyke.com/Internals/BlockClasses.html – see the links at the bottom of this article for the meaning of the P3 parameter prior to Oracle Database prior to 10g R1):

1  Data block
2  Sort block
3  Save undo block
4  Segment header
5  Save undo header
6  Free List
7  Extent map
8  1st level bitmap block
9  2nd level bitmap block
10 3rd level bitmap block
11 Bitmap block
12 Bitmap index block
13 File header block
14 Unused
15 System undo block
16 System undo block
17 Undo header
18 Undo block

For block class values above 18, the following calculation may be used, replacing n with the identified block class:

SELECT
  DECODE(MOD(n - 16,2),1,'Undo Header for Undo Segment ','Undo Block for Undo Segment ')||TO_CHAR(FLOOR((n - 17) / 2) + 1) DESCRIPTION
FROM
  DUAL;

For example, if the following appeared in a 10046 trace file (10.1 or above, in this case):

WAIT #12: nam='buffer busy waits' ela= 133261 file#=7 block#=2 class#=13 obj#=0 tim=14319369615

The P3 parameter is identified as class#, with a value of 13.  Based on the above list, the buffer busy wait is on the file header block of absolute file number 7.

If the following appeared in a 10046 trace file:

WAIT #24: nam='buffer busy waits' ela= 2636 file#=7 block#=137 class#=55 obj#=0 tim=82961305208

The output of the SQL statement calculation, after plugging in 55 for the value of n, is:

DESCRIPTION
-------------------------------
Undo Header for Undo Segment 20

The above indicates that the buffer busy wait is for the undo header of undo segment 20.  What should we do about buffer busy waits for the undo header, or for that matter any other block class?  The Oracle documentation (under the heading 10.3.1 buffer busy waits) offers suggestions for several of the block classes.  Maybe the next step in this case would be to start monitoring V$ROLLSTAT if automatic undo management is not in use:

SELECT
  *
FROM
  V$ROLLSTAT
WHERE
  USN=20;

Other Resources:
http://db-optimizer.blogspot.com/2010/01/oracle-wait-buffer-busy-wait.html
http://perfvision.com/papers/06_buffer_cache.ppt
http://perfvision.com/papers/Unit1_Intro_to_Waits.ppt





A Simple Request or a Performance Nightmare – Painted into a Corner by the ERP System

13 04 2010

April 13, 2010

Recently, a simple request came in from an ERP mailing list.  The author wanted to modify a report used by the purchasing module of the ERP program to show additional information on the report.  The purchasing module retrieves the data from the database, manipulates the data, and then pushes the manipulated data to a reporting package.  Wisely, the ERP developer allowed end users to add “extended queries” to bring in additional information from the database to be displayed on the report – all that the end user needs to do is to select from a list of variables provided by the ERP system to link to the database tables, and the ERP system will automatically pass the request to the database using bind variables.  Simple, right?

The table definitions look like this (primary key columns denoted by *):

DESC PURCHASE_ORDER
Name                Null?    Type
------------------- -------- ------------
ID                  NOT NULL VARCHAR2(15)  *
VENDOR_ID           NOT NULL VARCHAR2(15)
CONTACT_FIRST_NAME           VARCHAR2(30)
CONTACT_LAST_NAME            VARCHAR2(30)
CONTACT_INITIAL              VARCHAR2(2)
...

DESC PURC_ORDER_LINE
Name                Null?    Type
------------------- -------- ------------
PURC_ORDER_ID       NOT NULL VARCHAR2(15)  *
LINE_NO             NOT NULL NUMBER        *
PART_ID                      VARCHAR2(30)
VENDOR_PART_ID               VARCHAR2(30)
SERVICE_ID                   VARCHAR2(15)
USER_ORDER_QTY      NOT NULL NUMBER(14,4)
ORDER_QTY           NOT NULL NUMBER(14,4)
...

DESC PURC_LINE_DEL
Name                Null?    Type
------------------- -------- ------------
PURC_ORDER_ID       NOT NULL VARCHAR2(15)  *
PURC_ORDER_LINE_NO  NOT NULL NUMBER        *
DEL_SCHED_LINE_NO   NOT NULL NUMBER        *
DESIRED_RECV_DATE            DATE
ACTUAL_RECV_DATE             DATE
USER_ORDER_QTY      NOT NULL NUMBER(14,4)
RECEIVED_QTY                 NUMBER(14,4)
...

DESC PART
Name                Null?    Type
------------------- -------- ------------
ID                  NOT NULL VARCHAR2(30)  *
DESCRIPTION                  VARCHAR2(40)
STOCK_UM            NOT NULL VARCHAR2(15)
PLANNING_LEADTIME   NOT NULL NUMBER
ORDER_POLICY        NOT NULL CHAR(1)
ORDER_POINT                  NUMBER(14,4)
...

The PURCHASE_ORDER table contains the header information for the order, the PURC_ORDER_LINE table contains the line level detail for the order, and the PURC_LINE_DEL table contains the dates on which the line level detail should be provided to the company and the requested quantities for each of the dates.  While the delivery schedule’s date and order quantities already appear on the purchase order report, the previously received quantity and the delivery schedule line number need to be included on the report, along with a bit of other information.  The problem?  The ERP system does not provide a variable to target a specific delivery schedule line, but we do have the PURC_ORDER_ID (PO_ID variable), PURC_ORDER_LINE_NO (LN_LINE_NO), DESIRED_RECV_DATE (LN_DEL_SCHED_DATE), and USER_ORDER_QTY (LN_DEL_SCHED_QTY), so the first thought is to construct an extended query like this (line breaks are not permitted in the extended query, so this might be hard to read):

SELECT POL.PRODUCT_CODE , PO.STATUS , PLD.RECEIVED_QTY , PLD.DEL_SCHED_LINE_NO FROM PART P , PURCHASE_ORDER PO , PURC_ORDER_LINE POL , PURC_LINE_DEL PLD WHERE PO.ID = :pO_ID AND PO.ID=POL.PURC_ORDER_ID AND POL.LINE_NO = :LN_LINE_NO AND POL.PART_ID = P.ID(+) AND POL.PURC_ORDER_ID=PLD.PURC_ORDER_ID(+) AND POL.LINE_NO = PLD.PURC_ORDER_LINE_NO(+) AND PLD.DESIRED_RECV_DATE(+) = :LN_DEL_SCHED_DATE AND PLD.USER_ORDER_QTY(+) = :LN_DEL_SCHED_QTY

On trying the purchase order report with the extended query we are greeted with an invalid number error thrown by Oracle.  Invalid number?  Here is what a 10046 trace at level 4 showed:

BINDS #30:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=320 off=0
  kxsbbbfp=21c00ac8  bln=32  avl=06  flg=05
  value="144038"
 Bind#1
  oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=21 fl2=1000000 frm=01 csi=178 siz=0 off=32
  kxsbbbfp=21c00ae8  bln=32  avl=01  flg=01
  value="1"
 Bind#2
  oacdty=96 mxl=128(85) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=64
  kxsbbbfp=21c00b08  bln=128  avl=85  flg=01
  value="2/1/2010
2/1/2010
3/22/2010
4/13/2010
4/16/2010
5/14/2010
6/11/2010
7/9/2010
"
 Bind#3
  oacdty=96 mxl=128(49) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=192
  kxsbbbfp=21c00b88  bln=128  avl=49  flg=01
  value="8.00
8.00
8.00
16.00
0.00
8.00
8.00
8.00
"

Line 1 of this purchase order has 8 delivery schedule lines, and in this silly situation the extended query is executed only at the PURC_ORDER_LINE level, and not at the delivery schedule level – all of the delivery schedule information is passed into the report with the multiple lines in a single field, with CRLF characters separating the values in each of the delivery schedule lines.  OK, that was unexpected.  Now what, do we give up?  No, we use a little creativity to format the data in the required format, with all of the delivery schedule rows rolled in a single row:

SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    PURC_LINE_DEL PLD
  WHERE
    PLD.PURC_ORDER_ID='144038'
    AND PLD.PURC_ORDER_LINE_NO=1) P
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

PURC_ORDER_ID   PURC_ORDER_LINE_NO DEL_SCHED_LINE_ RECEIVED_QTY
--------------- ------------------ --------------- ------------
144038                           1 1               8
                                   2               8
                                   3               8
                                   4               16
                                   5               0
                                   6               0
                                   7               0
                                   8               0

Easy, right?  The execution plan of the above looks like this:

---------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |               |     1 |    51 |     4   (0)| 00:00:01 |
|   1 |  SORT GROUP BY                    |               |     1 |    51 |     4   (0)| 00:00:01 |
|*  2 |   CONNECT BY WITH FILTERING       |               |       |       |            |          |
|*  3 |    FILTER                         |               |       |       |            |          |
|   4 |     COUNT                         |               |       |       |            |          |
|   5 |      VIEW                         |               |    12 |   612 |     4   (0)| 00:00:01 |
|   6 |       WINDOW BUFFER               |               |    12 |   228 |     4   (0)| 00:00:01 |
|   7 |        TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|*  8 |         INDEX RANGE SCAN          | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
|*  9 |    HASH JOIN                      |               |       |       |            |          |
|  10 |     CONNECT BY PUMP               |               |       |       |            |          |
|  11 |     COUNT                         |               |       |       |            |          |
|  12 |      VIEW                         |               |    12 |   612 |     4   (0)| 00:00:01 |
|  13 |       WINDOW BUFFER               |               |    12 |   228 |     4   (0)| 00:00:01 |
|  14 |        TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|* 15 |         INDEX RANGE SCAN          | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
|  16 |    COUNT                          |               |       |       |            |          |
|  17 |     VIEW                          |               |    12 |   612 |     4   (0)| 00:00:01 |
|  18 |      WINDOW BUFFER                |               |    12 |   228 |     4   (0)| 00:00:01 |
|  19 |       TABLE ACCESS BY INDEX ROWID | PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|* 20 |        INDEX RANGE SCAN           | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("RN"-1=PRIOR "RN")
   3 - filter("RN"=1)
   8 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
   9 - access("RN"-1=PRIOR "RN")
  15 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
  20 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)

The above is fairly efficient, using the primary key index on the table.  We will just slide the above into an inline view in the report’s extended query (replacing the hardcoded literals with variables).  The following appears when trying to display the report:

Missing expression… :-(  how about what happened to the rest of the SQL statement?  Painted into a corner, again.  Now what, do we give up?

OK, no problem, just define a static view rather than wrapping our SQL statement into an inline view.  So, in testing it would look like this (the WHERE clause will be removed when it is created as a static view since the WHERE clause will be provided by the ERP package’s extended query):

SELECT
  P.PURC_ORDER_ID,   P.PURC_ORDER_LINE_NO,   MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,   MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY FROM   (SELECT     PLD.PURC_ORDER_ID,     PLD.PURC_ORDER_LINE_NO,     PLD.DEL_SCHED_LINE_NO,     PLD.RECEIVED_QTY,     ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN   FROM     PURC_LINE_DEL PLD) P WHERE   P.PURC_ORDER_ID='144038'   AND P.PURC_ORDER_LINE_NO=1 CONNECT BY PRIOR   P.RN=P.RN-1 START WITH   P.RN=1 GROUP BY   P.PURC_ORDER_ID,   P.PURC_ORDER_LINE_NO;

The execution plan for the above looks like this:

-----------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|   1 |  SORT GROUP BY              |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|*  2 |   FILTER                    |               |       |       |       |            |          |
|*  3 |    CONNECT BY WITH FILTERING|               |       |       |       |            |          |
|*  4 |     FILTER                  |               |       |       |       |            |          |
|   5 |      COUNT                  |               |       |       |       |            |          |
|   6 |       VIEW                  |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|   7 |        WINDOW SORT          |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|   8 |         TABLE ACCESS FULL   | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
|*  9 |     HASH JOIN               |               |       |       |       |            |          |
|  10 |      CONNECT BY PUMP        |               |       |       |       |            |          |
|  11 |      COUNT                  |               |       |       |       |            |          |
|  12 |       VIEW                  |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|  13 |        WINDOW SORT          |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|  14 |         TABLE ACCESS FULL   | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
|  15 |     COUNT                   |               |       |       |       |            |          |
|  16 |      VIEW                   |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|  17 |       WINDOW SORT           |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|  18 |        TABLE ACCESS FULL    | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
-----------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("P"."PURC_ORDER_ID"='144038' AND "P"."PURC_ORDER_LINE_NO"=1)
   3 - access("P"."RN"-1=PRIOR "P"."RN")
   4 - filter("P"."RN"=1)
   9 - access("P"."RN"-1=PRIOR "P"."RN")

The predicted time for execution is 2 seconds, and if there are 10 order lines ~~~ 2*10 = 20 seconds for the report to display.  The end user will complain, but let’s test just in case the predicted time is incorrect.  Executing the query…  Returning in an hour…  Why is this SQL statement still running?  Notice that the predicate information in the plan, unlike for the plan of the first SQL statement, does not include access(“PLD”.”PURC_ORDER_ID”=’144038′ AND “PLD”.”PURC_ORDER_LINE_NO”=1) on any of the lines – that predicate information was not pushed into the inline view, and providing a hint to push the predicates into the inline view does not change the execution plan.  The end user definitely will complain if it takes 10+ hours to print one report with the previously received quantities.  Painted into a corner, again.  Now what, do we give up?

If only we could somehow push at least the PURC_ORDER_ID further into the view.  Any ideas?

One possible solution is to create another table in the database, something like this:

CREATE TABLE CURRENT_PO_USER(
  USERNAME VARCHAR2(30) DEFAULT USER,
  PURC_ORDER_ID VARCHAR2(15),
  PRIMARY KEY(USERNAME));

GRANT ALL ON CURRENT_PO_USER TO PUBLIC;

We could then (somehow) do this before displaying the purchase order report:

DELETE FROM CURRENT_PO_USER WHERE USERNAME=USER;

INSERT INTO CURRENT_PO_USER(PURC_ORDER_ID) VALUES ('144038');

COMMIT;

Our test query then looks like this:

SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT /*+ ORDERED */
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    current_po_user CPU,
    PURC_LINE_DEL PLD
  WHERE
    CPU.USERNAME=USER
    AND CPU.PURC_ORDER_ID=PLD.PURC_ORDER_ID) P
WHERE
  P.PURC_ORDER_ID='144038'
  AND P.PURC_ORDER_LINE_NO=1
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

PURC_ORDER_ID   PURC_ORDER_LINE_NO DEL_SCHED_LINE_ RECEIVED_QTY
--------------- ------------------ --------------- ------------
144038                           1 1               8
                                   2               8
                                   3               8
                                   4               0
                                   5               0
                                   6               0
                                   7               0
                                   8               0

The query results are returned instantaneously, with an execution plan that looks like this:

-------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                 |     6 |   306 |     3   (0)| 00:00:01 |
|   1 |  SORT GROUP BY                      |                 |     6 |   306 |     3   (0)| 00:00:01 |
|*  2 |   FILTER                            |                 |       |       |            |          |
|*  3 |    CONNECT BY WITH FILTERING        |                 |       |       |            |          |
|*  4 |     FILTER                          |                 |       |       |            |          |
|   5 |      COUNT                          |                 |       |       |            |          |
|   6 |       VIEW                          |                 |     6 |   306 |     3   (0)| 00:00:01 |
|   7 |        WINDOW BUFFER                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|   8 |         NESTED LOOPS                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|   9 |          TABLE ACCESS BY INDEX ROWID| CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 10 |           INDEX UNIQUE SCAN         | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  11 |          TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 12 |           INDEX RANGE SCAN          | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
|* 13 |     HASH JOIN                       |                 |       |       |            |          |
|  14 |      CONNECT BY PUMP                |                 |       |       |            |          |
|  15 |      COUNT                          |                 |       |       |            |          |
|  16 |       VIEW                          |                 |     6 |   306 |     3   (0)| 00:00:01 |
|  17 |        WINDOW BUFFER                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  18 |         NESTED LOOPS                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  19 |          TABLE ACCESS BY INDEX ROWID| CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 20 |           INDEX UNIQUE SCAN         | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  21 |          TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 22 |           INDEX RANGE SCAN          | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
|  23 |     COUNT                           |                 |       |       |            |          |
|  24 |      VIEW                           |                 |     6 |   306 |     3   (0)| 00:00:01 |
|  25 |       WINDOW BUFFER                 |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  26 |        NESTED LOOPS                 |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  27 |         TABLE ACCESS BY INDEX ROWID | CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 28 |          INDEX UNIQUE SCAN          | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  29 |         TABLE ACCESS BY INDEX ROWID | PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 30 |          INDEX RANGE SCAN           | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("P"."PURC_ORDER_ID"='144038' AND "P"."PURC_ORDER_LINE_NO"=1)
   3 - access("RN"-1=PRIOR "RN")
   4 - filter("RN"=1)
  10 - access("CPU"."USERNAME"=USER@!)
  12 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")
  13 - access("RN"-1=PRIOR "RN")
  20 - access("CPU"."USERNAME"=USER@!)
  22 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")
  28 - access("CPU"."USERNAME"=USER@!)
  30 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")

Note
-----
   - dynamic sampling used for this statement

The next step, of course, is to create a statically defined view for our SQL statement:

CREATE VIEW PURC_LINE_DEL_PO_REPORT AS
SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT /*+ ORDERED */
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    current_po_user CPU,
    PURC_LINE_DEL PLD
  WHERE
    CPU.USERNAME=USER
    AND CPU.PURC_ORDER_ID=PLD.PURC_ORDER_ID) P
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

GRANT SELECT ON PURC_LINE_DEL_PO_REPORT TO PUBLIC;

But how do we populate the CURRENT_PO_USER table?  The ERP module supports the execution of VBScript macros when a purchase order is opened and when it is saved.  So, we just create a VBScript macro that populates that table as needed.  Painted into a corner, but fortunately there is a door in that corner of the room.

Maybe there is a better way that does not require the custom table and the custom VBScript macros?





Auto-Tuned DB_FILE_MULTIBLOCK_READ_COUNT Parameter

10 04 2010

April 10, 2010

There were a couple of recent threads on the OTN forums about the behavior of the DB_FILE_MULTIBLOCK_READ_COUNT parameter’s auto-tuning capability which was introduced with Oracle Database 10.2.0.1.  The threads included this discussion about a problem where the DB_FILE_MULTIBLOCK_READ_COUNT parameter refused to remain at a value of 0, and this discussion that described a problem where Oracle Database was auto-tuning the parameter to a value of 36.

I found the second discussion to be more interesting than the first, but in the first discussion I provided the following quotes from the Oracle documentation:

http://download.oracle.com/docs/cd/B28359_01/server.111/b28320/initparams053.htm

“As of Oracle Database 10g release 2, the default value of this parameter is a value that corresponds to the maximum I/O size that can be performed efficiently. This value is platform-dependent and is 1MB for most platforms. Because the parameter is expressed in blocks, it will be set to a value that is equal to the maximum I/O size that can be performed efficiently divided by the standard block size. Note that if the number of sessions is extremely large the multiblock read count value is decreased to avoid the buffer cache getting flooded with too many table scan buffers.”

http://download.oracle.com/docs/cd/B28359_01/server.111/b28274/iodesign.htm#g35578

“DB_FILE_MULTIBLOCK_READ_COUNT: The maximum I/O size for full table scans is computed by multiplying this parameter with DB_BLOCK_SIZE. (the upper value is subject to operating system limits). If this value is not set explicitly (or is set to 0), the default value corresponds to the maximum I/O size that can be efficiently performed and is platform-dependent.”

While the documentation did not explicitly state so, I suspected that the size of the buffer cache might also contribute to the value of the auto-tuned DB_FILE_MULTIBLOCK_READ_COUNT parameter’s value.  In the same discussion thread Jonathan Lewis indicated that the DB_CACHE_SIZE parameter was part of the calculation.  More or less the same answer, so my suspicion might have some merit.  I think that we need a test case to see if the size of the buffer cache actually has an impact on the auto-tuned parameter.

I built a new database in 64 bit Oracle Database 11.2.0.1 with an 8KB block size with all of the SGA parameters unspecified (the memory target parameters were also left unspecified), except for SGA_TARGET and SGA_MAX_SIZE.  The PGA_AGGREGATE_TARGET was set to 1800MB.  For the test case I altered the value of SGA_TARGET and SESSIONS (the value of which apparently rounds up to the nearest multiple of 8).  The results of the test follow (the value of Database Buffers also decreased for the 8000M tests as the number of sessions increased, but the changing values were not recorded):

SGA_TARGET=8000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    6000             128
    6400             128      6,979,321,856
    6448             127      6,979,321,856
    6504             126
    7000             117
    8000             102
   16000              51
   32000              25
   64000              12

-

SGA_TARGET=4000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    3000             128      3,338,665,984
    3056             128      3,338,665,984
    3080             127      3,338,665,984
    3104             126      3,338,665,984
    3128             125      3,338,665,984
    3152             125      3,338,665,984
    6304              62      3,338,665,984
    6400              61      3,338,665,984
   12608              31      3,137,339,392
   25216              15      2,432,696,320
   50432               7      1,056,964,608
   64000               6        251,658,240

-

SGA_TARGET=2000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    1400             128      1,560,281,088
    1504             123      1,560,281,088
    2000              92      1,560,281,088
    4000              46      1,560,281,088
    8000              23      1,358,954,496
   16000              11        905,969,664

In general, as the number of sessions doubles, the value of the auto-tuned DB_FILE_MULTIBLOCK_READ_COUNT is 1/2 of its previous value.  With the 8000MB SGA_TARGET, the DB_FILE_MULTIBLOCK_READ_COUNT hit 12 at 64,000 sessions.  With the 4000MB SGA_TARGET the DB_FILE_MULTIBLOCK_READ_COUNT hit 6 at 64,000 sessions.  With the 2000MB SGA_TARGET, the DB_FILE_MULTIBLOCK_READ_COUNT hit 11 at 16,000 sessions, which is roughly the same value as when the SGA_TARGET was 4 times larger with a SESSIONS parameter configured 4 times larger.

Pop quiz time:

1. What is the mathematical formula that determines the value of DB_FILE_MULTIBLOCK_READ_COUNT?  There is a chance that the above results might be different for a different release of Oracle Database.

2. Is the SGA_TARGET parameter, the DB_CACHE_SIZE parameter, the __DB_CACHE_SIZE hidden parameter, or the sum of the various buffer pool parameters the determining factor of the DB_FILE_MULTIBLOCK_READ_COUNT value (in addition to the value of the SESSIONS parameter)?  More tests are probably needed.

3. Assuming that the original poster in the OTN thread was using an 8KB block size, how was an auto-tuned value of 36 achieved for the DB_FILE_MULTIBLOCK_READ_COUNT parameter?





True or False – Autotrace

8 04 2010

April 8, 2010

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

I recently encountered a discussion thread (dbaforums.org/oracle/index.php?showtopic=19435) that asked about how to determine whether or not a SQL statement executed in a program uses indexes or full table scans – the database in question is an unspecified release version of Oracle 10g.  One of the responders in that thread pointed to an undated article (praetoriate.com/teas_prae_util11.htm) about the AUTOTRACE functionality of SQL*Plus, while other responders suggested tracing the program’s execution and then using TKPROF.

Please read the article, keeping in mind that the question concerns some release version of Oracle 10g, and see if you are able to answer the following true or false questions.  State why you believe that the question is true, or why you believe that the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. SQL*Plus’ AUTOTRACE feature performs statement tracing.

2. Using SQL*Plus’ AUTOTRACE feature requires a PLAN_TABLE in the schema of the user using AUTOTRACE.

3. AUTOTRACE retrieves the actual execution plan, along with the associated statistics for the execution.

4. When a large number of rows will be returned by SQL*Plus, the AUTOTRACE TRACEONLY feature should be used.

5. For SQL performance issues, AUTOTRACE is the first tool of choice for investigating the SQL performance issues.

6. Performance issues that are present when SQL is executed in an application will also be present when the SQL statement is executed in SQL*Plus with AUTOTRACE enabled.

-

——————————————————————————-
——————————————————————————-

May 25, 2010

The following screen capture is completely unrelated to this blog article, but is relevant to the comments about the blog redesign.  This is how the redesigned blog appears on a 16:9 netbook, with 1024 horizontal pixels of resolution:

I had to scroll the window slightly to the right to see the entire content portion of the blog, while the “floating” navigation section is hidden from view.  Internet Explorer 8.0 offers a zoom feature near the bottom right of the IE window – that feature (or a similar one in other browsers) might be a solution if your monitor does not offer 1024 pixels of horizontal resolution.

————————

Original Layout (4:3 monitor):
 
Modified Layout (4:3 monitor):





Battling the Symptoms or Addressing the Root Cause

3 04 2010

April 3, 2010

A non-Oracle specific question arrived in an email from an ERP mailing list – I think that the user who wrote the email was probably running SQL Server, but that probably does not imply much other than potential differences in read-consistency and trigger code when compared to a user running the same ERP package with Oracle Database.

Paraphrasing the question:

I need to be able to automate the running of a utility (VMFIXOHQ) on a Windows client computer.  The utility does not offer a command line interface for specifying parameters, so the method of automation must be able to enter text into screen fields, click program buttons, and activate menu items so that the utility will automatically run on a nightly basis.  A program named Automate is able to accomplish this task, but is too expensive for this specific task.

I have in the past written task schedulers that would do exactly what the author of the email requested, but I did not offer the task scheduler to the original poster.  Why, well it is hard to describe why.  With a lead-in, I offered the following analogy:

IT Guy: “Doctor, I have a splitting headache and I seem to be having trouble remembering things.”
Doctor1: “Let me write you a prescription for a new desk with a padded writing surface.”
IT Guy: “OK, but I don’t see how that will help my headache.”
Doctor1: “You just told me that you only have splitting headaches while sitting at your desk.”
IT Guy: “That new desk works great.  The headaches still happen, but don’t last quite as long.”
Doctor1: “Now let me prescribe something to cure the imprint of the paperclip and the stapler on your forehead.”
Doctor2:Wouldn’t it be easier to find out why he keeps banging his head on his desk?

In the above analogy, Doctor1 was treating the symptoms of the problem.  Maybe he notice the IT guy’s red forehead, and thought that if the IT guy must bang his head on his desk, he really should have a softer surface for his forehead to hit.  Once the original problem was mitigated, a secondary, related problem remained – obviously, the IT guy should make certain to clear his desk before banging his head.

Doctor2, on the other hand, suggested a root cause analysis.  If the IT guy is banging his head on his desk, determine what triggers the IT guy to bang his head on his desk.  Maybe he can’t find the flyswatter.  Maybe he once hit his head and then by coincidence found a solution to a perplexing problem.  Maybe he is frustrated (he might have worn too small of a size of shoes, causing his feet to hurt).  Maybe someone is forcing him to bang his head?  Wouldn’t it be better to find out why, rather than just trying a number of things that might make the problem less severe, but never actually fix the problem?

An Oracle database example of this is simply throwing hardware at a performance problem because a root cause analysis is perceived as requiring too much time and being too expensive (computer hardware costs are decreasing while at the same time IT labor costs are increasing).  Sure, replace the server with one having 4 times as many CPUs and 4 times as much memory – after all, hardware is cheap compared to the perceived cost of a root cause analysis (at least that is what it says on the news).  Forget that such a cheap upgrade will require 4 times as many Oracle Database CPU licenses, accompanied by 4 times as much for annual Oracle support/maintenance fees.  On second thought, maybe a root cause analysis is really a much better and less costly approach, no matter if the performance problem is caused by a change to daylight savings time, someone verbally abusing the SAN, an upgrade of the Oracle Database version, or something else.

It might seem that I drifted a bit from the topic of the email that arrived from the ERP mailing list about scheduling the execution of the VMFIXOHQ utility.  That utility is not one that should be run daily, not one that should be run weekly, not one that should be run monthly, and not even one that should be run yearly (this doesn’t sound like anything in the Oracle Database universe, does it?).  That utility has a very specific purpose – it fixes the results of application and/or database trigger bugs that caused the stored on hand inventory counts for a specific part to differ from what is sitting on the shelf.  More accurately, a transaction is recorded in the database whenever parts are added to inventory, removed from inventory, or moved from one warehouse location to another, causing the on hand inventory counts for the parts are adjusted accordingly.  This VMFIXOHQ utility runs through these transactions from day 1 and effectively determines how many of the part should be sitting on the shelf based on the supporting inventory transactions.  Scheduling the running of the VMFIXOHQ utility does not address the real reason for the inventory counts being inaccurate; rather it is a band-aid (a padded desk, if you will) for the real problem – a code bug, missing trigger, improperly handled deadlock, or multi-session read-consistency issues.

Was I wrong not to tell the original poster how to schedule the running of this utility?  :-)





True or False – Wait Events

31 03 2010

March 31, 2010

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

A continuation of the series of true or false quizzes for the week – maybe this one is too easy.  Today’s quiz is on the topic of wait events.   Assuming that the questions apply to a release of Oracle that has been available for up to five years, state why you believe that the answer to the question is true, or why you believe that the answer to the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. Assume that a database instance is being prepared for 1,500 to 2,000 sessions.  Given an unlimited budget, it is possible to configure the database instance to completely eliminate wait events.

2. Consider two identical Oracle databases with a single session connected to each database instance.  Each of the two sessions submits exactly the same SQL statement, with the first session experiencing no wait events while executing the query, and the second session experiencing nearly continuous I/O wait events.  The lack of wait events implies that the query execution for the first session is optimal, and should be the performance target for the second session.

3. Idle wait events are insignificant in performance tuning exercises, and should be ignored.

4. For every one minute of elapsed time, each CPU in the server is capable of accumulating 60 seconds of CPU wait time.

Did I mention that I dislike true/false type questions?  But then these are not simple true/false questions.





True or False – Improving Performance of SQL Statements

30 03 2010

March 30, 2010

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

A continuation of the concept of yesterday’s true or false quiz – this one is a little easier, with new reading material.  Today’s quiz is on the topic of improving performance of SQL statements.  The reading material:
Article 1
Article 2
Article 3

Article 4
Article 5
Article 6
Article 7
Article 8 (actually a book)
Article 9 (actually a book)
Article 10 (actually a book)
Article 11

Please read the above articles and see if you are able to answer the following true or false questions, assuming that the questions apply to a release of Oracle that has been available for up to five years.  State why you believe that the answer to the question is true, or why you believe that the answer to the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.  (Most of these questions can be answered with the help of the first couple of links.)

1. Queries containing subqueries should be rewritten as a logical step in improving query performance.

2. Complex queries should be decomposed into multiple queries using global temp tables and/or WITH clauses as a step toward improving query performance.

3. Significant performance improvements, possibly 20 fold, are possible by replacing some or all of a SQL statement with PL/SQL.  If true, provide an example showing a significant performance improvement with such a replacement.  If not true, provide an example that shows that performance did not improve significantly.

4. There are cases were performance improvements are possible by modifying a SQL statement containing a three table equijoin, which accesses primary and foreign keys columns of the tables, into a SQL statement which accesses a single table with two PL/SQL functions (each containing a SELECT) in column positions.





True or False – Oracle Sorting

29 03 2010

March 29, 2010 (Updated April 6, 2010 with a test table)

(Forward to the Next Post in the Series)

I recently encountered a discussion thread (dbaforums.org/oracle/index.php?s=eacd9ff86b358b4a14ecd3fd7653a9fd&showtopic=19407) that pointed to a news article about the internals of Oracle sorting.  The news article (dba-oracle.com/t_oracle_sorting.htm) has a date of October 15, 2007, so it is probably reasonable to assume that the article describes the behavior of Oracle Database 10g R2, and possibly Oracle Database 11g R1.

Please read the news article and see if you are able to answer the following true or false questions.  State why you believe that the question is true, or why you believe that the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. Sequencing of database output first started in the 1960s.

2. One of the very important components of Oracle tuning is Oracle sorting, yet that process is often overlooked.

3. SSD is a synonym for a super-fast RAM disk.

4. Oracle Database always performs an automatic sorting operation when a GROUP BY clause is used in a SQL statement, when an index is created, and when an ORDER BY clause is used in a SQL statement.

5. The cheapest method is always used by Oracle Database when ordering a resultset.

6. A hinted execution plan involving a single table, with a /*+ index */ hint, will always retrieve the rows in the sorted order of the index.

7. If a SQL statement requires a single sort operation that completes in memory, that SQL statement will not use any space in the TEMP tablespace when the rows are retrieved – with the assumption that a hash join did not spill to disk.

8. The CPU_COST parameter causes Oracle Database to favor the pre-sorted ordering of an index over a discrete sorting operation.

9. The value of the SORT_AREA_SIZE parameter or the PGA_AGGREGATE_TARGET parameter if used, influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

10. The clustering factor of an index influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

11. The default database block size in use by the database influences Oracle Database’s decision to prefer the pre-sorted ordering of an index over a discrete sorting operation.

12. A sort operation will only spill to disk when RAM is exhausted.

13. “At the time a session is established with Oracle, a private sort area is allocated in memory for use by the session for sorting, based on the value of the sort_area_size initialization parameter.”  Supporting evidence:
http://books.google.com/books?id=gsFC1D1LmvQC&pg=PA306&lpg=PA306#v=onepage&q=&f=false
http://www.articles.freemegazone.com/oracle-sorting.php
oracle-training.cc/oracle_tips_sort_operations.htm

14. For sort intensive tasks it is not possible to adjust the amount of memory allocated to those tasks by adjusting the SORT_AREA_SIZE parameter at the session level.

15. The entire database can be slowed down due to a disk sort in the TEMP tablespace because sorts to disk are I/O intensive.

16. A good general rule is that the SORT_AREA_SIZE parameter should be adjusted to eliminate sorts to disk caused by GROUP BY operations.

17. Buffer pool blocks are allocated to hold or manage the blocks that are in the TEMP tablespace.

18. An optimal workarea execution, completed entirely in memory, is always preferred over a one-pass or multi-pass workarea execution.

19. Free buffer waits can be caused by excessive sorts to disk, which cause data blocks needed by other sessions to be paged out of the buffer.

20. One percent is an acceptable ratio of disk sorts to the total number of sorts.

21. When the PGA_AGGREGATE_TARGET parameter is specified, the total work area size cannot exceed 200MB.

22. No task may use more than 10MB for sorting.

23. A DBA should modify two hidden (underscore) parameters to permit up to 50MB of memory to be used for an in-memory sort operation for a SQL statement.

Have you ever read an article in an attempt to find the answer to a very specific question, only to find that by the time the end of the article is reached, you now have a whole new set of questions?  Try to answer the above questions using something beyond true or false – tell me why in detail it is true or why it is false.  Are there any other questions that could be asked about the article?

——-

Test table for question #10, added April 6, 2010:

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

INSERT INTO T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,100),0,NULL,ROWNUM),
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

ALTER TABLE T1 MODIFY (C2 NOT NULL);

CREATE INDEX IND_T1_C2 ON T1(C2);

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




Duplicates when Querying V$TEMPSEG_USAGE?

22 03 2010

March 22, 2010

If you search through the Oracle documentation, you will find the following in the Oracle Database 9.2 documentation:

V$SESSION is basically an information view used for finding the SID or SADDR of a user. However, it has some columns that change dynamically and are useful for examining a user. For example:

SQL_HASH_VALUE, SQL_ADDRESS: These identify the SQL statement currently being executed by the session. If NULL or 0, then the session is not executing any SQL statement. PREV_HASH_VALUE and PREV_ADDRESS identify the previous statement being executed by the session.

The Oracle Database 10.2 documentation includes the following:

Use the following query to determine, at a point in time, which sessions are waiting for I/O:

SELECT SQL_ADDRESS, SQL_HASH_VALUE
  FROM V$SESSION
 WHERE EVENT LIKE ‘db file%read’;

Again in the Oracle Database 10.2 documentation:

SQL_ADDRESS: Used with SQL_HASH_VALUE to identify the SQL statement that is currently being executed
SQL_HASH_VALUE: Used with SQL_ADDRESS to identify the SQL statement that is currently being executed

The Oracle Database 11.2 documentation repeats what is found in the 10.2 documentation:

SQL_ADDRESS: Used with SQL_HASH_VALUE to identify the SQL statement that is currently being executed
SQL_HASH_VALUE: Used with SQL_ADDRESS to identify the SQL statement that is currently being executed

Why doesn’t the documentation for 10.2 and 11.2 suggest using the SQL_ID and SQL_CHILD_NUMBER columns to find the SQL statement that is currently being executed?  For that matter, why isn’t there a SQL_CHILD_ADDRESS column in V$SESSION if the documentation suggests using SQL_ADDRESS to find the SQL statement currently being executed?

Recently, an errata was filed for page 188 of the Expert Oracle Practices book by an observant reader named Andreas, who mentioned that the SQL statement found on that page could produce duplicate rows, and offered an improved version of the SQL statement.  The SQL statement from the book follows:

SQL> SELECT /*+ ORDERED */
  2    TU.USERNAME, S.SID, S.SERIAL#, S.SQL_ID, S.SQL_ADDRESS, TU.SEGTYPE, TU.EXTENTS,
  3    TU.BLOCKS, SQL.SQL_TEXT
  4  FROM
  5    V$TEMPSEG_USAGE TU, V$SESSION S, V$SQL SQL
  6  WHERE
  7    TU.SESSION_ADDR=S.SADDR
  8    AND TU.SESSION_NUM=S.SERIAL#
  9    AND S.SQL_ID=SQL.SQL_ID
 10    AND S.SQL_ADDRESS=SQL.ADDRESS;

The sample output included in the book from that SQL statement is this:

USERNAME   SID  SERIAL# SQL_ID        SQL_ADDRESS      SEGTYPE EXTENTS     BLOCKS
-------- ----- -------- ------------- ---------------- ------- ------- ----------
TESTUSER   165     2171 7pqxpw71fkjvj 000000027DB50320 SORT        370      47360

SQL_TEXT
-------------------------------------------------------------------
SELECT * FROM T1,T2 WHERE T1.ID<=100 AND T2.ID<=1000 ORDER BY T1.ID

We also included the execution plan for the SQL statement, but did not show how the execution plan was obtained since that would be discussed later in the chapter:

------------------------------------------------------------------------------------
| Id |Operation                   | Name   | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|  0|SELECT STATEMENT             |        |       |       |   119G(100)|          |
|  1| MERGE JOIN CARTESIAN        |        |  6552G|   643T|   119G  (3)|999:59:59 |
|  2|  TABLE ACCESS BY INDEX ROWID| T1     |  1005K|    50M|  1006K  (1)| 00:07:10 |
|* 3|   INDEX RANGE SCAN          | IND_T1 |  1005K|       |  2293   (9)| 00:00:01 |
|  4|  BUFFER SORT                |        |  6516K|   341M|   119G  (3)|999:59:59 |
|* 5|   TABLE ACCESS FULL         | T2     |  6516K|   341M|   118K  (3)| 00:00:51 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("T1"."ID"<=100)
   5 - filter("T2"."ID"<=1000)

Note
-----
   - dynamic sampling used for this statement

What is wrong with the above SQL statement (no, not the one that generated the Cartesian join – the other one that queried V$TEMPSEG_USAGE)?  We did not write the two chapters in linear order, starting at the beginning of chapter 8 and working to the end of chapter 9.  Instead, we outlined each section that would appear in the chapter, and wrote the contents of those sections in spurts.  At the time that the SQL statement which queried V$TEMPSEG_USAGE was written, we had already written the AdaptiveCursorBindTest.sql sample script that is mentioned later in chapter 8.  When the above SQL statement was written, I recall being internally conflicted – why?

  • Should the SQL statement instead use the HASH_VALUE, rather than SQL_ID, as suggested by the Oracle 10.2 and 11.2 documentation, which would then allow the query to also work on Oracle 9.2?  Would it be sufficient to just add a note stating that if you are running Oracle 9.2 or earlier, substitute the SQL_HASH_VALUE for SQL_ID?
  • Should the SQL statement join to V$SQLAREA to eliminate the problems with multiple child cursors for the same SQL_ID?  But how would we then retrieve the correct execution plan from the server’s memory in the event that the multiple child cursors have different execution plans?
  • Should we also use the SQL_CHILD_NUMBER column to join to V$SQL?  But then what about the users still running Oracle 9.2 or earlier?
  • Should there be a SQL_CHILD_ADDRESS column in V$SESSION since the SQL_ADDRESS column will probably be the same for all child cursors for a given SQL_ID?
  • How do we deal with the output of the AdaptiveCursorBindTest.sql sample script, which showed Oracle 11.1.0.6 producing multiple child cursors with the same CHILD_NUMBER for a give SQL_ID?  That would mean that even if the query included the SQL_CHILD_NUMBER column, there is still a potential for duplicate rows being returned by the query.

The initial plan was to circle back to this section of the chapter and try to describe some of the potential issues with using the SQL statement that queried V$TEMPSEG_USAGE, but that would not be an easy task without the reader first reading the rest of that chapter.  Alas, just days after the final version of the chapters were due to the publisher, and the first drop of ink was spilled on the page of the printed book, we made another pass through the chapter.  When I executed this SQL statement I found that it was listing the same SQL_ID more than once.  But why?  A query of V$SQL_SHARED_CURSOR showed that ROLL_INVALID_MISMATCH was set to Y when a second (or third) child cursor was created.  What does that mean?  Execute a query, collect statistics on the tables or indexes used by the query, wait about 5 hours, re-execute the query, and then check V$SQL_SHARED_CURSOR.  The delay is mentioned here and here, along with a hidden _optimizer_invalidation_period parameter that controls how long after statistics collection is performed, the previously hard parsed cursors that referenced those objects can no longer be used.

In short, we never did circle back to that section of the chapter before the book was printed, so I am happy that Andreas filed the errata report, which allowed us to clarify the situation.  We did join to V$SQL so that with a little more work it would be possible to determine the correct execution plan to pull from memory.  In retrospect, we probably should have just written the SQL statement like the following and provided a quick comment about Oracle Database 9.2.0.8 and earlier, and the potential duplicates in Oracle Database 11.1.0.6 that were demonstrated in the AdaptiveCursorBindTest.sql sample script:

SELECT /*+ ORDERED */
  TU.USERNAME, S.SID, S.SERIAL#, S.SQL_ID, S.SQL_CHILD_NUMBER,
  TU.SEGTYPE, TU.EXTENTS, TU.BLOCKS, SQL.SQL_TEXT
FROM
  V$TEMPSEG_USAGE TU, V$SESSION S, V$SQL SQL
WHERE
  TU.SESSION_ADDR=S.SADDR
  AND TU.SESSION_NUM=S.SERIAL#
  AND S.SQL_ID=SQL.SQL_ID
  AND S.SQL_CHILD_NUMBER=SQL.CHILD_NUMBER
  AND S.SQL_ADDRESS=SQL.ADDRESS;

Without looking at the V$SQL_SHARED_CURSOR view, what are the different reasons for multiple child cursors to be created?  To get you started:

  • Collecting object statistics
  • Changing the data type of bind variables
  • Changing the data length of bind variables
  • Changing the optimizer mode (ALL_ROWS, CHOOSE, RULE, FIRST_ROWS, etc.)
  • Adaptive cursor sharing (starting with Oracle Database 11.1.0.6)
  • Cardinality feedback (starting with Oracle Database 11.2.0.1)

I give my thanks to Andreas for inspiring this blog article.

Related blog articles:
SORT_AREA_SIZE Affecting Sorts to Disk with PGA_AGGREGATE_TARGET Set?
SORT_AREA_SIZE Affecting Sorts to Disk with PGA_AGGREGATE_TARGET Set 2?
SQL PLAN_HASH_VALUE Changes for the Same SQL Statement
V$SESSION_LONGOPS – Where’s My SQL Statement





Select Statement Causing an ORA-00001?

11 03 2010

March 11, 2010

Sometimes I receive seemingly interesting emails showing Oracle errors – leaving me to ponder… certainly, that can’t cause an error, can it?  Here is one that I received a year ago (paraphrased):

The commercially developed application that we are using displayed an error message identifying a SELECT statement as the source of an ORA-00001 error.  What is the source of the Oracle constraint error?  The error message displayed by the application is as follows:

select account_period
from PROJECT_SUMMARY
where project_id = :m_saProjSumProjectID[nProjSumIndex]
and id =:m_saProjSumSavedID[nProjSumIndex]
into :nACCOUNT_PERIOD

ORA-00001: unique constraint (TESTUSER.SYS_C006354) violated

This transaction has resulted in violating an Oracle defined constraint.
Constraints are enforced by the database manager.  This transaction has
been rolled back.

My first thought at the sight of this error was that the commercially developed application was actually displaying one of the SQL statements that was executed after the SQL statement which triggered the primary key violation.  It is easy to let a runtime error slide through for a period of time before the program notices that an error happened – maybe it is just a sign of sloppy programming (I hope not, because this has happened in some of my custom-developed programs too).

How would we start to troubleshoot this error message?  The “SYS_C” portion of the constraint name indicates that the constraint is most likely a system generated constraint name, probably intended to enforce a uniqueness requirement for a primary key column.  Exporting the data from the database using Datapump export (or the legacy exp utility) and importing the data into a new database could cause the number following “SYS_C” to change, and it is likely that constraint SYS_C006354 in my database (that is used by the same application) is very different from that of the person who posed the question to me.

Let’s see if we are able to find the answer by working the problem in a circular fashion.  For example, let’s find the name of the index that is used to enforce the primary key constraint on of one the application’s tables:

SELECT
  INDEX_NAME
FROM
  DBA_INDEXES
WHERE
  INDEX_NAME LIKE 'SYS%'
  AND TABLE_NAME='INVENTORY_TRANS';

INDEX_NAME
-----------
SYS_C005168

Now that we know that the index is named SYS_C005168, we could do something like this:

SELECT
  DC.OWNER,
  DC.CONSTRAINT_NAME,
  DC.CONSTRAINT_TYPE,
  DC.TABLE_NAME,
  DC.STATUS,
  SUBSTR(DCC.COLUMN_NAME,1,30) COLUMN_NAME
FROM
  DBA_CONSTRAINTS DC,
  DBA_CONS_COLUMNS DCC
WHERE
  DC.CONSTRAINT_NAME='SYS_C005168'
  AND DC.OWNER='TESTUSER'
  AND DC.OWNER=DCC.OWNER
  AND DC.CONSTRAINT_NAME=DCC.CONSTRAINT_NAME
ORDER BY
  DCC.POSITION;

OWNER   CONSTRAINT_NAME  CONSTRAINT_TYPE  TABLE_NAME       STATUS   COLUMN_NAME
------  ---------------  ---------------  ---------------  -------  --------------
SYSADM  SYS_C005168      P                INVENTORY_TRANS  ENABLED  TRANSACTION_ID

The above output shows that the primary key constraint SYS_C005168 enforces the uniqueness of the primary key (TRANSACTION_ID) column in the table INVENTORY_TRANS.  We just demonstrated that we now know what we already mostly knew.

In the case of the person who sent the email to me, the table name was not known.  So, we could take the last of the above SQL statements and substitute SYS_C006354 in place of SYS_C005168 to find the table name and primary key column that was violated.  If the SQL statement failed to return usable information the next step might be to enable a 10046 trace at level 4 for one of the affected sessions, and try to reproduce the problem.  A 10046 trace will list the sequence of events that led up to the error message appearing in the client application.





Why Doesn’t This Trigger Work – No Developer Tools Allowed in the Database

10 03 2010

March 10, 2010

In one of last week’s blog articles I asked why a SQL statement that had appeared in a book, was copied to various websites, and was offered as an example of good SQL simply did not work.  A couple of readers of this blog took up the challenge to offer suggestions.  I think that I found another example of blindly reproducing other’s code without verifying that the code works as expected.  What did I find this time?

http://www.orafaq.com/scripts/security/blocktools.txt

rem -----------------------------------------------------------------------
rem Filename:   NoTOAD.sql
rem Purpose:    Block developers from using TOAD and other tools on
rem             production databases.
rem Date:       19-Jan-2004
rem Author:     Frank Naude
rem -----------------------------------------------------------------------

CONNECT / AS SYSDBA;

CREATE OR REPLACE TRIGGER block_tools_from_prod
  AFTER LOGON ON DATABASE
DECLARE
  v_prog sys.v_$session.program%TYPE;
BEGIN
  SELECT program INTO v_prog
    FROM sys.v_$session
  WHERE  audsid = USERENV('SESSIONID')
    AND  audsid != 0  -- Don't Check SYS Connections
    AND  rownum = 1;  -- Parallel processes will have the same AUDSID's

  IF UPPER(v_prog) LIKE '%TOAD%' OR UPPER(v_prog) LIKE '%T.O.A.D%' OR -- Toad
     UPPER(v_prog) LIKE '%SQLNAV%' OR -- SQL Navigator
     UPPER(v_prog) LIKE '%PLSQLDEV%' OR -- PLSQL Developer
     UPPER(v_prog) LIKE '%BUSOBJ%' OR   -- Business Objects
     UPPER(v_prog) LIKE '%EXCEL%'       -- MS-Excel plug-in
  THEN
     RAISE_APPLICATION_ERROR(-20000, 'Development tools are not allowed on PROD DB!');
  END IF;
END;
/
SHOW ERRORS

If you search the Internet you will find this piece of code, minus the header block, on various websites as recently as 2010, including in this OTN thread.  The idea of blocking development tools in a production database could be a valid goal, so I am able to understand the interest in the trigger.  What is wrong with the trigger?  Is it just a case that SQL*Plus could also be considered a developer tool?  What about the Crystal Reports development enviroment?  What if the developer created his own development tool to access the database?  What if… someone changed the filename of TOAD?  What if… the trigger doesn’t actually block Excel without any tricks such as changing Excel’s filename?

The contents of this blog article were tested with Oracle Database 11.1.0.7 with an Oracle 11.1.0.7 client, Excel 2007, and Windows Vista as the client operating system.  First, I created the trigger when connected as SYS, and then queried V$SESSION to find that only my SQL*Plus connection was listed.

Then in Excel 2007 I selected Get External DataFrom Other Sources:

When prompted, I connected to the database as a normal user:

I was then able to freely execute queries against the database using the Microsoft Query Tool, which would then allow me to very easily return the rows to an Excel spreadsheet.

OK, maybe the above is cheating… a little.

But, what is the point in blocking Excel with the logon trigger, is the trigger supposed to stop someone from firing up an Excel macro that uses ADO to connect to the database and retrieve whatever information the developer would like to see?  Kind of like this example:

The logon trigger that appears on several websites did not block my Excel connection – if you take a look at the first screen capture you will see that the logon trigger was created without error, and then I was able to connect with the Microsoft Query Tool and my Excel macro using a normal user’s account.  Someone want to try explaining what went wrong?  Must be that we need to file a Metalink bug report, after all, I saw this example on the news so it must be true.  :-)

Maybe Oracle Database 11.2.0.1 will respond more favorably (Oracle 11.1.0.7 client, Excel 2007, and Windows Vista as the client operating system):

While this code might have worked fine in 2004, it would probably make sense to test this trigger code before copying it to your website.  I think that this is worth repeating:

Lesson 1: if you plan to publish something, whether in book form or on the Internet, make certain that what you publish actually works (or at least looks like you put some effort into it) .

Lesson 2: if you plan to copy someone else’s work and post it on your website/blog make certain that what you copy and pass off as your own actually works.

Lesson 3: don’t trust everything that you read on the Internet or in a book without first verifying that the information is correct, even if you find the information on your favorite website.





Where Are My Views?

5 03 2010

March 5, 2010

A year ago I received an email that was sent to an ERP user’s mailing list that stated that statically defined views were disappearing from one of the email author’s databases.  He stated that this problem had been an issue since Oracle 9i (probably 9.2.0.x) and continues to be a problem with Oracle 10g (likely 10.2.0.3 or 10.2.0.4).  The views were simply disappearing.  Was it caused by a bug in Oracle?  Was it caused by a bug or a naming conflict in the ERP system?  Was it caused by a renegade developer?  Was it a permission problem?  Was it a dropped synonym?  Or was someone routinely breaking it at night, found that the actual table was too big to fit in the get-away car, and managed to escape with only a picture of the table?

Since we do not know what is happening to the views, maybe the best course of action is to set a trap.  First, we will create a logging table to capture details about any objects that are dropped:

CREATE TABLE OBJECT_DROP_LOG (
  DICT_OBJ_TYPE VARCHAR2(40),
  DICT_OBJ_OWNER VARCHAR2(40),
  DICT_OBJ_NAME VARCHAR2(40),   
  DROP_USERNAME VARCHAR2(30) DEFAULT USER,
  DROP_DATE DATE DEFAULT SYSDATE);

GRANT INSERT ON OBJECT_DROP_LOG TO PUBLIC;
GRANT ALL ON OBJECT_DROP_LOG TO SYS;

As rows are inserted into the table, the DROP_USERNAME column will be automatically populated with the username of the person performing the object drop, and the DROP_DATE column will be automatically populated with the date and time of the drop.  Now we need a trigger to capture the other three columns in the table, the trigger will be created by the SYS user:

CREATE OR REPLACE TRIGGER LOG_DROP AFTER DROP ON DATABASE
BEGIN
  IF ORA_SYSEVENT='DROP' THEN
    INSERT INTO TESTUSER.OBJECT_DROP_LOG(
      DICT_OBJ_TYPE,
      DICT_OBJ_OWNER,
      DICT_OBJ_NAME)
    VALUES(
      ORA_DICT_OBJ_TYPE,
      ORA_DICT_OBJ_OWNER,
      ORA_DICT_OBJ_NAME);
  END IF;
END;
/

Now let’s log back in as our test user and create a couple of objects that will be dropped later:

CREATE TABLE T10 AS
SELECT
  ROWNUM C1
FROM
  DUAL
CONNECT BY
  LEVEL<=10;

Table created.

CREATE UNIQUE INDEX IND_T10 ON T10(C1);

Index created.

CREATE VIEW MY_STUFF AS
SELECT
  *
FROM
  T10;

View created.

Now let’s suppose that the event happens, something does this:

DROP VIEW MY_STUFF;

View dropped.

DROP TABLE T10;

Table dropped.

Now that the damage is done, will the logging table contain 0, 1, 2, or 3 entries?  Let’s log in as SYS and see what was captured:

COLUMN DICT_OBJ_TYPE FORMAT A13
COLUMN DICT_OBJ_OWNER FORMAT A14
COLUMN DICT_OBJ_NAME FORMAT A13
COLUMN DROP_USERNAME FORMAT A13
COLUMN DROP_DATE FORMAT A19

SELECT
  DICT_OBJ_TYPE,
  DICT_OBJ_OWNER,
  DICT_OBJ_NAME,
  DROP_USERNAME,
  TO_CHAR(DROP_DATE,'MM/DD/YYYY HH24:MI:SS') DROP_DATE
FROM
  OBJECT_DROP_LOG
ORDER BY
  DROP_DATE;

DICT_OBJ_TYPE DICT_OBJ_OWNER DICT_OBJ_NAME DROP_USERNAME DROP_DATE
------------- -------------- ------------- ------------- -------------------
VIEW          TESTUSER       MY_STUFF      TESTUSER      03/04/2010 23:17:33
TABLE         TESTUSER       T10           TESTUSER      03/04/2010 23:18:08

We see the drop of the view and the drop of the table, does the index still exist?

SELECT
  COUNT(*)
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='IND_T10';

  COUNT(*)
----------
         0

Looks like the table’s index is gone without a trace.  Let’s recover the table:

FLASHBACK TABLE TESTUSER.T10 TO BEFORE DROP;

Flashback complete.

SELECT
  COUNT(*)
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='T10';

  COUNT(*)
----------
         1

SELECT
  COUNT(*)
FROM
  DBA_OBJECTS
WHERE
  OBJECT_NAME='IND_T10';

  COUNT(*)
----------
         0

The table is back, but where is my index?

SELECT
  INDEX_NAME
FROM
  DBA_INDEXES
WHERE
  TABLE_NAME='T10'
  AND OWNER='TESTUSER';

INDEX_NAME
------------------------------
BIN$9mtb8W99SfiPr1EXVFGkgw==$0

That is a rather ugly name for an index – it was automatically changed when the associated table was dropped.  Connecting again as the TESTUSER:

ALTER INDEX "BIN$9mtb8W99SfiPr1EXVFGkgw==$0" RENAME TO IND_T10;

Index altered.

SELECT
  COUNT(*)
FROM
  USER_OBJECTS
WHERE
  OBJECT_NAME='IND_T10';

  COUNT(*)
----------
         1

The table and index are now back, so:

SELECT
  COUNT(*)
FROM
  USER_OBJECTS
WHERE
  OBJECT_NAME='MY_STUFF';

  COUNT(*)
----------
         0

Where is my view?  If I had executed the following, I could easily recreate the view:

SET PAGESIZE 0
SET LONG 90000
SPOOL MYSTUFF.SQL

SELECT
  DBMS_METADATA.GET_DDL('VIEW','MY_STUFF','TESTUSER')
FROM
  DUAL;

SPOOL OFF

(Caution: If you choose to implement this trigger, test it very carefully before pushing it into a production environment.  You could of course extend this example to capture much more information.)





Why Doesn’t this Trigger Code Work?

4 03 2010

March 4, 2010

A couple of days ago I received an interesting email from an ERP mailing list.  That email contained an Oracle trigger that looked like it would be helpful, but the author of the trigger was struggling a bit with the PL/SQL code and asked for some assistance with the trigger code.  The trigger code contained in the email looked like this:

CREATE OR REPLACE TRIGGER "TESTUSER"."TEST3" AFTER
UPDATE OF "STATUS" ON "TESTUSER"."OPERATION" REFERENCING OLD AS OLDDATA NEW AS NEWDATA FOR EACH ROW DECLARE
  msg1 varchar2(20000) := 'Despatch as been closed for ';
  msg2 varchar2(20000) := ' And there are operations not closed';
  recipients varchar2(20000);
  CountPlease number;
  Customer varchar2(20000);
  Base varchar2(20000) := :newdata.workorder_base_id;
BEGIN
IF UPDATING THEN
  if :newdata.resource_id = 'DESPATCH' and :Olddata.status <> :newdata.status and :newdata.status = 'C' then

  select name into Customer from customer where id in (select customer_id from customer_order where id = Base);

---jaggie bit here
    select count(distinct(workorder_lot_id||sequence_no||resource_id)) into CountPlease
    from operation where status = 'R' and workorder_type = 'W' and workorder_base_id = Base
    and not resource_id in ('DEVELOPMENT','START','DESPATCH','SERVICE');
---jaggie bit ends.
---Not yet inserted If CountPlease greater than 0 then...

    UTL_MAIL.SEND (
    sender => 'me@myplace.com.au',
    recipients => 'me@myplace.com.au',
    subject => msg1|| Base,
    message => msg1|| Customer|| ' , ' || Base || msg2||CountPlease);

  end if;
END IF;
END;
/

Paraphrasing the description of the problem:

I am having a problem with a trigger that I am trying to add to the OPERATION table.  The purpose of the trigger is to send an email if someone generates a labor ticket that causes the STATUS column of a row in the OPERATION table to change from ‘R’ (released) to ‘C’ (closed) when the RESOURCE_ID column contains the word ‘DESPATCH’, and there are other associated rows (excluding the rows with the RESOURCE_ID set to ‘DEVELOPMENT’, ‘START’, ‘DESPATCH’, or ‘SERVICE’) in that table associated with the modified row where the STATUS column is set to ‘R’.

The trigger works up to the point of the SQL statement containing the COUNT function, which is ultimately used to determine if the email should be sent.  The trigger compiles without error, however when a labor ticket is created (a row is inserted into the LABOR_TICKET table) that causes the STATUS of the corresponding row in the OPERATION table to change from ‘R’ to ‘C’ (caused by a trigger on the LABOR_TICKET table that then causes another trigger to fire on the OPERATION table), I receive the dreaded error in the ERP program of “invalid handle”. Yet my SQL seems sound via Sqlplus.

My other select statements work, and my email generates, provided I leave out the SELECT COUNT… SQL statement that is used to see if any other related rows in the OPERATION table have a status of ‘R’.

PL/SQL is not my native language (I think that it is still English), so I started by cleaning up the trigger code into a more readable form:

CREATE OR REPLACE TRIGGER "TESTUSER"."TEST3" AFTER UPDATE OF "STATUS" ON "TESTUSER"."OPERATION"
REFERENCING OLD AS OLDDATA NEW AS NEWDATA
FOR EACH ROW DECLARE
  MSG1 VARCHAR2(500) := 'Despatch as been closed for ';
  MSG2 VARCHAR2(500) := ' And there are operations not closed ';
  RECIPIENTS VARCHAR2(500);
  COUNTPLEASE NUMBER;
  CUSTOMERNAME VARCHAR2(50);
  BASEID VARCHAR2(30) := :NEWDATA.WORKORDER_BASE_ID;

BEGIN
IF UPDATING THEN
  IF :NEWDATA.RESOURCE_ID = 'DESPATCH' AND :OLDDATA.STATUS <> :NEWDATA.STATUS AND :NEWDATA.STATUS = 'C' THEN
    SELECT
      C.NAME INTO CUSTOMERNAME
    FROM
      CUSTOMER C,
      CUSTOMER_ORDER CO
    WHERE
      C.ID = CO.CUSTOMER_ID
      AND CO.ID = BASEID;

---jaggie bit here
    SELECT
      COUNT(SEQUENCE_NO||RESOURCE_ID) INTO COUNTPLEASE
    FROM
      OPERATION
    WHERE
      STATUS = 'R'
      AND WORKORDER_TYPE = 'W'
      AND WORKORDER_BASE_ID = :NEWDATA.WORKORDER_BASE_ID
      AND WORKORDER_LOT_ID = :NEWDATA.WORKORDER_LOT_ID
      AND WORKORDER_SPLIT_ID='0'
      AND RESOURCE_ID NOT IN ('DEVELOPMENT','START','DESPATCH','SERVICE');
---jaggie bit ends.

    IF COUNTPLEASE > 0 THEN
      UTL_MAIL.SEND (
        SENDER => 'me@myplace.com.au',
        RECIPIENTS => 'me@myplace.com.au',
        SUBJECT => MSG1|| BASEID,
        MESSAGE => MSG1|| CUSTOMERNAME|| ' , ' || BASEID || MSG2 ||COUNTPLEASE);
      NULL;
    END IF;
  END IF;
END IF;
END;
/

After the clean up I managed to compile the trigger and then performed a test with the ERP program.  The “dreaded error message” looked something like this:

ORA-04091: table TESTUSER.OPERATION is mutating, trigger/function may not see it ORA-06512: at “TESTUSER.TEST3″, line 24 ORA-04088: error during execution of trigger ‘TESTUSER.TEST3′ ORA-06512: at “TESTUSER.AIUD_LABTICK_STMT”, line 137 ORA-06512: at “TESTUSER.TAIUD

Something is wrong – the table to which the trigger is attached is mutating, which apparently means that it is changing into something other than a table (a chair, maybe?).  :-)

What needs to be done to finish fixing this trigger?  If you are struggling to find the answer, I might suggest taking a look at page 287 of the book “Beginning PL/SQL From Novice to Professional” (I am not saying that the answer is on that page, but you might want to look at it just for fun).  The documentation also suggests another approach for dealing with mutating tables, but I do not know if it will help in this case.  So, what needs to be done – removing NULL; was not the solution.





DBMS_XPLAN Format Parameters

1 03 2010

March 1, 2010 (updated March 5, 2010)

In the last couple of years I have seen several very good references for the DBMS_XPLAN parameters, but it seems that those references are typically hard to locate when needed.  The documentation, while good, is a little confusing because few example outputs are included.  From the documentation:

“format: Controls the level of details for the plan. It accepts four values: 

  • BASIC: Displays the minimum information in the plan—the operation ID, the operation name and its option.
  • TYPICAL: This is the default. Displays the most relevant information in the plan (operation id, name and option, #rows, #bytes and optimizer cost). Pruning, parallel and predicate information are only displayed when applicable. Excludes only PROJECTION, ALIAS and REMOTE SQL information (see below).
  • SERIAL: Like TYPICAL except that the parallel information is not displayed, even if the plan executes in parallel.
  • ALL: Maximum user level. Includes information displayed with the TYPICAL level with additional information (PROJECTION, ALIAS and information about REMOTE SQL if the operation is distributed).

Format keywords must be separated by either a comma or a space: 

  • ROWS – if relevant, shows the number of rows estimated by the optimizer
  • BYTES – if relevant, shows the number of bytes estimated by the optimizer
  • COST – if relevant, shows optimizer cost information
  • PARTITION – if relevant, shows partition pruning information
  • PARALLEL – if relevant, shows PX information (distribution method and table queue information)
  • PREDICATE – if relevant, shows the predicate section
  • PROJECTION -if relevant, shows the projection section
  • ALIAS – if relevant, shows the “Query Block Name / Object Alias” section
  • REMOTE – if relevant, shows the information for distributed query (for example, remote from serial distribution and remote SQL)
  • NOTE – if relevant, shows the note section of the explain plan
  • IOSTATS – assuming that basic plan statistics are collected when SQL statements are executed (either by using the gather_plan_statistics hint or by setting the parameter statistics_level to ALL), this format shows IO statistics for ALL (or only for the LAST as shown below) executions of the cursor.
  • MEMSTATS – Assuming that PGA memory management is enabled (that is, pga_aggregate_target parameter is set to a non 0 value), this format allows to display memory management statistics (for example, execution mode of the operator, how much memory was used, number of bytes spilled to disk, and so on). These statistics only apply to memory intensive operations like hash-joins, sort or some bitmap operators.
  • ALLSTATS – A shortcut for ‘IOSTATS MEMSTATS’
  • LAST – By default, plan statistics are shown for all executions of the cursor. The keyword LAST can be specified to see only the statistics for the last execution.

The following two formats are deprecated but supported for backward compatibility: 

  • RUNSTATS_TOT – Same as IOSTATS, that is, displays IO statistics for all executions of the specified cursor.
  • RUNSTATS_LAST – Same as IOSTATS LAST, that is, displays the runtime statistics for the last execution of the cursor

Format keywords can be prefixed by the sign ‘-’ to exclude the specified information. For example, ‘-PROJECTION’ excludes projection information.” 

This blog article will attempt to demonstrate using Oracle Database 11.2.0.1 as many of the FORMAT parameters for DBMS_XPLAN.DISPLAY_CURSOR as is possible.  We will use four test tables for the demonstration.  The test table definitions follow (warning – creating table T1 could require an hour or longer): 

CREATE TABLE T1 (
  ID NUMBER,
  DESCRIPTION VARCHAR2(80));

INSERT INTO T1
SELECT
  CEIL(ABS(SIN(ROWNUM/9.9999)*10000)),
  'This is the long description for this number '|| TO_CHAR(CEIL(ABS(SIN(ROWNUM/9.9999)*10000)))
FROM
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10000),
  (SELECT
    ROWNUM RN
  FROM
    DUAL
  CONNECT BY
    LEVEL<=10000);

CREATE INDEX IND_T1 ON T1(ID);

CREATE TABLE T2 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE TABLE T3 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE TABLE T4 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE INDEX IND_T4 ON T4(C1);

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,METHOD_OPT=>'FOR ALL COLUMNS SIZE 1')
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T3',CASCADE=>TRUE)
EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T4',CASCADE=>TRUE)

I will start by setting the STATISTICS_LEVEL parameter to ALL at the session level.  In general, this parameter should be set to TYPICAL (edit March 5, 2010: a /*+ GATHER_PLAN_STATISTICS */ hint may be used immediately after the SELECT keyword in the SQL statement to provide almost the same level of detail as would be available when setting the STATISTICS_LEVEL parameter to ALL, without as significant of a negative performance impact – see the Related Blog Articles links below for examples that use the hint).  I will also disable the output of rows to the SQL*Plus window: 

ALTER SESSION SET STATISTICS_LEVEL='ALL';
SET AUTOTRACE TRACEONLY STATISTICS

The following SQL statement is executed twice in session 1: 

SELECT /*+ PARALLEL(T1 8 ) */
  *
FROM
  T1;

Statistics
----------------------------------------------------------
         24  recursive calls
          0  db block gets
     815350  consistent gets
     813217  physical reads
          0  redo size
 5509985356  bytes sent via SQL*Net to client
    1100512  bytes received via SQL*Net from client
     100001  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
  100000000  rows processed

In session 2 we determine the SQL_ID and CHILD_NUMBER of the SQL statement that is executing in session 1: 

SELECT
  SQL_ID,
  CHILD_NUMBER
FROM
  V$SQL
WHERE
  SQL_TEXT LIKE 'SELECT /*+ PARALLEL(T1 8 ) */%';

SQL_ID        CHILD_NUMBER
------------- ------------
6kd5fkqdjb8fu            0

BASIC Format Parameter Value:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'BASIC'));

EXPLAINED SQL STATEMENT:
------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1

Plan hash value: 2494645258

-----------------------------------------
| Id  | Operation            | Name     |
-----------------------------------------
|   0 | SELECT STATEMENT     |          |
|   1 |  PX COORDINATOR      |          |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |
|   3 |    PX BLOCK ITERATOR |          |
|   4 |     TABLE ACCESS FULL| T1       |
-----------------------------------------

SERIAL Format Parameter Value:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'SERIAL'));

SQL_ID  6kd5fkqdjb8fu, child number 0
-------------------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1

Plan hash value: 2494645258

---------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |       |       | 30907 (100)|          |
|   1 |  PX COORDINATOR      |          |       |       |            |          |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |   100M|  5149M| 30907   (1)| 00:06:11 |
|   3 |    PX BLOCK ITERATOR |          |   100M|  5149M| 30907   (1)| 00:06:11 |
|*  4 |     TABLE ACCESS FULL| T1       |   100M|  5149M| 30907   (1)| 00:06:11 |
---------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
 4 - access(:Z>=:Z AND :Z<=:Z

TYPICAL Format Parameter Value:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'TYPICAL'));

SQL_ID  6kd5fkqdjb8fu, child number 0
-------------------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1

Plan hash value: 2494645258

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)|  Time    |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |       |       | 30907 (100)|          |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
 4 - access(:Z>=:Z AND :Z<=:Z)

ALL Format Parameter Value

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'ALL'));

SQL_ID  6kd5fkqdjb8fu, child number 0
-------------------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1

Plan hash value: 2494645258

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)|   Time   |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |       |       | 30907 (100)|          |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       |   100M|  5149M| 30907   (1)| 00:06:11 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1
   4 - SEL$1 / T1@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access(:Z>=:Z AND :Z<=:Z)

Column Projection Information (identified by operation id):
-----------------------------------------------------------
   1 - "T1"."ID"[NUMBER,22], "T1"."DESCRIPTION"[VARCHAR2,80]
   2 - (#keys=0) "T1"."ID"[NUMBER,22], "T1"."DESCRIPTION"[VARCHAR2,80]
   3 - "T1"."ID"[NUMBER,22], "T1"."DESCRIPTION"[VARCHAR2,80]
   4 - "T1"."ID"[NUMBER,22], "T1"."DESCRIPTION"[VARCHAR2,80]

ALLSTATS Format Parameter Value

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'ALLSTATS'));

SQL_ID  6kd5fkqdjb8fu, child number 0
-------------------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1
Plan hash value: 2494645258
----------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |      2 |        |    200M|00:00:47.47 |      52 |     12 |
|   1 |  PX COORDINATOR      |          |      2 |        |    200M|00:00:47.47 |      52 |     12 |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |      0 |    100M|      0 |00:00:00.01 |       0 |      0 |
|   3 |    PX BLOCK ITERATOR |          |     16 |    100M|    200M|00:01:56.71 |    1630K|   1626K|
|*  4 |     TABLE ACCESS FULL| T1       |    248 |    100M|    200M|00:00:53.14 |    1528K|   1524K|
----------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
4 - access(:Z>=:Z AND :Z<=:Z)

ALLSTATS LAST Format Parameter Value

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('6kd5fkqdjb8fu',0,'ALLSTATS LAST'));

SQL_ID  6kd5fkqdjb8fu, child number 0
-------------------------------------
SELECT /*+ PARALLEL(T1 8 ) */   * FROM   T1

Plan hash value: 2494645258

-------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |      1 |        |    100M|00:00:23.61 |      25 |
|   1 |  PX COORDINATOR      |          |      1 |        |    100M|00:00:23.61 |      25 |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 |      0 |    100M|      0 |00:00:00.01 |       0 |
|   3 |    PX BLOCK ITERATOR |          |      0 |    100M|      0 |00:00:00.01 |       0 |
|*  4 |     TABLE ACCESS FULL| T1       |      0 |    100M|      0 |00:00:00.01 |       0 |
-------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
 4 - access(:Z>=:Z AND :Z<=:Z)

Next SQL Statement Executed in Session 1:

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=100

SELECT
  *
FROM
  T2,
  T4
WHERE
  T2.C1 BETWEEN :N1 AND :N2
  AND T2.C1=T4.C1;

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

In session 2 we determine the SQL_ID and CHILD_NUMBER of the SQL statement that is executing in session 1: 

SELECT
  SQL_ID,
  CHILD_NUMBER
FROM
  V$SQL
WHERE
  SQL_TEXT LIKE 'SELECT%T2.C1 BETWEEN :N1 AND :N2%'
  AND SQL_TEXT NOT LIKE '%V$SQL%';

SQL_ID        CHILD_NUMBER
------------- ------------
75chksrfa5fbt            0

Starting Point, Viewing the Last Execution Statistics:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('75chksrfa5fbt',0,'ALLSTATS LAST'));

SQL_ID  75chksrfa5fbt, child number 0
-------------------------------------
SELECT   * FROM   T2,   T4 WHERE   T2.C1 BETWEEN :N1 AND :N2   AND
T2.C1=T4.C1

Plan hash value: 3771400634

-----------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name   | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |        |      1 |        |    100 |00:00:00.03 |     171 |     29 |
|*  1 |  FILTER                       |        |      1 |        |    100 |00:00:00.03 |     171 |     29 |
|   2 |   NESTED LOOPS                |        |      1 |        |    100 |00:00:00.03 |     171 |     29 |
|   3 |    NESTED LOOPS               |        |      1 |      2 |    100 |00:00:00.02 |     168 |     21 |
|*  4 |     TABLE ACCESS FULL         | T2     |      1 |      2 |    100 |00:00:00.01 |     159 |     13 |
|*  5 |     INDEX RANGE SCAN          | IND_T4 |    100 |      1 |    100 |00:00:00.01 |       9 |      8 |
|   6 |    TABLE ACCESS BY INDEX ROWID| T4     |    100 |      1 |    100 |00:00:00.01 |       3 |      8 |
-----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   4 - filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))
   5 - access("T2"."C1"="T4"."C1")
       filter(("T4"."C1"<=:N2 AND "T4"."C1">=:N1))

Note
-----
   - dynamic sampling used for this statement (level=2)

Enabling Extra Output:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('75chksrfa5fbt',0,'ALLSTATS LAST +PEEKED_BINDS +PROJECTION +ALIAS +PREDICATE +COST +BYTES'));

SQL_ID  75chksrfa5fbt, child number 0
-------------------------------------
SELECT   * FROM   T2,   T4 WHERE   T2.C1 BETWEEN :N1 AND :N2   AND  T2.C1=T4.C1

Plan hash value: 3771400634

--------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name   | Starts | E-Rows |E-Bytes| Cost(%CPU) | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |        |      1 |        |       |    51 (100)|    100 |00:00:00.03 |     171 |     29 |
|*  1 |  FILTER                       |        |      1 |        |       |            |    100 |00:00:00.03 |     171 |     29 |
|   2 |   NESTED LOOPS                |        |      1 |        |       |            |    100 |00:00:00.03 |     171 |     29 |
|   3 |    NESTED LOOPS               |        |      1 |      2 |   340 |    51   (0)|    100 |00:00:00.02 |     168 |     21 |
|*  4 |     TABLE ACCESS FULL         | T2     |      1 |      2 |   130 |    47   (0)|    100 |00:00:00.01 |     159 |     13 |
|*  5 |     INDEX RANGE SCAN          | IND_T4 |    100 |      1 |       |     1   (0)|    100 |00:00:00.01 |       9 |      8 |
|   6 |    TABLE ACCESS BY INDEX ROWID| T4     |    100 |      1 |   105 |     2   (0)|    100 |00:00:00.01 |       3 |      8 |
--------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
   1 - SEL$1
   4 - SEL$1 / T2@SEL$1
   5 - SEL$1 / T4@SEL$1
   6 - SEL$1 / T4@SEL$1

Peeked Binds (identified by position):
--------------------------------------
   1 - (NUMBER): 1
   2 - (NUMBER): 100

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   4 - filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))
   5 - access("T2"."C1"="T4"."C1")
       filter(("T4"."C1"<=:N2 AND "T4"."C1">=:N1))

Column Projection Information (identified by operation id):
-----------------------------------------------------------
   1 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,100], "T4"."C1"[NUMBER,22], "T4"."C2"[VARCHAR2,100]
   2 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,100], "T4"."C1"[NUMBER,22], "T4"."C2"[VARCHAR2,100]
   3 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,100], "T4".ROWID[ROWID,10], "T4"."C1"[NUMBER,22]
   4 - "T2"."C1"[NUMBER,22], "T2"."C2"[VARCHAR2,100]
   5 - "T4".ROWID[ROWID,10], "T4"."C1"[NUMBER,22]
   6 - "T4"."C2"[VARCHAR2,100]

Note
-----
   - dynamic sampling used for this statement (level=2)

Removing Output Sections:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('75chksrfa5fbt',0,'ALLSTATS LAST -NOTE -ROWS -PREDICATE'));

SQL_ID  75chksrfa5fbt, child number 0
-------------------------------------
SELECT   * FROM   T2,   T4 WHERE   T2.C1 BETWEEN :N1 AND :N2   AND
T2.C1=T4.C1

Plan hash value: 3771400634

--------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name   | Starts | A-Rows |   A-Time   | Buffers | Reads  |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |        |      1 |    100 |00:00:00.03 |     171 |     29 |
|   1 |  FILTER                       |        |      1 |    100 |00:00:00.03 |     171 |     29 |
|   2 |   NESTED LOOPS                |        |      1 |    100 |00:00:00.03 |     171 |     29 |
|   3 |    NESTED LOOPS               |        |      1 |    100 |00:00:00.02 |     168 |     21 |
|   4 |     TABLE ACCESS FULL         | T2     |      1 |    100 |00:00:00.01 |     159 |     13 |
|   5 |     INDEX RANGE SCAN          | IND_T4 |    100 |    100 |00:00:00.01 |       9 |      8 |
|   6 |    TABLE ACCESS BY INDEX ROWID| T4     |    100 |    100 |00:00:00.01 |       3 |      8 |
--------------------------------------------------------------------------------------------------

A More Complicated Example

The previous examples were too simple, so let’s look at something that is a bit more interesting.  We will introduce partitioning, parallel execution, and remote databases.  First, let’s create a larger version of table T3 with 1,000,000 rows rather than 10,000 rows: 

DROP TABLE T3 PURGE;

CREATE TABLE T3
  PARTITION BY RANGE(C1)
   (PARTITION P1 VALUES LESS THAN (5),
    PARTITION P2 VALUES LESS THAN (10),
    PARTITION P3 VALUES LESS THAN (20),
    PARTITION P4 VALUES LESS THAN (40),
    PARTITION P5 VALUES LESS THAN (80),
    PARTITION P6 VALUES LESS THAN (160),
    PARTITION P7 VALUES LESS THAN (320),
    PARTITION P8 VALUES LESS THAN (640),
    PARTITION P9 VALUES LESS THAN (1280),
    PARTITION P10 VALUES LESS THAN (2560),
    PARTITION P11 VALUES LESS THAN (5120),
    PARTITION P12 VALUES LESS THAN (10240),
    PARTITION P20 VALUES LESS THAN (MAXVALUE))
AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

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

Now let’s connect to the database in another session as the SYS user and create a database link to an Oracle 11.1.0.6 database (global names are not used in the database, otherwise we would would need a specific name for the database link, as mentioned here), and then flush the buffer cache: 

CREATE PUBLIC DATABASE LINK TEST_LINK CONNECT TO TESTUSER IDENTIFIED BY MY_PASS_HERE USING 'o11106';

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

In the remote 11.1.0.6 database, the TESTUSER creates the following tables, and then the SYS user flushes the buffer cache: 

CREATE TABLE T3 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE TABLE T4 AS
SELECT
  ROWNUM C1,
  LPAD('A',100,'A') C2
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

CREATE INDEX IND_T4 ON T4(C1);

COMMIT;

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

ALTER SYSTEM FLUSH BUFFER_CACHE;
ALTER SYSTEM FLUSH BUFFER_CACHE;

Back in the 11.2.0.1 database as our test user, we create a SQL statement to access table T1, T2, T3, T4, and the remote tables T3 and T4: 

VARIABLE N1 NUMBER
VARIABLE N2 NUMBER
EXEC :N1:=1
EXEC :N2:=200
ALTER SESSION SET STATISTICS_LEVEL='ALL';
SET AUTOTRACE TRACEONLY STATISTICS

SELECT /*+ PARALLEL(8) */
  T2.C1 T2_C1,
  SUBSTR(T2.C2,1,10) T2_C2,
  T3.C1 T3_C1,
  SUBSTR(T3.C2,1,10) T3_C2,
  T4.C1 T4_C1,
  SUBSTR(T4.C2,1,10) T4_C2,
  TL_T3.C1 TL_T3_C1,
  SUBSTR(TL_T3.C2,1,10) TL_T3_C2,
  TL_T4.C1 TL_T4_C1,
  SUBSTR(TL_T4.C2,1,10) TL_T4_C2,
  V_T1.C
FROM
  T2,
  T3,
  T4,
  T3@TEST_LINK TL_T3,
  T4@TEST_LINK TL_T4,
  (SELECT
    ID,
    COUNT(*) C
  FROM
    T1
  GROUP BY
    ID) V_T1
WHERE
  T2.C1 BETWEEN :N1 AND :N2
  AND T2.C1=T3.C1
  AND T2.C1=T4.C1
  AND T2.C1=TL_T3.C1
  AND T2.C1=TL_T4.C1
  AND T2.C1=V_T1.ID(+)
ORDER BY
  T2.C1;

Statistics
----------------------------------------------------------
       2855  recursive calls
         12  db block gets
       3979  consistent gets
       2893  physical reads
       1324  redo size
       9145  bytes sent via SQL*Net to client
        667  bytes received via SQL*Net from client
         15  SQL*Net roundtrips to/from client
         95  sorts (memory)
          0  sorts (disk)
        200  rows processed

Now let’s check the execution plan: 

SET AUTOTRACE OFF

SELECT
  SQL_ID,
  CHILD_NUMBER
FROM
  V$SQL
WHERE
  SQL_TEXT LIKE '%T3@TEST_LINK TL_T3,%'
  AND SQL_TEXT NOT LIKE '%V$SQL%';

SQL_ID        CHILD_NUMBER
------------- ------------
dkmcbpadz15w1            0
dkmcbpadz15w1            1

Interesting, two child cursors.  Let’s see the execution plans: 

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR('dkmcbpadz15w1',NULL,'ALLSTATS LAST'));

SQL_ID  dkmcbpadz15w1, child number 0
-------------------------------------
SELECT /*+ PARALLEL(8) */   T2.C1 T2_C1,   SUBSTR(T2.C2,1,10) T2_C2,
T3.C1 T3_C1,   SUBSTR(T3.C2,1,10) T3_C2,   T4.C1 T4_C1,
SUBSTR(T4.C2,1,10) T4_C2,   TL_T3.C1 TL_T3_C1,   SUBSTR(TL_T3.C2,1,10)
TL_T3_C2,   TL_T4.C1 TL_T4_C1,   SUBSTR(TL_T4.C2,1,10) TL_T4_C2,
V_T1.C FROM   T2,   T3,   T4,   T3@TEST_LINK TL_T3,   T4@TEST_LINK
TL_T4,   (SELECT     ID,     COUNT(*) C   FROM     T1   GROUP BY
ID) V_T1 WHERE   T2.C1 BETWEEN :N1 AND :N2   AND T2.C1=T3.C1   AND
T2.C1=T4.C1   AND T2.C1=TL_T3.C1   AND T2.C1=TL_T4.C1   AND
T2.C1=V_T1.ID(+) ORDER BY   T2.C1

Plan hash value: 453902047

---------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                      | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                               |          |      1 |        |    200 |00:00:02.49 |    2609 |   2655 |       |       |          |
|*  1 |  PX COORDINATOR                                |          |      1 |        |    200 |00:00:02.49 |    2609 |   2655 |       |       |          |
|   2 |   PX SEND QC (ORDER)                           | :TQ10008 |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   3 |    SORT ORDER BY                               |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 | 73728 | 73728 |          |
|   4 |     PX RECEIVE                                 |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   5 |      PX SEND RANGE                             | :TQ10007 |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|*  6 |       FILTER                                   |          |      0 |        |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|*  7 |        HASH JOIN OUTER                         |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |   697K|   697K|          |
|   8 |         PX RECEIVE                             |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|   9 |          PX SEND HASH                          | :TQ10006 |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|* 10 |           HASH JOIN                            |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |   705K|   705K|          |
|  11 |            PART JOIN FILTER CREATE             | :BF0000  |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  12 |             PX RECEIVE                         |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  13 |              PX SEND BROADCAST                 | :TQ10005 |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|* 14 |               HASH JOIN                        |          |      0 |     17 |      0 |00:00:00.01 |       0 |      0 |   713K|   713K|          |
|* 15 |                HASH JOIN                       |          |      0 |     21 |      0 |00:00:00.01 |       0 |      0 |   727K|   727K|          |
|* 16 |                 HASH JOIN                      |          |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |   757K|   757K|          |
|  17 |                  BUFFER SORT                   |          |      0 |        |      0 |00:00:00.01 |       0 |      0 | 73728 | 73728 |          |
|  18 |                   PX RECEIVE                   |          |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  19 |                    PX SEND HASH                | :TQ10000 |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  20 |                     TABLE ACCESS BY INDEX ROWID| T4       |      1 |     25 |    200 |00:00:00.02 |       6 |     16 |       |       |          |
|* 21 |                      INDEX RANGE SCAN          | IND_T4   |      1 |     45 |    200 |00:00:00.01 |       2 |      8 |       |       |          |
|  22 |                  PX RECEIVE                    |          |      0 |     30 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  23 |                   PX SEND HASH                 | :TQ10004 |      0 |     30 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  24 |                    PX BLOCK ITERATOR           |          |      0 |     30 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|* 25 |                     TABLE ACCESS FULL          | T2       |      0 |     30 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  26 |                 BUFFER SORT                    |          |      0 |        |      0 |00:00:00.01 |       0 |      0 | 73728 | 73728 |          |
|  27 |                  PX RECEIVE                    |          |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  28 |                   PX SEND HASH                 | :TQ10001 |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  29 |                    REMOTE                      | T3       |      1 |     25 |    200 |00:00:00.09 |       0 |      0 |       |       |          |
|  30 |                BUFFER SORT                     |          |      0 |        |      0 |00:00:00.01 |       0 |      0 | 73728 | 73728 |          |
|  31 |                 PX RECEIVE                     |          |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  32 |                  PX SEND HASH                  | :TQ10002 |      0 |     25 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  33 |                   REMOTE                       | T4       |      1 |     25 |    200 |00:00:00.01 |       0 |      0 |       |       |          |
|  34 |            PX BLOCK ITERATOR                   |          |      0 |   2500 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|* 35 |             TABLE ACCESS FULL                  | T3       |      0 |   2500 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  36 |         BUFFER SORT                            |          |      0 |        |      0 |00:00:00.01 |       0 |      0 | 73728 | 73728 |          |
|  37 |          PX RECEIVE                            |          |      0 |  10000 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  38 |           PX SEND HASH                         | :TQ10003 |      0 |  10000 |      0 |00:00:00.01 |       0 |      0 |       |       |          |
|  39 |            VIEW                                |          |      1 |  10000 |    200 |00:00:01.03 |    2577 |   2632 |       |       |          |
|  40 |             HASH GROUP BY                      |          |      1 |  10000 |    200 |00:00:01.03 |    2577 |   2632 |  1115K|  1115K| 2593K (0)|
|* 41 |              FILTER                            |          |      1 |        |   1273K|00:00:00.78 |    2577 |   2632 |       |       |          |
|* 42 |               INDEX RANGE SCAN                 | IND_T1   |      1 |    250K|   1273K|00:00:00.43 |    2577 |   2632 |       |       |          |
---------------------------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   6 - filter(:N1<=:N2)
   7 - access("T2"."C1"="V_T1"."ID")
  10 - access("T2"."C1"="T3"."C1")
  14 - access("T2"."C1"="TL_T4"."C1")
  15 - access("T2"."C1"="TL_T3"."C1")
  16 - access("T2"."C1"="T4"."C1")
  21 - access("T4"."C1">=:N1 AND "T4"."C1"<=:N2)
  25 - access(:Z>=:Z AND :Z<=:Z)
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))
  35 - access(:Z>=:Z AND :Z<=:Z)
       filter(("T3"."C1">=:N1 AND "T3"."C1"<=:N2))
  41 - filter(:N1<=:N2)
  42 - access("ID">=:N1 AND "ID"<=:N2)

Note
-----
   - dynamic sampling used for this statement (level=5)
   - Degree of Parallelism is 8 because of hint

 

SQL_ID  dkmcbpadz15w1, child number 1
-------------------------------------
SELECT /*+ PARALLEL(8) */   T2.C1 T2_C1,   SUBSTR(T2.C2,1,10) T2_C2,
T3.C1 T3_C1,   SUBSTR(T3.C2,1,10) T3_C2,   T4.C1 T4_C1,
SUBSTR(T4.C2,1,10) T4_C2,   TL_T3.C1 TL_T3_C1,   SUBSTR(TL_T3.C2,1,10)
TL_T3_C2,   TL_T4.C1 TL_T4_C1,   SUBSTR(TL_T4.C2,1,10) TL_T4_C2,
V_T1.C FROM   T2,   T3,   T4,   T3@TEST_LINK TL_T3,   T4@TEST_LINK
TL_T4,   (SELECT     ID,     COUNT(*) C   FROM     T1   GROUP BY
ID) V_T1 WHERE   T2.C1 BETWEEN :N1 AND :N2   AND T2.C1=T3.C1   AND
T2.C1=T4.C1   AND T2.C1=TL_T3.C1   AND T2.C1=TL_T4.C1   AND
T2.C1=V_T1.ID(+) ORDER BY   T2.C1

Plan hash value: 453902047

--------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                      | Name     | Starts | E-Rows | A-Rows |   A-Time   |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                               |          |      0 |        |      0 |00:00:00.01 |       |       |          |
|*  1 |  PX COORDINATOR                                |          |      0 |        |      0 |00:00:00.01 |       |       |          |
|   2 |   PX SEND QC (ORDER)                           | :TQ10008 |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|   3 |    SORT ORDER BY                               |          |      0 |     17 |      0 |00:00:00.01 | 36864 | 36864 | 4096  (0)|
|   4 |     PX RECEIVE                                 |          |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|   5 |      PX SEND RANGE                             | :TQ10007 |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|*  6 |       FILTER                                   |          |      1 |        |     25 |00:00:01.03 |       |       |          |
|*  7 |        HASH JOIN OUTER                         |          |      1 |     17 |     25 |00:00:01.03 |   693K|   693K| 1286K (0)|
|   8 |         PX RECEIVE                             |          |      1 |     17 |     25 |00:00:00.01 |       |       |          |
|   9 |          PX SEND HASH                          | :TQ10006 |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|* 10 |           HASH JOIN                            |          |      0 |     17 |      0 |00:00:00.01 |  1278K|   930K| 1260K (0)|
|  11 |            PART JOIN FILTER CREATE             | :BF0000  |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|  12 |             PX RECEIVE                         |          |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|  13 |              PX SEND BROADCAST                 | :TQ10005 |      0 |     17 |      0 |00:00:00.01 |       |       |          |
|* 14 |               HASH JOIN                        |          |      1 |     17 |     25 |00:00:00.14 |   705K|   705K| 1139K (0)|
|* 15 |                HASH JOIN                       |          |      1 |     21 |     25 |00:00:00.12 |   720K|   720K| 1129K (0)|
|* 16 |                 HASH JOIN                      |          |      1 |     25 |     25 |00:00:00.03 |   763K|   763K| 1128K (0)|
|  17 |                  BUFFER SORT                   |          |      1 |        |     25 |00:00:00.02 |  4096 |  4096 | 4096  (0)|
|  18 |                   PX RECEIVE                   |          |      1 |     25 |     25 |00:00:00.02 |       |       |          |
|  19 |                    PX SEND HASH                | :TQ10000 |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|  20 |                     TABLE ACCESS BY INDEX ROWID| T4       |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|* 21 |                      INDEX RANGE SCAN          | IND_T4   |      0 |     45 |      0 |00:00:00.01 |       |       |          |
|  22 |                  PX RECEIVE                    |          |      1 |     30 |     25 |00:00:00.01 |       |       |          |
|  23 |                   PX SEND HASH                 | :TQ10004 |      0 |     30 |      0 |00:00:00.01 |       |       |          |
|  24 |                    PX BLOCK ITERATOR           |          |      0 |     30 |      0 |00:00:00.01 |       |       |          |
|* 25 |                     TABLE ACCESS FULL          | T2       |      0 |     30 |      0 |00:00:00.01 |       |       |          |
|  26 |                 BUFFER SORT                    |          |      1 |        |     25 |00:00:00.09 | 36864 | 36864 | 4096  (0)|
|  27 |                  PX RECEIVE                    |          |      1 |     25 |     25 |00:00:00.09 |       |       |          |
|  28 |                   PX SEND HASH                 | :TQ10001 |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|  29 |                    REMOTE                      | T3       |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|  30 |                BUFFER SORT                     |          |      1 |        |     25 |00:00:00.01 | 36864 | 36864 | 4096  (0)|
|  31 |                 PX RECEIVE                     |          |      1 |     25 |     25 |00:00:00.01 |       |       |          |
|  32 |                  PX SEND HASH                  | :TQ10002 |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|  33 |                   REMOTE                       | T4       |      0 |     25 |      0 |00:00:00.01 |       |       |          |
|  34 |            PX BLOCK ITERATOR                   |          |      0 |   2500 |      0 |00:00:00.01 |       |       |          |
|* 35 |             TABLE ACCESS FULL                  | T3       |      0 |   2500 |      0 |00:00:00.01 |       |       |          |
|  36 |         BUFFER SORT                            |          |      1 |        |     25 |00:00:01.03 | 18432 | 18432 | 2048  (0)|
|  37 |          PX RECEIVE                            |          |      1 |  10000 |     25 |00:00:01.03 |       |       |          |
|  38 |           PX SEND HASH                         | :TQ10003 |      0 |  10000 |      0 |00:00:00.01 |       |       |          |
|  39 |            VIEW                                |          |      0 |  10000 |      0 |00:00:00.01 |       |       |          |
|  40 |             HASH GROUP BY                      |          |      0 |  10000 |      0 |00:00:00.01 |    10M|  3024K|          |
|* 41 |              FILTER                            |          |      0 |        |      0 |00:00:00.01 |       |       |          |
|* 42 |               INDEX RANGE SCAN                 | IND_T1   |      0 |    250K|      0 |00:00:00.01 |       |       |          |
--------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(:N1<=:N2)
   6 - filter(:N1<=:N2)
   7 - access("T2"."C1"="V_T1"."ID")
  10 - access("T2"."C1"="T3"."C1")
  14 - access("T2"."C1"="TL_T4"."C1")
  15 - access("T2"."C1"="TL_T3"."C1")
  16 - access("T2"."C1"="T4"."C1")
  21 - access("T4"."C1">=:N1 AND "T4"."C1"<=:N2)
  25 - access(:Z>=:Z AND :Z<=:Z)
       filter(("T2"."C1">=:N1 AND "T2"."C1"<=:N2))
  35 - access(:Z>=:Z AND :Z<=:Z)
       filter(("T3"."C1">=:N1 AND "T3"."C1"<=:N2))
  41 - filter(:N1<=:N2)
  42 - access("ID">=:N1 AND "ID"<=:N2)

Note
-----
   - dynamic sampling used for this statement (level=5)
   - automatic DOP: Computed Degree of Parallelism is 8

There are a couple of interesting items that you might notice, maybe someone can explain why: 

  • The execution plan for the first child cursor shows on line ID 25 that 0 rows were retrieved from table T2, yet the execution plan shows that 200 rows were retrieved.
  • SHOW PARAMETER OPTIMIZER_DYNAMIC_SAMPLING shows that dynamic sampling is set to 2, yet the Note section of the execution plans show that dynamic sampling at level 5 was performed (statistics were not collected for table T2).
  • The Note section of the first child cursor shows that the degree of parallelism is 8 because of a hint, while the Note section of the second child cursor shows that the degree of parallelism was automatically computed as 8.
  • What was the purpose of the second child cursor?  No rows were returned, yet some lines in that plan show that 25 rows were retrieved.
  • Did I miss something?

Adding and Removing Items from the DBMS_XPLAN Output

The following execution plan was created by specifying the format parameters displayed in the blue box.  The yellow boxes indicate where those items appear in the execution plan, and how to remove other items that appear by default when the ALLSTATS LAST format parameter is provided. 

Related Blog Articles:
Automated DBMS_XPLAN, Trace, and Send to Excel
Execution Plans – What is the Plan, and Where Do I Find It?
Execution Plans – What is the Plan, and Where Do I Find It 2
Execution Plans – What is the Plan, and Where Do I Find It 3
Parallel Reasoning





Reviewing Session-Level Parameters

25 02 2010

February 25, 2010

A couple of days ago I received an email from a friend who manages a database (10.2.0.4) that is used by the same ERP platform as is used where I work.  The email was quite friendly until I saw the attached file, which included a rather unfriendly ORA-07445 error message and stack trace:

ksedmp: internal or fatal error
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [_intel_fast_memcpy.A+18] [PC:0x33CFC0E] [ADDR:0x39D10000] [UNABLE_TO_READ] []
Current SQL statement for this session:
update my_table set
costed_date = SYSDATE
where type = 'W'
and base_id = :1       
and lot_id = :2      
and split_id = :3        
and sub_id = '0' 

----- Call Stack Trace -----
calling              call     entry                argument values in hex     
location             type     point                (? means dubious value)    
-------------------- -------- -------------------- ----------------------------
_intel_fast_memcpy.           0000000000000000     000000000 000000000 000000000
A+18                                               000000000
0000000000000001     CALL???  _intel_fast_memcpy.  110F0E2E0 00118F111 0F7714C60
                              A+18                 1160CE740
0000000110F0E2E0     CALL???  0000000000000001     00118F111 0F7714C60 1160CE740
                                                   000000004
updgrh+3747          CALL???  0000000110F0E2E0     0F7714C60 1160CE740 000000004
                                                   000000000
__PGOSF480_upduaw+1  CALL???  updgrh+3747          11DEAD460 00001E768 000000000
58                                                 ACD6D33AF808
kdusru+540           CALL???  __PGOSF480_upduaw+1  00001E658 000000002 00001F2E0
                              58                   00001F430
kauupd+521           CALL???  kdusru+540           110F0DBC0 023037F78 000000000
                                                   000000000
updrow+2086          CALL???  kauupd+521           039CDBA10 110F0DA48 039D0E000
                                                   100000000
__PGOSF536_qerupRow  CALL???  updrow+2086          110E03438 000007FFF 002E4644C
Procedure+93                                       00001F430
qerupFetch+748       CALL???  __PGOSF536_qerupRow  0EB37C530 000000000 000000000
                              Procedure+93         100000000
...

No wonder it crashed with an ORA-07445 Access Violation error – look at the first argument of the __PGOSF480_upduaw+158 calling location - it must be that fatal errors appear in Oracle whenever the hexadecimal number DEAD appears in the middle of an argument. :-)  (Watch out for false correlation when troubleshooting.)  In case you are wondering, Metalink Doc ID 175982.1 “ORA-600 Lookup Error Categories” does not describe the updgrh function that eventually lead to the crash in the _intel_fast_memcpy.A+18 calling location, but there are a couple of articles on Metalink that describe updgrh as a function that is involved in updates to migrated rows.

As an experiment, a logon trigger like the following was created (caution, this logon trigger changes a “hidden” Oracle parameter to disable bind variable peeking – exercise caution, and check with Oracle support, before changing any hidden parameters):

CREATE OR REPLACE TRIGGER "SYS"."NO_PEEK_BIND" AFTER LOGON ON DATABASE
DECLARE
  SHOULD_EXECUTE INTEGER;
BEGIN
  SELECT DECODE(SUBSTR(UPPER(PROGRAM),1,8),'AAAAAAAA',1,0)+DECODE(INSTR(PROGRAM,'\',-1),0,0,DECODE(SUBSTR(UPPER(SUBSTR(PROGRAM,INSTR(PROGRAM,'\',-1)+1)),1,8),'AAAAAAAA',1,0)) INTO SHOULD_EXECUTE FROM V$SESSION WHERE SID=(SELECT SID FROM V$MYSTAT WHERE ROWNUM=1);
  IF SHOULD_EXECUTE > 0 THEN
    EXECUTE IMMEDIATE 'ALTER SESSION SET "_optim_peek_user_binds"=FALSE';
  END IF;
END;
/

The above logon trigger disables bind variable peeking for any program with AAAAAAAA at the start of its filename, even if a portion of the program’s file path (assuming that the path directories are separated by backslashes) is included in the PROGRAM column of V$SESSION.  Once in place, this logon trigger changes the parsing environment for the session such that any previously hard parsed SQL statements that were used by the program in the past would need to be re-hard parsed when executed by the program.  Looking through the remainder of the trace file I noticed that a lot of the bind variables were not set to a value (No bind buffers allocated appeared in the trace file) during the first parse call by the session, so peeking at the bind variables could potentially cause problems if that special case is not handled correctly by Oracle Database 10.2.0.4.  (The stack trace did not suggest that bind variable peeking was the cause of the problem.)

Once the trigger was in place, and new sessions have connected, were are able to confirm that the session-level parameter modification happened with the following SQL statement:

SELECT
  S.SID,
  SUBSTR(S.PROGRAM,1,8) PROGRAM,
  SOE.NAME,
  SOE.VALUE,
  SOE.ISDEFAULT
FROM
  V$SESSION S,
  V$SES_OPTIMIZER_ENV SOE
WHERE
  SUBSTR(UPPER(S.PROGRAM),1,8) IN ('AAAAAAAA','BBBBBBBB')
  AND S.SID=SOE.SID
ORDER BY
  NAME,
  PROGRAM;

 SID PROGRAM  NAME                                 VALUE                     ISD
---- -------- ------------------------------------ ------------------------- ---
 303 AAAAAAAA _optim_peek_user_binds               false                     NO
 303 AAAAAAAA _optimizer_adaptive_cursor_sharing   false                     NO
 335 BBBBBBBB _optimizer_adaptive_cursor_sharing   false                     NO
 303 AAAAAAAA active_instance_count                1                         YES
 335 BBBBBBBB active_instance_count                1                         YES
 303 AAAAAAAA bitmap_merge_area_size               1048576                   YES
 335 BBBBBBBB bitmap_merge_area_size               1048576                   YES
 303 AAAAAAAA cell_offload_compaction              ADAPTIVE                  YES
 335 BBBBBBBB cell_offload_compaction              ADAPTIVE                  YES
 303 AAAAAAAA cell_offload_plan_display            AUTO                      YES
 335 BBBBBBBB cell_offload_plan_display            AUTO                      YES
 303 AAAAAAAA cell_offload_processing              true                      YES
 335 BBBBBBBB cell_offload_processing              true                      YES
 303 AAAAAAAA cpu_count                            2                         YES
 335 BBBBBBBB cpu_count                            2                         YES
 303 AAAAAAAA cursor_sharing                       exact                     YES
 335 BBBBBBBB cursor_sharing                       exact                     YES
 303 AAAAAAAA db_file_multiblock_read_count        32                        YES
 335 BBBBBBBB db_file_multiblock_read_count        32                        YES
 303 AAAAAAAA hash_area_size                       131072                    YES
 335 BBBBBBBB hash_area_size                       131072                    YES
 303 AAAAAAAA is_recur_flags                       0                         YES
 335 BBBBBBBB is_recur_flags                       0                         YES
 303 AAAAAAAA optimizer_capture_sql_plan_baselines false                     YES
 335 BBBBBBBB optimizer_capture_sql_plan_baselines false                     YES
 303 AAAAAAAA optimizer_dynamic_sampling           2                         YES
 335 BBBBBBBB optimizer_dynamic_sampling           2                         YES
 303 AAAAAAAA optimizer_features_enable            11.1.0.7                  YES
 335 BBBBBBBB optimizer_features_enable            11.1.0.7                  YES
 303 AAAAAAAA optimizer_index_caching              0                         YES
 335 BBBBBBBB optimizer_index_caching              0                         YES
 303 AAAAAAAA optimizer_index_cost_adj             100                       YES
 335 BBBBBBBB optimizer_index_cost_adj             100                       YES
 303 AAAAAAAA optimizer_mode                       all_rows                  YES
 335 BBBBBBBB optimizer_mode                       all_rows                  YES
 303 AAAAAAAA optimizer_secure_view_merging        true                      YES
 335 BBBBBBBB optimizer_secure_view_merging        true                      YES
 303 AAAAAAAA optimizer_use_invisible_indexes      false                     YES
 335 BBBBBBBB optimizer_use_invisible_indexes      false                     YES
 303 AAAAAAAA optimizer_use_pending_statistics     false                     YES
 335 BBBBBBBB optimizer_use_pending_statistics     false                     YES
 303 AAAAAAAA optimizer_use_sql_plan_baselines     true                      YES
 335 BBBBBBBB optimizer_use_sql_plan_baselines     true                      YES
 303 AAAAAAAA parallel_ddl_mode                    enabled                   YES
 335 BBBBBBBB parallel_ddl_mode                    enabled                   YES
 303 AAAAAAAA parallel_degree                      0                         YES
 335 BBBBBBBB parallel_degree                      0                         YES
 303 AAAAAAAA parallel_dml_mode                    disabled                  YES
 335 BBBBBBBB parallel_dml_mode                    disabled                  YES
 303 AAAAAAAA parallel_execution_enabled           false                     YES
 335 BBBBBBBB parallel_execution_enabled           false                     YES
 303 AAAAAAAA parallel_query_default_dop           0                         YES
 335 BBBBBBBB parallel_query_default_dop           0                         YES
 303 AAAAAAAA parallel_query_mode                  enabled                   YES
 335 BBBBBBBB parallel_query_mode                  enabled                   YES
 303 AAAAAAAA parallel_threads_per_cpu             2                         YES
 335 BBBBBBBB parallel_threads_per_cpu             2                         YES
 303 AAAAAAAA pga_aggregate_target                 143360 KB                 YES
 335 BBBBBBBB pga_aggregate_target                 143360 KB                 YES
 303 AAAAAAAA query_rewrite_enabled                true                      YES
 335 BBBBBBBB query_rewrite_enabled                true                      YES
 303 AAAAAAAA query_rewrite_integrity              enforced                  YES
 335 BBBBBBBB query_rewrite_integrity              enforced                  YES
 303 AAAAAAAA result_cache_mode                    MANUAL                    YES
 335 BBBBBBBB result_cache_mode                    MANUAL                    YES
 303 AAAAAAAA skip_unusable_indexes                true                      YES
 335 BBBBBBBB skip_unusable_indexes                true                      YES
 303 AAAAAAAA sort_area_retained_size              0                         YES
 335 BBBBBBBB sort_area_retained_size              0                         YES
 303 AAAAAAAA sort_area_size                       65536                     YES
 335 BBBBBBBB sort_area_size                       65536                     YES
 303 AAAAAAAA star_transformation_enabled          false                     YES
 335 BBBBBBBB star_transformation_enabled          false                     YES
 303 AAAAAAAA statistics_level                     typical                   YES
 335 BBBBBBBB statistics_level                     typical                   YES
 303 AAAAAAAA transaction_isolation_level          read_commited             YES
 335 BBBBBBBB transaction_isolation_level          read_commited             YES
 303 AAAAAAAA workarea_size_policy                 auto                      YES
 335 BBBBBBBB workarea_size_policy                 auto                      YES

The above output is obviously not from the 10.2.0.4 database.  As can be determined by the above, the _OPTIM_PEEK_USER_BINDS parameter is set to FALSE only for the program AAAAAAAA.  If you look closely at the output, you will also notice that the _OPTIMIZER_ADAPTIVE_CURSOR_SHARING parameter is set to the non-default value of FALSE for both sessions (this change was made in the spfile), and it would be a logical next step to determine why that hidden parameter was changed from the default.

Did changing the behavior of bind variable peeking solve the ORA-07445 Access Violation error?  Well, that question is off topic for this blog article – the ORA-07445 is just one reason why it might be necessary to explore the parameters that were modified at the session-level.  V$SES_OPTIMIZER_ENV shows the parameters that were modified from the Oracle defaults (check the ISDEFAULT column) at the session-level, and those values may be compared with the system-wide defaults found in the V$SYS_OPTIMIZER_ENV view.  A previous blog article described the V$SQL_OPTIMIZER_ENV view, which shows the parameters that were in effect when a specific child cursor was initially hard parsed.





Eliminating 2 Wait Events from the Top 5, How Many Remain?

24 02 2010

February 24, 2010

A recent question on the OTN forums forced me to stop and think for a moment.  If you eliminate two of the most commonly found wait events from the top five wait events:

  • How many wait events will appear in the top five wait events for a selected time period (hint - something has to appear in the top five)?
  • When the two most commonly found wait events are eliminated from the top five, does that necessarily mean that the database performance is better, or could the performance be worse?

The question from the OTN forum is as follows:

I have a query regarding the 2 events:
1. db file scattered read
2. db file sequential read

If the above two events are in top 5 events then what could be the reason for this and how to resolve the issue?

The question asked is a good question, but something is missing.  Similar questions have appeared on various forums in the past, so this blog article is not specifically addressed to this particular OTN posting.  The original poster excluded a couple of potentially useful pieces of information:

  • What Oracle release and operating system platform is in use?
  • How many seconds of wait time were reported in each of the wait events?
  • What was the total duration of the statistics collection period?
  • Were there any other, potentially more significant wait events in the top five list?
  • How many users were connected to the database?
  • What was the average wait duration for each of the events, and how many waits?
  • Were any business critical processes operating at a slower than expected speed?

There will always be five wait events in a top 5 list, so if the original poster was able to somehow eliminate those datafile type access waits events from the top 5 list, which wait events should take the place of the db file scattered read and db file sequential read waits?  Would it be better to see a different set of wait events, maybe pipe get and inactive session followed closely by cleanup of aborted processes? (I think that there might be a play on words and their definitions here – SHUTDOWN IMMEDIATE; is one certain way to decrease the frequency of datafile type access waits.)





Retrieving the Hidden Oracle Parameters and Saving the Parameter Values in Excel

23 02 2010

February 23, 2010

The are a large number of initialization parameters that configure the behavior of an Oracle database instance, and it seems that the number of hidden parameters (those parameters that begin with _ ) continues to grow with each new Oracle Database release.  In some cases, parameters that were once normal parameters became hidden parameters in later releases (the SPIN_COUNT, and _SPIN_COUNT parameters are one example).  In other cases, the normal parameter defines the minimum requested parameter value and the hidden parameter defines the current value (DB_CACHE_SIZE and __DB_CACHE_SIZE parameters, respectively).

For documentation purposes it might be helpful to permanently record the values of the normal and hidden initialization parameters, and that is the purpose of the VBS script in this article.  The script uses a SQL statement that was originally found here, and then was modified so that the normal and hidden versions of the parameters will sort into adjacent rows when dislayed on screen.  Once the parameter values are written to Excel, the Excel worksheet is automatically saved with the value of the DB_NAME initialization parameter and the current date and time.  When targeting an 11.2.0.1 database, the output might look like the following screen capture:

Unfortunately, we have a slight problem.  The SQL statement in the script must be executed as the SYS user, and if the O7_DICTIONARY_ACCESSIBILITY initialization parameter is set to FALSE (the default starting with Oracle 9.0.1), the normal connection string used in previous scripts will not work (I have not found a way to pass AS SYSDBA when Provider=OraOLEDB.Oracle is specified in the connection string).  If you do not want to set the O7_DICTIONARY_ACCESSIBILITY initialization parameter to TRUE, you will need to create an ODBC connection to the database.

To create an ODBC connection, launch the ODBC Data Source Administrator utility from the Control Panel, and switch to the System DSN tab.  Click Add… then select one of the ODBC providers offered by Oracle Corp (you may need to perform a custom install of the Oracle Client for Oracle’s ODBC client to appear in the list – note that there is a separate 32 bit and 64 bit ODBC Administrator on 64 bit Windows, with the 32 bit version located in the Windows\SysWow64 folder, see this article for more information):

Pick a generic name for the ODBC connection, such as MyODBC (this is the name used in the script) and then enter the database name from the Tnsnames.ora file into the TNS Service Name box (I specified or112) – note that you can change this database name at a later time to point the script at a different database.  Click OK.

The VBS script to extract the normal and hidden parameters follows (modify the script to specify the correct password for the SYS user):

'Version 1.0

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

Dim strUsername
Dim strPassword
Dim strDatabase
Dim strSQL                          'SQL statement
Dim objExcel                        'For sending the output to Excel

Dim snpData                         'ADO Recordset object used to retrieve the user's data
Dim dbDatabase                      'ADO database connection object

Dim intTempCount                    'Counter of the number of Excel sheets that have been created

Dim strDBNAME                       'DB_NAME parameter from the database parameters
Dim strLastColumn                   'Column identifier in Excel of the right-most column

Dim i                               'Counter

On Error Resume Next

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

'Create an Excel connection
Set objExcel = CreateObject("Excel.Application")

'Set up to allow exporting, if requested
objExcel.DisplayAlerts = False
objExcel.Workbooks.Add

strUsername = "sys"    'Must connect as the SYS user
strPassword = "SysPassword"
strDatabase = "MyODBC" 'Must use an ODBC connection if O7_DICTIONARY_ACCESSIBILITY = FALSE

If UCase(strUsername) <> "SYS" Then
  'Can use this for SYS if O7_DICTIONARY_ACCESSIBILITY = TRUE, ODBC connection then not required
  dbDatabase.ConnectionString = "Provider=OraOLEDB.Oracle;Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & ";"
Else
  'Must use an ODBC connection if O7_DICTIONARY_ACCESSIBILITY = FALSE
  dbDatabase.ConnectionString = "Data Source=" & strDatabase & ";User ID=" & strUsername & ";Password=" & strPassword & " AS SYSDBA;"
End If

dbDatabase.Open

'Should verify that the connection attempt was successful, but I will leave that for someone else to code
If Err <> 0 Then
  MsgBox "Not Connected, Error: " & Err
Else
  'Adapted from the SQL statement at http://www.jlcomp.demon.co.uk/params.html
  strSQL = "SELECT " & vbCrLf
  strSQL = strSQL & "  UPPER(NAM.KSPPINM) NAME," & vbCrLf
  strSQL = strSQL & "  VAL.KSPPSTVL VALUE," & vbCrLf
  strSQL = strSQL & "  NAM.INDX+1 NUM," & vbCrLf
  strSQL = strSQL & "  NAM.KSPPITY TYPE," & vbCrLf
  strSQL = strSQL & "  VAL.KSPPSTDF ISDEFAULT," & vbCrLf
  strSQL = strSQL & "  DECODE(BITAND(NAM.KSPPIFLG/256,1),1,'TRUE','FALSE') ISSES_MODIFIABLE," & vbCrLf
  strSQL = strSQL & "  DECODE(BITAND(NAM.KSPPIFLG/65536,3)," & vbCrLf
  strSQL = strSQL & "    1,'IMMEDIATE'," & vbCrLf
  strSQL = strSQL & "    2,'DEFERRED' ," & vbCrLf
  strSQL = strSQL & "    3,'IMMEDIATE'," & vbCrLf
  strSQL = strSQL & "    'FALSE') ISSYS_MODIFIABLE," & vbCrLf
  strSQL = strSQL & "  DECODE(BITAND(VAL.KSPPSTVF,7)," & vbCrLf
  strSQL = strSQL & "    1,'MODIFIED'," & vbCrLf
  strSQL = strSQL & "    4,'SYSTEM MODIFIED'," & vbCrLf
  strSQL = strSQL & "    'FALSE') ISMODIFIED," & vbCrLf
  strSQL = strSQL & "  DECODE(BITAND(VAL.KSPPSTVF,2),2,'TRUE', 'FALSE') ISADJUSTED," & vbCrLf
  strSQL = strSQL & "  NAM.KSPPDESC DESCRIPTION" & vbCrLf
  strSQL = strSQL & "FROM" & vbCrLf
  strSQL = strSQL & "  X$KSPPI NAM," & vbCrLf
  strSQL = strSQL & "  X$KSPPSV VAL" & vbCrLf
  strSQL = strSQL & "WHERE " & vbCrLf
  strSQL = strSQL & "  NAM.INDX = VAL.INDX " & vbCrLf
  strSQL = strSQL & "ORDER BY" & vbCrLf
  strSQL = strSQL & "  UPPER(DECODE(SUBSTR(NAM.KSPPINM,1,2),'__',SUBSTR(NAM.KSPPINM,3)," & vbCrLf
  strSQL = strSQL & "          DECODE(SUBSTR(NAM.KSPPINM,1,1),'_',SUBSTR(NAM.KSPPINM,2),NAM.KSPPINM)))," & vbCrLf
  strSQL = strSQL & "  UPPER(NAM.KSPPINM)"
  snpData.Open strSQL, dbDatabase

  If snpData.State = 1 Then
    If Not (snpData.EOF) Then
      With objExcel
        .Visible = True
        .ActiveWorkbook.Sheets.Add
        .ActiveSheet.Name = "DB Parameters"

         For i = 0 To snpData.Fields.Count - 1
           .ActiveSheet.Cells(1, i + 1).Value = snpData.Fields(i).Name
         Next
         .ActiveSheet.Range(.ActiveSheet.Cells(1, 1), .ActiveSheet.Cells(1, snpData.Fields.Count)).Font.Bold = True

         'Format the columns in the spreadsheet
         For i = 0 To snpData.Fields.Count - 1
           strLastColumn = Chr(64 + ((i + 1) Mod 26))

           .Columns(strLastColumn).Select
           Select Case snpData.Fields(i).Type
             Case adDate, adDBDate, adDBTimeStamp, adDBTime
               .Selection.HorizontalAlignment = -4152
               .Selection.NumberFormat = "mm/dd/yy hh:nn AM/PM"
             Case adBigInt, adInteger, adSmallInt, adTinyInt, adUnsignedBigInt, adUnsignedInt, adUnsignedSmallInt, adUnsignedTinyInt
               .Selection.HorizontalAlignment = -4152
               .Selection.NumberFormat = "0"
             Case adVarNumeric, adDecimal, adDouble, adNumeric, adSingle
               .Selection.HorizontalAlignment = -4152
               .Selection.NumberFormat = "0"
             Case adVarChar
               .Selection.HorizontalAlignment = -4131
               .Selection.NumberFormat = "@"
           End Select
         Next

         strLastColumn = Chr(64 + ((snpData.Fields.Count + 1) Mod 26))
         .ActiveSheet.Range("A2").CopyFromRecordset snpData

         'Auto-fit up to columns
         .ActiveSheet.Columns("A:" & strLastColumn).AutoFit
         .ActiveSheet.Range("B2").Select
         .ActiveWindow.FreezePanes = True

         .Application.DisplayAlerts = False
         'Remove the default worksheets
         For i = 1 To ActiveWorkbook.Sheets.Count
           If .ActiveWorkbook.Sheets(i).Name = "Sheet1" Then
             .Sheets("Sheet1").Select
             .ActiveWindow.SelectedSheets.Delete
           End If
           If .ActiveWorkbook.Sheets(i).Name = "Sheet2" Then
             .Sheets("Sheet2").Select
             .ActiveWindow.SelectedSheets.Delete
           End If
           If .ActiveWorkbook.Sheets(i).Name = "Sheet3" Then
             .Sheets("Sheet3").Select
             .ActiveWindow.SelectedSheets.Delete
           End If
         Next
      End With
      snpData.Close

      'Repeat the SQL statement to find the value of the DB_NAME parameter
      snpData.Open strSQL, dbDatabase

      Do While Not (snpData.EOF)
        If UCase(snpData("name")) = "DB_NAME" Then
          strDBNAME = snpData("value")
          Exit Do
        End If
        snpData.MoveNext
      Loop
    Else
      MsgBox "No Rows Returned"
    End If
  Else
    MsgBox "Could Not Open the SQL Statement " & Err
  End If
  snpData.Close

  objExcel.ActiveWorkbook.SaveAs "C:\OracleParameters " & strDBNAME & " " & Replace(Replace(Now, "/", "-"), ":", "-") & ".xls"
End If

'Clean Up
Set objExcel = Nothing
Set snpData = Nothing
dbDatabase.Close
Set dbDatabase = Nothing

When the script runs it will create a spreadsheet in the root of the C:\ drive – move the spreadsheet as needed for documentation purposes.





How to Determine which First Rows OPTIMIZER_MODE was Specified

16 02 2010

February 16, 2010

As you are probably aware, recent releases of Oracle (10.1 and above) support several variants of the first rows OPTIMIZER_MODE, in addition to ALL_ROWS, RULE, CHOOSE, and the original FIRST_ROWS (RULE and CHOOSE are now deprecated, and generally FIRST_ROWS should not be used).  When a 10046 trace is generated for a session, the trace file includes a reference (og=) that indicates the optimizer mode in effect for that SQL statement, as described in this article.  Unfortunately, 10046 extended trace files do not make a distinction between the original FIRST_ROWS optimizer mode and the newer variants FIRST_ROWS_1, FIRST_ROWS_10, FIRST_ROWS_100, and FIRST_ROWS_1000 – all will show og=2 in the 10046 trace file.  When the OPTIMIZER_MODE is set to FIRST_ROWS_10, for instance, the optimizer assumes that the client will only read the first 10 rows, and the client will discard the rest of the rows in the result set.  If the optimizer predicts that only eight rows will be returned (or a number less than or equal to 10), the optimizer will likely generate an execution plan similar to what would be generated with the OPTIMIZER_MODE set to ALL_ROWS.  As such, a different execution plan could be generated if the OPTIMIZER_MODE is set to FIRST_ROWS_10 rather than FIRST_ROWS_1000 when the result set is predicted to include, for instance, 120 rows.

Last year a question appeared on the OTN forums asking how to determine which of the FIRST_ROWS optimizer modes was in use based on the contents of a raw 10046 trace file.  Sounds like an interesting request.  If a simultaneous 10053 trace was enabled, or a 10132 trace (as suggested by Jonathan Lewis in the thread), the optimizer mode will be written directly to the same trace file that includes the 10046 trace information, if the SQL statement is hard parsed.  What else can you do?  A trace file generated on Oracle 11.1 and above includes the SQL_ID for the SQL statement in the raw 10046 trace file, while earlier versions include the HASH_VALUE which can be used to determine the SQL_ID.  Unfortunately, there could be multiple child cursors for the same SQL_ID, each potentially using a different value for the OPTIMIZER_MODE.

As a test, we could use a script like the following (using the sample table from this blog article):

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

SELECT
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C1<=50000;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1';

SELECT
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C1<=50000;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_10';

SELECT
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C1<=50000;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_100';

SELECT
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C1<=50000;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET OPTIMIZER_MODE='FIRST_ROWS_1000';

SELECT
  C1,
  C2,
  C3
FROM
  T1
WHERE
  C1<=50000;

SELECT SYSDATE FROM DUAL;

ALTER SESSION SET OPTIMIZER_MODE='ALL_ROWS';

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

The resulting trace file might contain entries like ths following (when executed on Oracle 10.2.0.4):

PARSING IN CURSOR #1 len=51 dep=0 uid=31 oct=3 lid=31 tim=1934865102 hv=1321303491 ad='94ec5058'
...
PARSE #1:c=0,e=1474,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1934865097
...
STAT #1 id=1 cnt=50000 pid=0 pos=1 obj=114250 op='TABLE ACCESS FULL T1 (cr=3323 pr=0 pw=0 time=50079 us)'
...
PARSING IN CURSOR #1 len=51 dep=0 uid=31 oct=3 lid=31 tim=1943577683 hv=1321303491 ad='94ec5058'
...
PARSE #1:c=0,e=1694,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,tim=1943577677
...
STAT #1 id=1 cnt=50000 pid=0 pos=1 obj=114250 op='TABLE ACCESS BY INDEX ROWID T1 (cr=1803 pr=0 pw=0 time=150071 us)'
STAT #1 id=2 cnt=50000 pid=1 pos=1 obj=114251 op='INDEX RANGE SCAN SYS_C0020571 (cr=143 pr=0 pw=0 time=333 us)'

...
PARSING IN CURSOR #1 len=51 dep=0 uid=31 oct=3 lid=31 tim=1952576477 hv=1321303491 ad='94ec5058'
...
PARSE #1:c=0,e=100,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1952576474
...
STAT #1 id=1 cnt=50000 pid=0 pos=1 obj=114250 op='TABLE ACCESS BY INDEX ROWID T1 (cr=1803 pr=0 pw=0 time=150075 us)'
STAT #1 id=2 cnt=50000 pid=1 pos=1 obj=114251 op='INDEX RANGE SCAN SYS_C0020571 (cr=143 pr=0 pw=0 time=285 us)'
...
PARSING IN CURSOR #1 len=51 dep=0 uid=31 oct=3 lid=31 tim=1961574186 hv=1321303491 ad='94ec5058'
...
PARSE #1:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1961574184
...
STAT #1 id=1 cnt=50000 pid=0 pos=1 obj=114250 op='TABLE ACCESS BY INDEX ROWID T1 (cr=1803 pr=0 pw=0 time=150075 us)'
STAT #1 id=2 cnt=50000 pid=1 pos=1 obj=114251 op='INDEX RANGE SCAN SYS_C0020571 (cr=143 pr=0 pw=0 time=298 us)'
...
PARSING IN CURSOR #1 len=51 dep=0 uid=31 oct=3 lid=31 tim=1970536100 hv=1321303491 ad='94ec5058'
...
PARSE #1:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=2,tim=1970536097
...
STAT #1 id=1 cnt=50000 pid=0 pos=1 obj=114250 op='TABLE ACCESS BY INDEX ROWID T1 (cr=1803 pr=0 pw=0 time=150075 us)'
STAT #1 id=2 cnt=50000 pid=1 pos=1 obj=114251 op='INDEX RANGE SCAN SYS_C0020571 (cr=143 pr=0 pw=0 time=294 us)'

If you are able to determine the SQL_ID based on the contents of the trace file, you could do something like this:

SELECT
  CHILD_NUMBER CN,
  NAME,
  VALUE,
  ISDEFAULT DEF
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='fnk3z1j7c2zf3'
ORDER BY
  CHILD_NUMBER,
  NAME;

 CN NAME                          VALUE           DEF
--- ----------------------------- --------------- ---
  0 active_instance_count         1               YES
  0 bitmap_merge_area_size        1048576         YES
...

Unfortunately, the 10.2.0.4 trace file lacks the SQL_ID, so we need an extra trip into V$SQL:

SELECT
  SE.SQL_ID,
  SE.CHILD_NUMBER CN,
  SE.ADDRESS,
  SE.NAME,
  SE.VALUE,
  SE.ISDEFAULT DEF
FROM
  V$SQL_OPTIMIZER_ENV SE,
  V$SQL S
WHERE
  S.HASH_VALUE=1321303491
  AND S.SQL_ID=SE.SQL_ID
  AND S.CHILD_NUMBER=SE.CHILD_NUMBER
  AND S.ADDRESS=SE.ADDRESS
ORDER BY
  SE.CHILD_NUMBER,
  SE.NAME;

SQL_ID         CN ADDRESS          NAME                          VALUE           DEF
------------- --- ---------------- ----------------------------- --------------- ---
fnk3z1j7c2zf3   0 000007FF94EC5058 active_instance_count         1               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 bitmap_merge_area_size        1048576         YES
fnk3z1j7c2zf3   0 000007FF94EC5058 cpu_count                     4               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 cursor_sharing                exact           YES
fnk3z1j7c2zf3   0 000007FF94EC5058 hash_area_size                131072          NO
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_dynamic_sampling    2               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_features_enable     10.2.0.4        NO
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_index_caching       0               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_index_cost_adj      100             YES
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_mode                all_rows        YES
fnk3z1j7c2zf3   0 000007FF94EC5058 optimizer_secure_view_merging true            YES
fnk3z1j7c2zf3   0 000007FF94EC5058 parallel_ddl_mode             enabled         YES
fnk3z1j7c2zf3   0 000007FF94EC5058 parallel_dml_mode             disabled        YES
fnk3z1j7c2zf3   0 000007FF94EC5058 parallel_execution_enabled    false           YES
fnk3z1j7c2zf3   0 000007FF94EC5058 parallel_query_mode           enabled         YES
fnk3z1j7c2zf3   0 000007FF94EC5058 parallel_threads_per_cpu      2               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 pga_aggregate_target          204800 KB       YES
fnk3z1j7c2zf3   0 000007FF94EC5058 query_rewrite_enabled         true            YES
fnk3z1j7c2zf3   0 000007FF94EC5058 query_rewrite_integrity       enforced        YES
fnk3z1j7c2zf3   0 000007FF94EC5058 skip_unusable_indexes         true            YES
fnk3z1j7c2zf3   0 000007FF94EC5058 sort_area_retained_size       0               YES
fnk3z1j7c2zf3   0 000007FF94EC5058 sort_area_size                65536           YES
fnk3z1j7c2zf3   0 000007FF94EC5058 sqlstat_enabled               true            NO
fnk3z1j7c2zf3   0 000007FF94EC5058 star_transformation_enabled   false           YES
fnk3z1j7c2zf3   0 000007FF94EC5058 statistics_level              typical         YES
fnk3z1j7c2zf3   0 000007FF94EC5058 workarea_size_policy          auto            YES
fnk3z1j7c2zf3   1 000007FF94EC5058 active_instance_count         1               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 bitmap_merge_area_size        1048576         YES
fnk3z1j7c2zf3   1 000007FF94EC5058 cpu_count                     4               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 cursor_sharing                exact           YES
fnk3z1j7c2zf3   1 000007FF94EC5058 hash_area_size                131072          NO
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_dynamic_sampling    2               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_features_enable     10.2.0.4        NO
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_index_caching       0               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_index_cost_adj      100             YES
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_mode                first_rows_1    NO
fnk3z1j7c2zf3   1 000007FF94EC5058 optimizer_secure_view_merging true            YES
fnk3z1j7c2zf3   1 000007FF94EC5058 parallel_ddl_mode             enabled         YES
fnk3z1j7c2zf3   1 000007FF94EC5058 parallel_dml_mode             disabled        YES
fnk3z1j7c2zf3   1 000007FF94EC5058 parallel_execution_enabled    false           YES
fnk3z1j7c2zf3   1 000007FF94EC5058 parallel_query_mode           enabled         YES
fnk3z1j7c2zf3   1 000007FF94EC5058 parallel_threads_per_cpu      2               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 pga_aggregate_target          204800 KB       YES
fnk3z1j7c2zf3   1 000007FF94EC5058 query_rewrite_enabled         true            YES
fnk3z1j7c2zf3   1 000007FF94EC5058 query_rewrite_integrity       enforced        YES
fnk3z1j7c2zf3   1 000007FF94EC5058 skip_unusable_indexes         true            YES
fnk3z1j7c2zf3   1 000007FF94EC5058 sort_area_retained_size       0               YES
fnk3z1j7c2zf3   1 000007FF94EC5058 sort_area_size                65536           YES
fnk3z1j7c2zf3   1 000007FF94EC5058 sqlstat_enabled               true            NO
fnk3z1j7c2zf3   1 000007FF94EC5058 star_transformation_enabled   false           YES
fnk3z1j7c2zf3   1 000007FF94EC5058 statistics_level              typical         YES
fnk3z1j7c2zf3   1 000007FF94EC5058 workarea_size_policy          auto            YES

From the above, we see that there were only two child cursors in the library cache for our SQL statement.  Changing the OPTIMIZER_MODE between the various first rows modes did not trigger the generation of a new child cursor (this same behavior is present on Oracle 11.1.0.7 also), so the OPTIMIZER_MODE recorded in V$SQL_OPTIMIZER_ENV is first_rows_1.

A 10046 trace file captured with Oracle 11.1.0.7, executing the SQL statement with just the ALL_ROWS and FIRST_ROWS_1000 OPTIMIZER_MODEs, included the following:

PARSING IN CURSOR #14 len=51 dep=0 uid=60 oct=3 lid=60 tim=5884684690220 hv=1321303491 ad='23b698b8' sqlid='fnk3z1j7c2zf3'
...
PARSE #14:c=31250,e=43048,p=0,cr=140,cu=0,mis=1,r=0,dep=0,og=1,plh=3617692013,tim=5884684690220
...
STAT #14 id=1 cnt=50000 pid=0 pos=1 obj=86190 op='TABLE ACCESS FULL T1 (cr=6497 pr=3268 pw=0 time=0 us cost=890 size=700000 card=50000)'
...
PARSING IN CURSOR #17 len=51 dep=0 uid=60 oct=3 lid=60 tim=5884708721111 hv=1321303491 ad='23b698b8' sqlid='fnk3z1j7c2zf3'
...
PARSE #17:c=15625,e=31248,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=2,plh=4259601085,tim=5884708721111
...
STAT #17 id=1 cnt=50000 pid=0 pos=1 obj=86190 op='TABLE ACCESS BY INDEX ROWID T1 (cr=8260 pr=0 pw=0 time=0 us cost=37 size=14028 card=1002)'
STAT #17 id=2 cnt=50000 pid=1 pos=1 obj=86191 op='INDEX RANGE SCAN SYS_C0015323 (cr=3422 pr=0 pw=0 time=0 us cost=4 size=0 card=0)'

Since the SQL_ID was written to the 10046 trace file, we are able to see the optimizer parameters in effect for the query with the following SQL statement:

SELECT
  CHILD_NUMBER CN,
  NAME,
  VALUE,
  ISDEFAULT DEF
FROM
  V$SQL_OPTIMIZER_ENV
WHERE
  SQL_ID='fnk3z1j7c2zf3'
ORDER BY
  CHILD_NUMBER,
  NAME;

 CN NAME                                  VALUE           DEF
--- ------------------------------------- --------------- ---
  0 _optim_peek_user_binds                false           NO
  0 _optimizer_adaptive_cursor_sharing    false           NO
  0 active_instance_count                 1               YES
  0 bitmap_merge_area_size                1048576         YES
  0 cell_offload_compaction               ADAPTIVE        YES
  0 cell_offload_plan_display             AUTO            YES
  0 cell_offload_processing               true            YES
  0 cpu_count                             2               YES
  0 cursor_sharing                        exact           YES
  0 db_file_multiblock_read_count         32              YES
  0 hash_area_size                        131072          YES
  0 is_recur_flags                        0               YES
  0 optimizer_capture_sql_plan_baselines  false           YES
  0 optimizer_dynamic_sampling            2               YES
  0 optimizer_features_enable             11.1.0.7        YES
  0 optimizer_index_caching               0               YES
  0 optimizer_index_cost_adj              100             YES
  0 optimizer_mode                        all_rows        YES
  0 optimizer_secure_view_merging         true            YES
  0 optimizer_use_invisible_indexes       false           YES
  0 optimizer_use_pending_statistics      false           YES
  0 optimizer_use_sql_plan_baselines      true            YES
  0 parallel_ddl_mode                     enabled         YES
  0 parallel_degree                       0               YES
  0 parallel_dml_mode                     disabled        YES
  0 parallel_execution_enabled            false           YES
  0 parallel_query_default_dop            0               YES
  0 parallel_query_mode                   enabled         YES
  0 parallel_threads_per_cpu              2               YES
  0 pga_aggregate_target                  143360 KB       YES
  0 query_rewrite_enabled                 true            YES
  0 query_rewrite_integrity               enforced        YES
  0 result_cache_mode                     MANUAL          YES
  0 skip_unusable_indexes                 true            YES
  0 sort_area_retained_size               0               YES
  0 sort_area_size                        65536           YES
  0 sqlstat_enabled                       true            NO
  0 star_transformation_enabled           false           YES
  0 statistics_level                      typical         YES
  0 transaction_isolation_level           read_commited   YES
  0 workarea_size_policy                  auto            YES
  1 _optim_peek_user_binds                false           NO
  1 _optimizer_adaptive_cursor_sharing    false           NO
  1 active_instance_count                 1               YES
  1 bitmap_merge_area_size                1048576         YES
  1 cell_offload_compaction               ADAPTIVE        YES
  1 cell_offload_plan_display             AUTO            YES
  1 cell_offload_processing               true            YES
  1 cpu_count                             2               YES
  1 cursor_sharing                        exact           YES
  1 db_file_multiblock_read_count         32              YES
  1 hash_area_size                        131072          YES
  1 is_recur_flags                        0               YES
  1 optimizer_capture_sql_plan_baselines  false           YES
  1 optimizer_dynamic_sampling            2               YES
  1 optimizer_features_enable             11.1.0.7        YES
  1 optimizer_index_caching               0               YES
  1 optimizer_index_cost_adj              100             YES
  1 optimizer_mode                        first_rows_1000 NO
  1 optimizer_secure_view_merging         true            YES
  1 optimizer_use_invisible_indexes       false           YES
  1 optimizer_use_pending_statistics      false           YES
  1 optimizer_use_sql_plan_baselines      true            YES
  1 parallel_ddl_mode                     enabled         YES
  1 parallel_degree                       0               YES
  1 parallel_dml_mode                     disabled        YES
  1 parallel_execution_enabled            false           YES
  1 parallel_query_default_dop            0               YES
  1 parallel_query_mode                   enabled         YES
  1 parallel_threads_per_cpu              2               YES
  1 pga_aggregate_target                  143360 KB       YES
  1 query_rewrite_enabled                 true            YES
  1 query_rewrite_integrity               enforced        YES
  1 result_cache_mode                     MANUAL          YES
  1 skip_unusable_indexes                 true            YES
  1 sort_area_retained_size               0               YES
  1 sort_area_size                        65536           YES
  1 sqlstat_enabled                       true            NO
  1 star_transformation_enabled           false           YES
  1 statistics_level                      typical         YES
  1 transaction_isolation_level           read_commited   YES
  1 workarea_size_policy                  auto            YES

As long as someone did not use more than one of the first rows OPTIMIZER_MODEs, the above query will show the OPTIMIZER_MODE that was in effect at the time of the hard parse.  Of course, if another of the above parameters was also changed when the OPTIMIZER_MODE changed, there is a very good chance that a new child cursor would have been generated.





V$FILESTAT is Wrong?

13 02 2010

February 13, 2010

While describing file monitoring in chapter 8 of the Expert Oracle Practices book, one of the interesting items that Randolf and I mentioned was an apparent inconsistency in V$FILESTAT, but we then went on to explain why the inconsistency is present.  To see this inconsistency, I will bounce an 11.1.0.7 database, execute a couple of SQL statements to force physical reads (the SQL statements are not important to this experiment), and then check the current values in V$FILESTAT.  The following script will be executed to show the V$FILESTAT statistics and also the statistics from V$FILE_HISTOGRAM:

spool fileactivity.txt
set linesize 160
set pagesize 2000

SELECT
  FILE#,
  PHYRDS,
  PHYWRTS,
  PHYBLKRD,
  PHYBLKWRT,
  SINGLEBLKRDS,
  READTIM,
  WRITETIM,
  SINGLEBLKRDTIM,
  AVGIOTIM,
  LSTIOTIM,
  MINIOTIM,
  MAXIORTM,
  MAXIOWTM
FROM
  V$FILESTAT
WHERE
  FILE# IN (6,7);

SELECT
  FILE#,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1,SINGLEBLKRDS,0)) MILLI1,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2,SINGLEBLKRDS,0)) MILLI2,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4,SINGLEBLKRDS,0)) MILLI4,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,8,SINGLEBLKRDS,0)) MILLI8,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,16,SINGLEBLKRDS,0)) MILLI16,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,32,SINGLEBLKRDS,0)) MILLI32,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,64,SINGLEBLKRDS,0)) MILLI64,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,128,SINGLEBLKRDS,0)) MILLI128,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,256,SINGLEBLKRDS,0)) MILLI256,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,512,SINGLEBLKRDS,0)) MILLI512,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1024,SINGLEBLKRDS,0)) MILLI1024,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2048,SINGLEBLKRDS,0)) MILLI2048,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4096,SINGLEBLKRDS,0)) MILLI4096
FROM
  V$FILE_HISTOGRAM
WHERE
  FILE# IN (6,7)
GROUP BY
  FILE#
ORDER BY
  FILE#;

spool off

So, what is the inconsistency?  Here is the output of the above SQL statements:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6     13       9       13         9            2      25        0              8        0        0        0        9        0
    7  27983   39608   138431    107305        13693    6073  3702202           1719        0        0        0       36      447 

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      0      0      0       0       0       2        0        0        0         0         0         0
    7  12816    222     68     79     108     304      80       12        3        1         0         0         0

So, what is the inconsistency?  Let’s ignore file #7 for a moment and take a look at file #6.  In the above output, the SINGLEBLKRDS column indicates that there were 2 single block reads of file #6, and the SINGLEBLKRDTIM column indicates that the two single block reads required 8 centiseconds (0.08 seconds).  The V$FILE_HISTOGRAM output shows that there were two block reads of file #6 that completed in the range of 32ms (0.032 seconds) and 63.99999ms (0.06399999 seconds).  Those two sets of statistics are consistent, so where is the inconsistency?

Let’s check a couple of the statistics from the output of V$FILESTAT and check the definitions from the documentation:

 2 SINGLEBLKRDS - Number of single block reads
13 PHYBLKRD - Number of physical blocks read
13 PHYRDS - Number of physical reads done

Is the inconsistency clear now?  If 2 of the 13 blocks that were read from the tablespace were read by single block reads, that means that 11 of the blocks were read by something other than single block reads.  Single block reads, by definition, read one block during each read request, so 2 of the 13 physical reads were read by single block reads and that means 11 of the read request were something other than single block reads.  That means 11 blocks were read in 11 read calls by something other than single block reads – were they read by multi-block reads?  Think about that for a moment.

Do those columns really mean something other than what the documentation states?  Is this another bug in the V$FILESTAT view?  Bugs?  From Metalink:

  • V$FILESTAT WRITETIM Shows Very High Values [ID 168930.1]
  • Bug 4942939 – Very high values for ODM/ASM readtim/writetim in V$FILESTAT [ID 4942939.8]
  • Bug 2481002 – V$FILESTAT.AVGIOTIM is incorrect [ID 2481002.8]

All of the above bugs were fixed prior to Oracle 11.1.0.7.  Maybe the next step is to look for more information about V$FILESTAT:

OK, now that you are back from reading the above links, how is it possible to read 11 blocks in a total of 11 read requests when none of the 11 reads are single block reads?  Maybe another script will help answer that question:

CONNECT SYS/SYSPASSWORD AS SYSDBA

CREATE OR REPLACE TRIGGER STARTUP_10046_TRACE AFTER STARTUP ON DATABASE
BEGIN
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET MAX_DUMP_FILE_SIZE=UNLIMITED';
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET TIMED_STATISTICS=TRUE';
  EXECUTE IMMEDIATE 'ALTER SYSTEM SET EVENTS ''10046 TRACE NAME CONTEXT FOREVER, LEVEL 12''';
END;
/

SHUTDOWN IMMEDIATE;

STARTUP

spool fileactivitystartup.txt
set linesize 160
set pagesize 2000

SELECT
  FILE#,
  PHYRDS,
  PHYWRTS,
  PHYBLKRD,
  PHYBLKWRT,
  SINGLEBLKRDS,
  READTIM,
  WRITETIM,
  SINGLEBLKRDTIM,
  AVGIOTIM,
  LSTIOTIM,
  MINIOTIM,
  MAXIORTM,
  MAXIOWTM
FROM
  V$FILESTAT
WHERE
  FILE# IN (6,7);

SELECT
  FILE#,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1,SINGLEBLKRDS,0)) MILLI1,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2,SINGLEBLKRDS,0)) MILLI2,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4,SINGLEBLKRDS,0)) MILLI4,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,8,SINGLEBLKRDS,0)) MILLI8,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,16,SINGLEBLKRDS,0)) MILLI16,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,32,SINGLEBLKRDS,0)) MILLI32,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,64,SINGLEBLKRDS,0)) MILLI64,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,128,SINGLEBLKRDS,0)) MILLI128,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,256,SINGLEBLKRDS,0)) MILLI256,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,512,SINGLEBLKRDS,0)) MILLI512,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,1024,SINGLEBLKRDS,0)) MILLI1024,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,2048,SINGLEBLKRDS,0)) MILLI2048,
  MAX(DECODE(SINGLEBLKRDTIM_MILLI,4096,SINGLEBLKRDS,0)) MILLI4096
FROM
  V$FILE_HISTOGRAM
WHERE
  FILE# IN (6,7)
GROUP BY
  FILE#
ORDER BY
  FILE#;

spool off

ALTER SYSTEM SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

DROP TRIGGER STARTUP_10046_TRACE;

The output of the above script follows:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6      4       1        4         1            1       2        0              2        0        2        0        2        0
    7      4       1        4         1            1       2        0              2        0        2        0        2        0

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      0      0      0       0       1       0        0        0        0         0         0         0
    7      0      0      0      0       0       1       0        0        0        0         0         0         0

Again we see the inconsistency SINGLEBLKRDS = 1, PHYBLKRD = 4, PHYRDS = 4 – therefore there were 3 blocks read in 3 physical reads that were not single block reads.  How is this possible?  Maybe we should check the trace files?  The trace file for the session performing the STARTUP command contains the following:

...
WAIT #5: nam='direct path read' ela= 17 file number=1 first dba=1 block cnt=1 obj#=369 tim=7842773692
WAIT #5: nam='direct path read' ela= 11153 file number=2 first dba=1 block cnt=1 obj#=369 tim=7842784875
WAIT #5: nam='direct path read' ela= 19974 file number=3 first dba=1 block cnt=1 obj#=369 tim=7842804886
WAIT #5: nam='direct path read' ela= 1 file number=4 first dba=1 block cnt=1 obj#=369 tim=7842804932
WAIT #5: nam='direct path read' ela= 1 file number=5 first dba=1 block cnt=1 obj#=369 tim=7842804959
WAIT #5: nam='direct path read' ela= 1 file number=6 first dba=1 block cnt=1 obj#=369 tim=7842804981
...

The trace file for LGWR contains the following:

...
WAIT #0: nam='direct path read' ela= 5 file number=1 first dba=1 block cnt=1 obj#=-1 tim=7842890656
WAIT #0: nam='direct path read' ela= 1 file number=2 first dba=1 block cnt=1 obj#=-1 tim=7842890694
WAIT #0: nam='direct path read' ela= 1 file number=3 first dba=1 block cnt=1 obj#=-1 tim=7842890726
WAIT #0: nam='direct path read' ela= 1 file number=4 first dba=1 block cnt=1 obj#=-1 tim=7842890756
WAIT #0: nam='direct path read' ela= 0 file number=5 first dba=1 block cnt=1 obj#=-1 tim=7842890801
WAIT #0: nam='direct path read' ela= 1 file number=6 first dba=1 block cnt=1 obj#=-1 tim=7842890832
...

Let’s see: 1 single block read in the SYS session, 1 single block read in the LGWR trace file, therefore 1=2?  That makes complete sense.  What you probably will not find in the documentation is a statement that the SINGLEBLKRDS column of V$FILESTAT and the statistics in V$FILE_HISTOGRAM correspond to the “db file sequential read” wait event, and do not include statistics for single block reads associated with the “direct path read” wait event.  (At least in this case.)

What about Oracle 11.2.0.1?  Here is the output of the two SQL statements after executing a couple of queries following a database bounce:

FILE# PHYRDS PHYWRTS PHYBLKRD PHYBLKWRT SINGLEBLKRDS READTIM WRITETIM SINGLEBLKRDTIM AVGIOTIM LSTIOTIM MINIOTIM MAXIORTM MAXIOWTM
----- ------ ------- -------- --------- ------------ ------- -------- -------------- -------- -------- -------- -------- --------
    6     18      14       18        14           18       2        0              2        0        0        0        1        0
    7  57047  223616   535618    495511        42430   11588  5689141           4838        0        0        0      218      279

FILE# MILLI1 MILLI2 MILLI4 MILLI8 MILLI16 MILLI32 MILLI64 MILLI128 MILLI256 MILLI512 MILLI1024 MILLI2048 MILLI4096
----- ------ ------ ------ ------ ------- ------- ------- -------- -------- -------- --------- --------- ---------
    6      0      1      0      0       1       0       0        0        0        0         0         0         0
    7  39775    186    342    991     684     235     107       79        7        3         1         2         2

From the above:

18 SINGLEBLKRDS - Number of single block reads
18 PHYBLKRD - Number of physical blocks read
18 PHYRDS - Number of physical reads done

Don’t you hate it when Oracle is self-consistent, and yet at the same time not self-consistent?  One has to wonder if a bug was corrected regarding the counting of single block reads, or if direct path reads are no longer performed when the database is opened.  But, we have another problem – look closely at the output from V$FILE_HISTOGRAM.





Tracing Enabled for Sessions After Instance Restart

12 02 2010

February 12, 2010

An recent thread in the comp.databases.oracle.server Usenet group brought up an interesting question.  What would cause a 10046 trace at level 12 and and errorstack trace at level 3 for event 21700 to be enabled for sessions every time the original poster bounced the Oracle XE instance?  Is this possibly a sign that someone modified an initialization parameter?  Did someone modify the application to enabling tracing to log files?  Is it a bug in Oracle XE? 

Fortunately, the OP provided a portion of one of the trace files, as shown below:

*** SERVICE NAME:(SYS$USERS) 2010-02-02 09:46:36.593
*** SESSION ID:(31.46) 2010-02-02 09:46:36.593
=====================
PARSING IN CURSOR #6 len=69 dep=2 uid=0 oct=42 lid=0 tim=80934443123 hv=3164292706 ad='6688fd70'
alter session set events '10046 trace name context forever, level 12'
END OF STMT
EXEC #6:c=0,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934443118
=====================
PARSING IN CURSOR #6 len=71 dep=2 uid=0 oct=42 lid=0 tim=80934681241 hv=681663222 ad='6b8cb08c'
alter session set events '21700 trace name errorstack forever, level 3'
END OF STMT
PARSE #6:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934681236
BINDS #6:
EXEC #6:c=0,e=8426,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934748960
=====================
PARSING IN CURSOR #6 len=34 dep=2 uid=0 oct=42 lid=0 tim=80934753347 hv=1152259314 ad='66a0f058'
alter session set sql_trace = TRUE
END OF STMT
PARSE #6:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934753343
BINDS #6:
EXEC #6:c=0,e=29497,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=80934836162
=====================
PARSING IN CURSOR #7 len=435 dep=1 uid=0 oct=47 lid=0 tim=80934862347 hv=545826169 ad='6b897000'
begin
      execute immediate 'alter session set max_dump_file_size = unlimited';
      execute immediate 'alter session set tracefile_identifier = ''10046via_app''';
      execute immediate 'alter session set events ''10046 trace name context forever, level 12''';
      execute immediate 'alter session set events ''21700 trace name errorstack forever, level 3''';
      execute immediate 'alter session set sql_trace = TRUE';
  end;
END OF STMT

So, from the above trace file, is the tracing caused by:

  • A bug in Oracle XE
  • An application that was modified
  • A modified parameter in the spfile/pfile
  • None of the above

The number following dep= in the trace file is a significant clue.  SQL statements that are submitted by client application code will appear in 10046 trace files with dep= set to 0, so that probably rules out a change to the application code, unless of course the application is executing a PL/SQL block.  The discrete ALTER SESSION statements in the trace file that are wrapped in EXECUTE IMMEDIATE statements probably rules out the possibility of a parameter that was modified in the spfile/pfile and probably also rules out the possibilty of a bug in Oracle XE.  So, what might the next step be to find the cause of the trace files?

Another possibility is either a LOGON or STARTUP trigger that is enabling the trace.  The OP mentioned in the thread that he had enabled tracing earlier to troubleshoot a problem.  The tracing is apparently enabled in a PL/SQL procedure or anonymous PL/SQL block based on the value of dep= and the EXECUTE IMMEDIATE calls, so either a LOGON or STARTUP trigger is a possibility.  To test this possibility, you might execute a SQL statement like this:

SELECT
  TRIGGER_NAME,
  TRIGGER_TYPE,
  TRIGGERING_EVENT
FROM
  DBA_TRIGGERS
WHERE
  OWNER='SYS'
  AND TRIGGER_TYPE IN ('BEFORE EVENT','AFTER EVENT')
  AND SUBSTR(TRIGGERING_EVENT,1,5) IN ('START','LOGON');

TRIGGER_NAME           TRIGGER_TYPE TRIGGERING_EVENT
---------------------- ------------ ----------------
LOGON_FIX_MYAPP_PERF   AFTER EVENT  LOGON
LOGON_CAPTURE_10046    AFTER EVENT  LOGON
ENABLE_OUTLINES_TRIG   AFTER EVENT  STARTUP

If the above returned no rows, there is still a very small chance that a logon trigger or startup trigger is owned by a user other than SYS, so it might make sense to repeat the SQL statement without the OWNER=’SYS’ predicate in the WHERE clause.  In my case the SQL statement returned three rows – two logon triggers and one startup trigger.  The logon trigger name LOGON_CAPTURE_10046 is a significant indicator that a trigger is present that will enable a 10046 trace when the user logs into the database – it helps to use a consistent and descriptive naming convention.

The OP did not show the output of the above SQL statement, but did state that he found and removed a logon trigger that enabled the two traces.  If such a trigger is found, and you know that the trigger does not belong in the database, the trigger may be removed by connecting to the database as the SYS user and dropping the trigger:

DROP TRIGGER LOGON_CAPTURE_10046;







Follow

Get every new post delivered to your Inbox.

Join 137 other followers