Striving for Optimal Performance
  • Home
  • Blog
    • Archive
    • Categories
  • Troubleshooting Oracle Performance
    • Description
    • Structure
    • Table of Contents
    • Forewords
    • Reviews
    • Downloadable Files
    • Addenda and Errata
  • Publications
  • Public Appearances
    • Past Public Appearances
  • Contact
  • Search
  • About

Posts in category Bug

How Many Children Can a Parent Cursor Have? 1,000,000?

Oct19
2012
2 Comments Written by Christian Antognini

The patch set 11.2.0.3 includes a fix for bug# 10187168 which, in reality, is an enhancement request. Its purpose is to artificially limit the number of child cursors that a parent cursor can have. The concept is quite easy: when a parent cursor reaches _cursor_obsolete_threshold (default value is 100) child cursors the parent cursor is obsoleted and, as a result, a new one is created.

So, as of 11.2.0.3 (or with some PSUs and bundle patches), the answer to the question is: 100.

But how many child cursors are supported in previous 11.2 releases? This is a question that crossed my mind few weeks ago while preparing for the “Shareable Cursors” presentation that I gave at the OakTable World in San Francisco. Is it for example possible to have a parent cursor with 1,000,000 child cursors? Not that something like that is sensible, but I would like to know whether it is technically possible. In other words, whether the database engine supports it.

To try answering the question, I wrote and run on 11.2.0.2 the following test case. Notice that the PL/SQL block is able, if there is enough memory, to create 1,000,000 child cursors. Hence, before running it, I increased the shared pool size to 10GB.

SQL> CREATE TABLE t (n NUMBER);

Table created.

SQL> INSERT INTO t VALUES (1);

1 row created.

SQL> COMMIT;

Commit complete.

SQL> execute dbms_stats.gather_table_stats(user,'t')

PL/SQL procedure successfully completed.

SQL> DECLARE
  2    l_count PLS_INTEGER;
  3  BEGIN
  4    FOR oic IN 1..100
  5    LOOP
  6      EXECUTE IMMEDIATE 'ALTER SESSION SET optimizer_index_caching = '||oic;
  7      FOR oica IN 1..10000
  8      LOOP
  9        EXECUTE IMMEDIATE 'ALTER SESSION SET optimizer_index_cost_adj = '||oica;
 10        EXECUTE IMMEDIATE 'SELECT count(*) FROM t' into l_count;
 11      END LOOP;
 12    END LOOP;
 13  END;
 14  /
DECLARE
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 6809
Session ID: 7 Serial number: 9

As you can see the result is interesting ;-)

In the alert.log I found the following information:

Errors in file /u00/app/oracle/diag/rdbms/dbm11202/DBM11202/trace/DBM11202_ora_6809.trc  (incident=25425):
ORA-00600: internal error code, arguments: [15206], [], [], [], [], [], [], [], [], [], [], []
Incident details in: /u00/app/oracle/diag/rdbms/dbm11202/DBM11202/incident/incdir_25425/DBM11202_ora_6809_i25425.trc

As always, when I see this kind of error, I check the ORA-600/ORA-7445/ORA-700 Error Look-up Tool. Unfortunately, in this case, no information is provided. So I continued investigating the issued by looking at the trace file generated for the incident. As expected the SQL statement hitting the problem was the following:

----- Current SQL Statement for this session (sql_id=5tjqf7sx5dzmj) -----
SELECT count(*) FROM t

And the library cache content for the associated cursor was the following:

      LibraryHandle:  Address=0x2c5e4d030 Hash=3a56fe71 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
        ObjectName:  Name=SELECT count(*) FROM t
          FullHashValue=6d0bd54734bada875cc6ce3e3a56fe71 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=978779761 OwnerIdn=36
        Statistics:  InvalidationCount=0 ExecutionCount=65535 LoadCount=65536 ActiveLocks=51 TotalLockCount=65536 TotalPinCount=1
        Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=65535 BucketInUse=0 HandleInUse=0 HandleReferenceCount=0
        Concurrency:  DependencyMutex=0x2c5e4d0e0(0, 4097, 0, 0) Mutex=0x2c5e4d160(0, 5120057, 12919, 0)
        Flags=RON/PIN/TIM/PN0/DBN/[10012841]
        WaitersLists:
          Lock=0x2c5e4d0c0[0x2c5e4d0c0,0x2c5e4d0c0]
          Pin=0x2c5e4d0a0[0x2c5e4d0a0,0x2c5e4d0a0]
        Timestamp:  Current=10-19-2012 07:02:48
        HandleReference:  Address=0x2c5e4d1e0 Handle=(nil) Flags=[00]
        LibraryObject:  Address=0x2c5e4bfc0 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
          ChildTable:  size='65536'
            Child:  id='0' Table=0x2c5e4ce70 Reference=0x2c5e4c898 Handle=0x2c5e4bbd0
            Child:  id='1' Table=0x2c5e4ce70 Reference=0x2c5e4cd58 Handle=0x2c5dd4338
            Child:  id='2' Table=0x2c5e4ce70 Reference=0x2c5dce0d0 Handle=0x2c5dcdae8
            Child:  id='3' Table=0x2c5e4ce70 Reference=0x2c5dce568 Handle=0x2c5dc8298
            Child:  id='4' Table=0x2c5e4ce70 Reference=0x2c5dcea00 Handle=0x2c5dc2a48
            …
            Child:  id='65530' Table=0x2846e56d8 Reference=0x2846b07e8 Handle=0x2846b03d8
            Child:  id='65531' Table=0x2846e56d8 Reference=0x2846b0c80 Handle=0x2846ad188
            Child:  id='65532' Table=0x2846e56d8 Reference=0x2846b1118 Handle=0x2846a9f38
            Child:  id='65533' Table=0x2846e56d8 Reference=0x2846a60f8 Handle=0x2846a5ce8
            Child:  id='65534' Table=0x2846e56d8 Reference=0x2846a6590 Handle=0x2846a2a98

The most interesting part is the one providing the number of child cursors: 65536.

I might be wrong but to me that means that the child number is stored as an unsigned integer taking 16 bits. And, when the maximum is exceeded, an ORA-00600 is raised.

According to this test the maximum number of child cursors for a given parent cursor is 65536. But, as already written, the fix for bug# 10187168 artificially limits it to 100.

Posted in 11gR2, Library Cache

Event 10046 – Full List of Levels

Aug10
2012
Leave a Comment Written by Christian Antognini

Extended SQL trace (a.k.a. debugging event 10046 at a level higher than 1) is one of the key features provided by Oracle to troubleshoot applications using Oracle Database. For many years the available levels were always the same (4, 8 and 12). In fact, since I wrote my first paper about it in May 2000 and the release of 11g nothing changed.

With 11g, as I described in this post, new levels (16 and 32) were introduced.

More recently, with the introduction of the fix for bug 8328200, a new one was added to the list (64).

So, I thought it was time to publish the current list of available levels…

Level Description
0 The debugging event is disabled.
1 The debugging event is enabled. For each processed database call, the following information is given: SQL statement, response time, service time, number of processed rows, number of logical reads, number of physical reads and writes, execution plan, and little additional information.
Up to 10.2 an execution plan is written to the trace file only when the cursor it is associated with is closed. The execution statistics associated to it are values aggregated over all executions.
As of 11.1 an execution plan is written to the trace file only after the first execution of every cursor. The execution statistics associated to it are the ones of the first execution only.
4 As in level 1, with additional information about bind variables. Mainly, the data type, its precision, and the value used for each execution.
8 As in level 1, plus detailed information about wait time. For each wait experienced during the processing, the following information is given: the name of the wait event, the duration, and a few additional parameters identifying the resource that has been waited for.
16 As in level 1, plus the execution plans information is written to the trace file for each execution. Available as of 11.1 only.
32 As in level 1, but without the execution plans information. Available as of 11.1 only.
64 As in level 1, plus the execution plans information might be written for executions following the first one. The condition is that, since the last write of execution plans information, a particular cursor consumed at least one additional minute of DB time. This level is interesting in two cases. First, when the information about the first execution is not enough for analysing a specific issue. Second, when the overhead of writing the information about every execution (level 16) is too high. Generally available as of 11.2.0.2 only.

In addition to the levels described in the previous table, you can also combine the levels 4 and 8 with every other level greater than 1. For example:

  • Level 12 (4 + 8): simultaneously enable level 4 and level 8.
  • Level 28 (4 + 8 + 16): simultaneously enable level 4, level 8 and level 16.
  • Level 68 (4 + 64): simultaneously enable level 4 and level 64.

If you are using dbms_monitor or dbms_session for enabling extended SQL trace, here is the mapping between the levels and the parameters:

  • Level 4: waits=FALSE, binds=TRUE, plan_stat=’first_execution’
  • Level 8: waits=TRUE, binds=FALSE, plan_stat=’first_execution’
  • Level 16: waits=FALSE, binds=FALSE, plan_stat=’all_executions’
  • Level 32: waits=FALSE, binds=FALSE, plan_stat=’never’
  • Level 64: not available yet

As you can see from the previous list, it is not possible to enable level 64 through dbms_monitor and dbms_session. Hence, statements like the following ones or ORADEBUG have to be used:

alter session set events '10046 trace name context forever, level 64'

alter session set events 'sql_trace wait=false, bind=false, plan_stat=adaptive'

I really hope that this limitation will be removed very soon.

UPDATE 2012-08-13: An Oracle employee informed me that about the limitation of dbms_monitor and dbms_session bug #14483308 has been opened. Thank you Ted!
UPDATE 2012-08-16: Bug #14483308 was rejected :-( . As a result enhancement request #14499199 was created.

Posted in 11gR1, 11gR2, SQL Trace

Index Scan with Filter Predicate Based on a Subquery

Feb06
2012
3 Comments Written by Christian Antognini

Most execution plans can be interpreted by following few basic rules (in TOP, Chapter 6, I provide such a list of rules). Nevertheless, there are some special cases. One of them is when an index scan, in addition to the access predicate, has a filter predicate applying a subquery.

The following execution plan, taken from Enterprise Manager 11.2, is an example (click on the image to increase its size):
Execution Plan
Notes:

  • According to the order column the first operation being executed is the scan of the I2 index. Unfortunately this is wrong. In fact the first operation being executed is the scan of the I1 index. This is a bug in Enterprise Manager. I wanted to show you this example to demonstrate that not only for us it might be difficult to correctly interpret an execution plan ;-)
  • The filter predicate IS NOT NULL is also wrong. This is not a bug, however. It is a limitation in the current implementation. The problem is that in some cases the V$SQL_PLAN and V$SQL_PLAN_STATISTICS_ALL views are not able to show all the necessary details.

Without seeing the query on which this execution plan is based, it is not obvious at all to know what’s going on. So, here is the query:

SELECT *
FROM t1
WHERE n1 = 8
AND n2 IN (SELECT t2.n1 FROM t2, t3 WHERE t2.id = t3.id AND t3.n1 = 8) 

Based on the query it is essential to point out that the access predicate "T2"."N1"=:B1 cannot be evaluated and, therefore, the scan of the I2 index cannot be carried out, without having a value passed through the B1 bind variable. In other words, without knowing the value of T1.N2.

To describe how this execution plan is carried out, let’s have a look to the information provided by the DBMS_XPLAN.DISPLAY function (which does not expose the limitation related to the filter predicate).

-----------------------------------------------
| Id  | Operation                      | Name |
-----------------------------------------------
|   0 | SELECT STATEMENT               |      |
|   1 |  TABLE ACCESS BY INDEX ROWID   | T1   |
|*  2 |   INDEX RANGE SCAN             | I1   |
|   3 |    NESTED LOOPS                |      |
|   4 |     TABLE ACCESS BY INDEX ROWID| T2   |
|*  5 |      INDEX RANGE SCAN          | I2   |
|*  6 |     TABLE ACCESS BY INDEX ROWID| T3   |
|*  7 |      INDEX RANGE SCAN          | I3   |
-----------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
2 - access("N1"=8)
    filter( EXISTS (SELECT /*+ LEADING ("T2" "T3") USE_NL ("T3") INDEX
           ("T3" "I3") INDEX_RS_ASC ("T2" "I2") */ 0 FROM "T3" "T3","T2" "T2" WHERE
           "T2"."N1"=:B1 AND "T3"."N1"=8 AND "T2"."ID"="T3"."ID"))
5 - access("T2"."N1"=:B1)
6 - filter("T2"."ID"="T3"."ID")
7 - access("T3"."N1"=8)

The operations are carried out as follows:

  1. Operation 2 applies the access predicate "N1"=8 by scanning the I1 index.
  2. For each key returned by the previous scan, the subquery is executed once. Note that the subquery carries out a nested loop. While the outer loop accesses the T2 table, the inner loop accesses the T3 table.
  3. The first operation of the outer loop is operation 5. It applies the access predicate "T2"."N1"=:B1 by scanning the I2 index. Based on the rowid returned by the index access the T2 table is accessed (operation 4).
  4. For each row returned by the outer loop, the inner loop is executed once. The first operation of the inner loop is operation 7. It applies the access predicate "T3"."N1"=8 by scanning the I3 index. Based on the rowid returned by the index access the T3 table is accessed (operation 6) and the filter predicate "T2"."ID"="T3"."ID" (the join condition) is applied. By the way, it is interesting to notice that, contrary to the join condition is not applied as an access predicate, as it usually happens.
  5. If the subquery returns a row, the rowid returned by operation 2 can be used to access the T1 table (operation 1). The row extracted from this operation is sent to the caller.

All in all, this is a very special execution plan…

In summary, be careful when you see an index scan with a filter predicate applying a subquery. The execution plan might not be carried out as you expect at first sight. It is also essential to point out that in such a case the predicate information is essential to fully understand what’s going on.

Posted in 10gR2, 11gR1, 11gR2, Query Optimizer, TOP
← Older Entries

EvoLve theme by Theme4Press  •  Powered by WordPress Striving for Optimal Performance