Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Archive for the ‘Cursor’ Category

LOB vs. SQL*Trace

with 2 comments

Have you noticed this abnormality of SQL*Trace on reading LOB?

Here we have 2 tables t1 and t2 which have same volume but with different the data types - LOB vs. VARCHAR2.

create table t1(c1 int, c2 clob);

declare
	v_clob clob := rpad('x', 4000, 'x');
begin
	for idx in 1 .. 1000 loop
		insert into t1 values(idx, v_clob);
	end loop;
end;
/

create table t2(c1 int, c2 varchar2(4000));

declare
	v_varchar varchar2(4000) := rpad('x', 4000, 'x');
begin
	for idx in 1 .. 1000 loop
		insert into t2 values(idx, v_varchar);
	end loop;
end;
/


Reading t1.LOB takes 2 min.

UKJA@ukja102> select * from t1;

        C1                                                                      
----------                                                                      
C2                                                                              
--------------------------------------------------------------------------------
       583                                                                      
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...

1000 rows selected.

Elapsed: 00:02:05.53
UKJA@ukja102> 



, while reading t2.VARCAR2 takes 10 sec.

UKJA@ukja102> select * from t2;

        C1                                                                      
----------                                                                      
C2                                                                              
--------------------------------------------------------------------------------
         5                                                                      
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
...
1000 rows selected.

Elapsed: 00:00:10.50



The performance difference between LOB and VARCHAR2 is not an issue here. The abnormality is observed in the report by SQL*Trace and tkprof. See following.

select * 
from
 t1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch     1001      0.14       0.09          0       1009          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1003      0.14       0.09          0       1009          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
   1000  TABLE ACCESS FULL T1 (cr=1009 pr=0 pw=0 time=41472 us)


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



Reading t1.LOB took 2 min, but the tkprof report shows the time of just around 0.1 sec. Where has the actual 2 min gone?

Reading t2.VARCHAR2 shows what I expected. Around 10 sec waiting for the request of the client.

select * 
from
 t2

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       68      0.01       0.01          0       1005          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       70      0.01       0.02          0       1005          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
   1000  TABLE ACCESS FULL T2 (cr=1005 pr=0 pw=0 time=8348 us)


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


Has Oracle just ignored the time spent on LOB reading? If so, it would be just a sign of bug. But look at following total time in the tkprof report on t1.LOB.

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.01       0.00          0          0          0           0
Execute      6      0.00       0.00          0          0          0           0
Fetch     1007      0.14       0.09          0       1009          0        1003
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1018      0.15       0.09          0       1009          0        1003

Misses in library cache during parse: 2

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                  102009        0.00          0.31
  SQL*Net message from client                102009        0.03         32.35
  direct path read                           201000        0.06         58.51

...



Look at the times and elapsed time of the wait events! Very strange, isn’t it? The query itself does not include these values, but only the total time includes them. There should be some mismatch. Where does this mismatch happen?

This is the time when we should look into the raw trace file, which is not very common in the real life. See following.

PARSING IN CURSOR #1 len=16 dep=0 uid=61 oct=3 lid=61 tim=155701141356 hv=2245880055 ad='2e6260a8'
select * from t1
END OF STMT
PARSE #1:c=0,e=925,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=155701141350
EXEC #1:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=155701142972
WAIT #1: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143147
WAIT #1: nam='SQL*Net message from client' ela= 358 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701143714
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144019
FETCH #1:c=0,e=312,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,tim=155701144249
WAIT #1: nam='SQL*Net message from client' ela= 161 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=155701144584
WAIT #0: nam='direct path read' ela= 24239 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701169489
WAIT #0: nam='direct path read' ela= 440 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701170930
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701171143
WAIT #0: nam='SQL*Net message from client' ela= 1273 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701172643
WAIT #0: nam='direct path read' ela= 26168 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701199245
WAIT #0: nam='direct path read' ela= 787 file number=12 first dba=13915 block cnt=1 obj#=89468 tim=155701200504
WAIT #0: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701200820
WAIT #0: nam='SQL*Net message from client' ela= 450 driver id=1413697536 #bytes=1 p3=0 obj#=89468 tim=155701201480
...



Do you see the mismatching happening here? CURSOR#1 is the query being executed(select * from t1), but suddenly wait event is reported as WAIT#0 not WAIT#1. This is why we have no wait time in the query itself.

Now comes the difficult part. What the hell is the WAIT#0? Where did it come from? Simple additional test case would give the hints to interpret this phenomenon. While session#1 is reading on t1.LOB, let’s monitor the session#1.

-- session #1(sid=140)
select * from t1;

UKJA@ukja102> -- session #2
UKJA@ukja102> col sql_id new_value v_sql_id
UKJA@ukja102> col prev_sql_id new_value v_prev_sql_id
UKJA@ukja102> col kglnaobj new_value v_kglnaobj
UKJA@ukja102>
UKJA@ukja102> select sql_id, prev_sql_id from v$session where sid = 140
  2  ;

SQL_ID        PREV_SQL_ID
------------- -------------
fa45sbd422h0k 27uhu2q2xuu7r

Elapsed: 00:00:00.01
UKJA@ukja102>-- Note that the CURRENT query is not shown in V$SQL
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_sql_id';
old   1: select sql_text from v$sql where sql_id = '&v_sql_id'
new   1: select sql_text from v$sql where sql_id = 'fa45sbd422h0k'

no rows selected

Elapsed: 00:00:00.00
UKJA@ukja102>-- The CURRENT query is reported as the PREVIOUS query
UKJA@ukja102> select sql_text from v$sql where sql_id = '&v_prev_sql_id';
old   1: select sql_text from v$sql where sql_id = '&v_prev_sql_id'
new   1: select sql_text from v$sql where sql_id = '27uhu2q2xuu7r'

SQL_TEXT
--------------------------------------------------------------------------------
select * from t1

Elapsed: 00:00:00.01
UKJA@ukja102>-- Although the current query is not existent in the v$sql, 
-- it should exist in the X$KGLOB - the mother of all LCOs
UKJA@ukja102> select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id';
old   1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = '&v_sql_id'
new   1: select kglhdnsp, kglnaobj from sys.xm$kglob where kglobt03 = 'fa45sbd422h0k'

  KGLHDNSP
----------
KGLNAOBJ
--------------------------------------------------------------------------------
         0
table_4_9_15d7b_0_0_

         0
table_4_9_15d7b_0_0_


Elapsed: 00:00:00.01
UKJA@ukja102>-- What does table_4_9_15d7b_0_0_ mean?
UKJA@ukja102> select object_name from dba_objects
  2  where object_id = to_dec(regexp_substr('&v_kglnaobj',  '[^_]+', 1, 4));
old   2: where object_id = to_dec(regexp_substr('&v_kglnaobj',  '[^_]+', 1, 4))
new   2: where object_id = to_dec(regexp_substr('table_4_9_15d7b_0_0_',  '[^_]+', 1, 4))

OBJECT_NAME
--------------------------------------------------------------------------------
T1



Above result means that

  • When reading LOB, Oracle creates internal cursor which reads the LOB.
  • Because this internal cursor is just another new cursor, the time spent on it is not included in the original query.
  • This internal query does not show itself in the trace file. We can just infer it.
  • Be careful when interpreting the tkprof report, especially when there is a big difference between the time of the individual queries and the total time.

And followings are related posts which describe the same phenomenon in the different ways.
http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/
https://dioncho.wordpress.com/2009/04/20/lob-sql_id-and-lco/

Written by Dion Cho

June 19, 2009 at 2:22 am

Posted in Cursor, Wait Event

Similar cursor sharing and adative cursor sharing

with 8 comments

Similar cursor sharing and multiple child cursors are very common problems as shown here.

What makes people confused about simiar cursor sharing is this.

What the hell does “SIMILAR” mean exactly?

My opinion is…

Even with the tiny chance of the different execution plans, Oracle would deny to share the cursor.

Okay, then, when do we have any tiny chance of different execution plans with literal predicates? Many documents mention only about histogram, but as far as I know, we have more cases.

  1. Histogram predicate
  2. Range predicate
  3. Partition key predicate

Very reasonable, isn’t it?

But the stupidity of similar cursor sharing implementation drives some peolpe crazy. Oracle just spawns as many child cursors as the distinct count of literal value. This means that this SQL statment

alter session set cursor_sharing = similar;
(Assuming the existence of histogram on the column c1)
select * from t1 where c1 = 1;
select * from t1 where c1 = 2;
select * from t1 where c1 = 3;
...
select * from t1 where c1 = 100;



would have 100 child cursors, not just one shared child cursor. This would result in a disaster under certain circumstances.

Following is a simple test case that demonstrates the stupidity of similar cursor sharing.

UKJA@ukja102> create table t1(c1 int, c2 int);

Table created.

Elapsed: 00:00:00.01
UKJA@ukja102> 
UKJA@ukja102> insert into t1
  2  select level, 1
  3  from dual connect by level <= 10000
  4  ;

10000 rows created.

Elapsed: 00:00:00.04
UKJA@ukja102> 
UKJA@ukja102> insert into t1
  2  select level, 2
  3  from dual connect by level <= 1
  4  ;

1 row created.

Elapsed: 00:00:00.01
UKJA@ukja102> 
UKJA@ukja102> create index t1_n1 on t1(c1);

Index created.

Elapsed: 00:00:00.15
UKJA@ukja102> -- Gather histogram
UKJA@ukja102> exec dbms_stats.gather_table_stats(user, 't1', -
> 	  method_opt=>'for all columns size skewonly');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.23
UKJA@ukja102> -- SIMILAR cursor sharing
UKJA@ukja102> alter session set cursor_sharing = similar;

Session altered.

Elapsed: 00:00:00.00
UKJA@ukja102> -- Case1: Range predicate
UKJA@ukja102> select /* range_predicate */ count(c2) from t1 where c1 between 1 and 100;
UKJA@ukja102> select /* range_predicate */ count(c2) from t1 where c1 between 1 and 200;
UKJA@ukja102> select /* range_predicate */ count(c2) from t1 where c1 between 1 and 300;
UKJA@ukja102> select /* range_predicate */ count(c2) from t1 where c1 between 1 and 400;
UKJA@ukja102> select /* range_predicate */ count(c2) from t1 where c1 between 1 and 10000;

UKJA@ukja102> -- Version count is 5 which means no sharing happend
UKJA@ukja102> select sql_text, version_count from v$sqlarea
  2  where sql_text like 'select /* range_predicate */ count(c2) from t1%';

SQL_TEXT                                                                        
--------------------------------------------------------------------------------
VERSION_COUNT                                                                   
-------------                                                                   
select /* range_predicate */ count(c2) from t1 where c1 between :"SYS_B_0" and :
"SYS_B_1"                                                                       
            5    

UKJA@ukja102> -- Case2. Histogram predicate
UKJA@ukja102> select /* histogram */ count(c2) from t1 where c2 = 1;
UKJA@ukja102> select /* histogram */ count(c2) from t1 where c2 = 2;
UKJA@ukja102> select /* histogram */ count(c2) from t1 where c2 = 3;
UKJA@ukja102> select /* histogram */ count(c2) from t1 where c2 = 4;
UKJA@ukja102> select /* histogram */ count(c2) from t1 where c2 = 5;

UKJA@ukja102> -- Version count is 5 which means no sharing happend
UKJA@ukja102> select sql_text, version_count from v$sqlarea
  2  where sql_text like 'select /* histogram */ count(c2) from t1%';

SQL_TEXT                                                                        
--------------------------------------------------------------------------------
VERSION_COUNT                                                                   
-------------                                                                   
select /* histogram */ count(c2) from t1 where c2 = :"SYS_B_0"                  
            5                                                                   

UKJA@ukja102> create table t2(c1 int, c2 int)
  2  partition by list(c1) (
  3  	     partition p1 values (1),
  4  	     partition p2 values (2),
  5  	     partition p3 values (3)
  6  );

Table created.

Elapsed: 00:00:00.11
UKJA@ukja102> 
UKJA@ukja102> insert into t2
  2  select mod(level,3)+1, level
  3  from dual connect by level  
UKJA@ukja102> exec dbms_stats.gather_table_stats(user, 't2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.15
UKJA@ukja102> 
UKJA@ukja102> alter session set cursor_sharing = similar;

Session altered.

Elapsed: 00:00:00.00
UKJA@ukja102> -- Case3: Partition key predicate
UKJA@ukja102> select /* partition */ count(c2) from t2 where c1 = 1;
UKJA@ukja102> select /* partition */ count(c2) from t2 where c1 = 2;
UKJA@ukja102> select /* partition */ count(c2) from t2 where c1 = 3;
UKJA@ukja102> select /* partition */ count(c2) from t2 where c1 = 4;
UKJA@ukja102> select /* partition */ count(c2) from t2 where c1 = 5;

UKJA@ukja102> -- Version count is 5 which means no sharing happend
UKJA@ukja102> select sql_text, version_count from v$sqlarea
  2  where sql_text like 'select /* partition */ count(c2) from t2%';

SQL_TEXT                                                                        
--------------------------------------------------------------------------------
VERSION_COUNT                                                                   
-------------                                                                   
select /* partition */ count(c2) from t2 where c1 = :"SYS_B_0"                  
            5                                                                   
            





Do you agree with me on the stupidity of SIMILAR cursor sharing implementation?

By the way, the only positive way to handle this problem is introduced as of 11g in the name of adaptive cursor sharing. The funny thing is we don’t need SIMILAR cursor sharing any more. FORCE sharing + adaptive cursor sharing would solve all these problems.

Following simple test case shows that SIMILAR cursor sharing is useless with adaptive cursor sharing. FORCE cursor sharing is now superior to SIMILAR cursor sharing!

select /* partition */ count(c2) from t2 where c1 = 1;
select /* partition */ count(c2) from t2 where c1 = 2;
select /* partition */ count(c2) from t2 where c1 = 3;
select /* partition */ count(c2) from t2 where c1 = 4;
select /* partition */ count(c2) from t2 where c1 = 5;

alter session set cursor_sharing = similar;

UKJA@ukja116> select sql_text, version_count from v$sqlarea
  2  where sql_text like 'select /* partition */ count(c2) from t2%';

SQL_TEXT
--------------------------------------------------------------------------------
VERSION_COUNT
-------------
select /* partition */ count(c2) from t2 where c1 = :"SYS_B_0"
            5

alter session set cursors_sharing = force;

UKJA@ukja116> select sql_text, version_count from v$sqlarea
  2  where sql_text like 'select /* partition */ count(c2) from t2%';

SQL_TEXT
--------------------------------------------------------------------------------
VERSION_COUNT
-------------
select /* partition */ count(c2) from t2 where c1 = :"SYS_B_0"
            2

UKJA@ukja116> @shared_cursor 'select /* partition */ count(c2) from t2%'
UKJA@ukja116> set echo off
old  14:           and q.sql_text like ''&1''',
new  14:           and q.sql_text like ''select /* partition */ count(c2) from t2%''',
SQL_TEXT                       = select /* partition */ count(c2) from t2 where
c1 = :"SYS_B_0"
SQL_ID                         = 5n1vgm2quammk
ADDRESS                        = 2F63F08C
CHILD_ADDRESS                  = 2B78CBE4
CHILD_NUMBER                   = 0
LOAD_OPTIMIZER_STATS           = Y
--------------------------------------------------
SQL_TEXT                       = select /* partition */ count(c2) from t2 where
c1 = :"SYS_B_0"
SQL_ID                         = 5n1vgm2quammk
ADDRESS                        = 2F63F08C
CHILD_ADDRESS                  = 262D3680
CHILD_NUMBER                   = 1
BIND_MISMATCH                  = Y
--------------------------------------------------



Adaptive cursor sharing really looks like adaptive and more powerful than any other previous implementations on the cursor sharing. Looks like prominent new feature, but let’s see what happens in the real production system.

Written by Dion Cho

June 1, 2009 at 2:41 am

LOB, sql_id and LCO

with 3 comments

Kerry Osborne wrote an interesting case on LOB here.

His post gave me a curiosity, so I made a simple test case to emulate his case with some interesting informations.

1. Make LOB data

create table t1(c1 clob);

insert into t1 values(rpad('x',4000,'x'));

commit;

declare
  dest_lob    clob;
  src_lob     clob;
begin
  select c1 into dest_lob
  from t1
  where rownum = 1
  for update;
  
  for idx in 1 .. 100 loop
    dbms_lob.append(dest_lob, rpad('x',4000,'x'));
  end loop;
end;
/

commit;


2. Read LOB data

select * from t1;


3. While reading LOB data, query v$session in another session. As Kerry pointed out, the PREV_SQL_ID value is sql id of select query. But we have no SQL of sql id ‘3aug5b01n1pgg’

UKJA@ukja102> exec print_table('select sql_id, prev_sql_id from v$session where sid=159');
SQL_ID                        : 3aug5b01n1pgg
PREV_SQL_ID                   : 27uhu2q2xuu7r
-----------------

UKJA@ukja102> select sql_text from v$sql where sql_id = '3aug5b01n1pgg';

no rows selected

UKJA@ukja102> select sql_text from v$sql where sql_id = '27uhu2q2xuu7r';

SQL_TEXT
------------------------------------------------------------------------
select * from t1


4. So, where is the object whose sql id is ‘3aug5b01n1pgg’? Here it goes.

UKJA@ukja102> exec print_table('select * from sys.xm$kglob where kglobt03 = ''3aug5b01n1pgg''');
ADDR                          : 08BF90BC
INDX                          : 0
INST_ID                       : 1
KGLHDADR                      : 2A968140
KGLHDPAR                      : 2AC9FBF4
KGLHDCLT                      : 1
KGLNAOWN                      :
KGLNAOBJ                      : table_4_9_1473d_0_0_
KGLFNOBJ                      : table_4_9_1473d_0_0_
KGLNADLK                      :
KGLNAHSH                      : 54580719
KGLNAHSV                      : 7b9cdfbab84ebfd03569e5580340d5ef
KGLNATIM                      : 2009/04/20 17:51:06
KGLNAPTM                      :
KGLHDNSP                      : 0
...
KGLOBT03                      : 3aug5b01n1pgg
...
KGLOBDJV                      : 0
-----------------
ADDR                          : 08BFA0C8
INDX                          : 1
INST_ID                       : 1
KGLHDADR                      : 2AC9FBF4
KGLHDPAR                      : 2AC9FBF4
KGLHDCLT                      : 1
KGLNAOWN                      :
KGLNAOBJ                      : table_4_9_1473d_0_0_
KGLFNOBJ                      : table_4_9_1473d_0_0_
KGLNADLK                      :
KGLNAHSH                      : 54580719
KGLNAHSV                      : 7b9cdfbab84ebfd03569e5580340d5ef
KGLNATIM                      : 2009/04/20 17:51:06
KGLNAPTM                      :
KGLHDNSP                      : 0
...
KGLOBT03                      : 3aug5b01n1pgg
...
KGLOBDJV                      : 0
-----------------



x$kglob.kglobt03 is sql id and the object is table_4_9_1473d_0_0_. Here we have 2 LCOs – one is parent and the other is child.

Also note that the namespace(kglhdnsp) is 0(CURSOR). This means that this LCO is not actually LOB itself, but the internal query on LOB.

5. Library cache dump shows another interesting stuff.

-- parent LCO of the object table_4_9_1473d_0_0_0
BUCKET 54767:
  LIBRARY OBJECT HANDLE: handle=2ac9fbf4 mutex=2AC9FCA8(0)
  name=table_4_9_1473d_0_0_0
  hash=7b9cdfbab84ebfd03569e5580340d5ef timestamp=04-20-2009 17:51:06
  namespace=CRSR flags=RON/KGHP/TIM/KEP/PN0/SML/DBN/[12010044]
  kkkk-dddd-llll=0001-0001-0001 lock=0 pin=0 latch#=1 hpc=0000 hlc=0000
  lwt=2AC9FC50[2AC9FC50,2AC9FC50] ltm=2AC9FC58[2AC9FC58,2AC9FC58]
  pwt=2AC9FC34[2AC9FC34,2AC9FC34] ptm=2AC9FC3C[2AC9FC3C,2AC9FC3C]
  ref=2AC9FC70[2AC9FC70,2AC9FC70] lnd=2AC9FC7C[2B8C29A4,2B93DDB4]
    DEPENDENCY REFERENCES:
    reference latch flags
    --------- ----- -------------------
     2aa7c468     2 [60]
    LIBRARY OBJECT: object=2a96823c
    type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0
    CHILDREN: size=16
    child#    table reference   handle
    ------ -------- --------- --------
         0 2aa7cb18  2aa7c7cc 2a968140 <-- child LCO
    DATA BLOCKS:
    data#     heap  pointer    status pins change whr
    ----- -------- -------- --------- ---- ------ ---
        0 2cfe5b94 2a9682d4 I/P/A/-/-    0 NONE   00 

-- child LCO of the object table_4_9_1473d_0_0_0
  LIBRARY OBJECT HANDLE: handle=2a968140 mutex=2A9681F4(0)
  namespace=CRSR flags=RON/KGHP/PN0/[10010000]
  kkkk-dddd-llll=0000-0041-0041 lock=0 pin=0 latch#=1 hpc=0000 hlc=0000
  lwt=2A96819C[2A96819C,2A96819C] ltm=2A9681A4[2A9681A4,2A9681A4]
  pwt=2A968180[2A968180,2A968180] ptm=2A968188[2A968188,2A968188]
  ref=2A9681BC[2AA7C7CC,2AA7C7CC] lnd=2A9681C8[2A9681C8,2A9681C8]
    CHILD REFERENCES:
    reference latch flags
    --------- ----- -------------------
     2aa7c7cc     2 CHL[02]
    LIBRARY OBJECT: object=2aa7c32c
    type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0
    DEPENDENCIES: count=1 size=16
    dependency#    table reference   handle position flags
    ----------- -------- --------- -------- -------- -------------------
              0 2aa7be88  2aa7bc68 2bb69938        0 DEP[01]  <-- Dependency
    READ ONLY DEPENDENCIES: count=1 size=16
    dependency#    table reference   handle flags
    ----------- -------- --------- -------- -------------------
              0 2aa7c6e8  2aa7c468 2ac9fbf4 /ROD/KPP[60]
    AUTHORIZATIONS: count=1 size=16 minimum entrysize=16
    00000000 3d000000 00020000 00000000 
    ACCESSES: count=1 size=16
    dependency# types
    ----------- -----
              0 0009
    DATA BLOCKS:
    data#     heap  pointer    status pins change whr
    ----- -------- -------- --------- ---- ------ ---
        0 2aa8466c 2aa7c47c I/-/A/-/-    0 NONE   00 
        6 2aa7bc9c 2aa7b8f0 I/-/A/-/-    0 NONE   00 
        
-- The dependee object is UKJA.T1
BUCKET 91153:
  LIBRARY OBJECT HANDLE: handle=2bb69938 mutex=2BB699EC(0)
  name=UKJA.T1
  hash=3534ea19a12fe932b9932812247d6411 timestamp=04-20-2009 17:51:06
  namespace=TABL flags=KGHP/TIM/SML/[02000000]
  kkkk-dddd-llll=0000-074d-074d lock=0 pin=0 latch#=2 hpc=0004 hlc=0004
  lwt=2BB69994[2BB69994,2BB69994] ltm=2BB6999C[2BB6999C,2BB6999C]
  pwt=2BB69978[2BB69978,2BB69978] ptm=2BB69980[2BB69980,2BB69980]
  ref=2BB699B4[2BB699B4,2BB699B4] lnd=2BB699C0[2BAA6AEC,2B067B7C]
    DEPENDENCY REFERENCES:
    reference latch flags
    --------- ----- -------------------
     2aa7bc68     2 DEP[01]
     2bae61b0     1 DEP[01]
     2aa79778     1 DEP[01]
     2a2dbf8c     1 DEP[01]
     2af9332c     1 DEP[01]
     2bd67bb4     0 DEP[01]
     2aca005c     0 DEP[01]
     2be04a6c     0 DEP[01]
    LIBRARY OBJECT: object=2bfe509c
    type=TABL flags=EXS/LOC[0005] pflags=[0000] status=VALD load=0
    DATA BLOCKS:
    data#     heap  pointer    status pins change whr
    ----- -------- -------- --------- ---- ------ ---
        0 2bb6448c 2bfe5158 I/-/A/-/-    0 NONE   00 
        2 2bb1bc84 2aca5cdc I/-/A/-/-    0 NONE   00 
        3 2bb1bc10 2bfe658c I/-/A/-/-    0 NONE   00 
        8 2bfe5374 2c7e9de0 I/-/A/-/-    0 NONE   00 
        9 2bfe540c 2b8df62c I/-/A/-/-    0 NONE   00 
  BUCKET 91153 total object count=1
 



Yes, we can even find out which table is being related using the ugly library cache dump. But we still have no direct way to identify the existence of LOB. :(

This was a very interesting case and thank you Kerry for sharing valueable info!




Written by Dion Cho

April 20, 2009 at 10:39 am

Posted in Cursor

Tagged with , , ,

Library cache latch has gone?

with 9 comments

As Tanel Poder declared with big proud, all the library cache related latches have gone in Oracle 11g!

Good news to DBAs and developers, but bad news to people like me who make moneny from troubleshooting library cache latch contention. :)

So, I decided to prove that I’m still capable of something meaningful.

-- This query has only one child
@shared_cursor 'select /* cursor_share_1 */ * from t1 where c1 = :b1%'

SQL_TEXT                       = select /* cursor_share_1 */ * from t1 where c1 
= :b1                                                                           
SQL_ID                         = 6jf82h3bq1tzr                                  
ADDRESS                        = 2B3F7078                                       
CHILD_ADDRESS                  = 2B3F6F34                                       
CHILD_NUMBER                   = 0                                              
--------------------------------------------------                              

PL/SQL procedure successfully completed.

-- This query has 5 children!
@shared_cursor 'select /* cursor_share */ * from t1 where c1 = :b1%'

SQL_TEXT                       = select /* cursor_share */ * from t1 where c1 =
:b1
SQL_ID                         = 2zu6xb9130t89
ADDRESS                        = 2B38369C
CHILD_ADDRESS                  = 2AC50F60
CHILD_NUMBER                   = 0
--------------------------------------------------
SQL_TEXT                       = select /* cursor_share */ * from t1 where c1 =
:b1
SQL_ID                         = 2zu6xb9130t89
ADDRESS                        = 2B38369C
CHILD_ADDRESS                  = 2A652B48
CHILD_NUMBER                   = 1
OPTIMIZER_MODE_MISMATCH        = Y
--------------------------------------------------
SQL_TEXT                       = select /* cursor_share */ * from t1 where c1 =
:b1
SQL_ID                         = 2zu6xb9130t89
ADDRESS                        = 2B38369C
CHILD_ADDRESS                  = 2A3C7968
CHILD_NUMBER                   = 2
BIND_MISMATCH                  = Y
--------------------------------------------------
SQL_TEXT                       = select /* cursor_share */ * from t1 where c1 =
:b1
SQL_ID                         = 2zu6xb9130t89
ADDRESS                        = 2B38369C
CHILD_ADDRESS                  = 2A1EFD0C
CHILD_NUMBER                   = 3
BIND_MISMATCH                  = Y
--------------------------------------------------
SQL_TEXT                       = select /* cursor_share */ * from t1 where c1 =
:b1
SQL_ID                         = 2zu6xb9130t89
ADDRESS                        = 2B38369C
CHILD_ADDRESS                  = 2A1DA0F0
CHILD_NUMBER                   = 4
BIND_MISMATCH                  = Y
OPTIMIZER_MODE_MISMATCH        = Y
--------------------------------------------------

PL/SQL procedure successfully completed.



Now I make a heavy soft parse to make massive lacth and/or mutex acquistion, and make a simple comparsion for one child vs. filve children.

@mon_on userenv('sid')

declare
  v_cursor      number;
begin
  for idx in 1 .. 200000 loop
    v_cursor := dbms_sql.open_cursor;
    dbms_sql.parse(v_cursor, 'select /* cursor_share_1 */ * from t1 where c1 = :b1', dbms_sql.native);
    dbms_sql.close_cursor(v_cursor);
  end loop;
end;
/

@mon_off

declare
  v_cursor      number;
begin
  for idx in 1 .. 200000 loop
    v_cursor := dbms_sql.open_cursor;
    dbms_sql.parse(v_cursor, 'select /* cursor_share */ * from t1 where c1 = :b1', dbms_sql.native);
    dbms_sql.close_cursor(v_cursor);
  end loop;
end;
/

@mon_off2
@mon_show2


The result of 10g. The long child chain caused 1.5M + 0.8M + 0.8M = 3.1M of more latch acquisition.

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS      
------------------------------ ---------- ---------- ---------- ----------      
library cache                     1599584         -9         -1          0      
library cache lock                 799878          0          0          0      
library cache pin                  799743          1          0          0      
session allocation                  -1497          0          0          0      
shared pool                          -517          0          0          0      
...


The result of 11g. The long child chain caused 0.4M of more shared pool latch acquisition.

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS      
------------------------------ ---------- ---------- ---------- ----------      
shared pool                        399866          3          1          0      
cache buffers chains                 -175          0          0         -7      
enqueue hash chains                    58          0          0          0      
enqueues                               57          0          0          0      
row cache objects                     -46          0          0          0      
shared pool simulator                 -40          0          0          0      
...


Great improvement, isn’t it? We really don’t need any latch for searching through library cache chain and looking into child cursors. Instead, mutexes are used for these operations. Mutex for library cache hash bucket, library cache lock and library cache pin.

But wait… Why I’m getting shared pool activity in 11g? I’m just soft parsing. Well, at this point of time, I have no explanation. More research in need.

The most important thing is that from now on, I’m going to make my living troubleshooting shared pool latch contention. More more annoying library cache latch contention! :)

Written by Dion Cho

March 26, 2009 at 4:21 am

Posted in Cursor, Wait Event

Tagged with ,

The secret of session_cached_cursors

with one comment

Session_cached_cursors is one of the most confusing and misunderstood parameters in Oracle.

To summarize (at least in 10g):

  1. Oracle caches the cursor of the SQL statement executed more than 2 times in the same server process. Yes, the cursor is cached in PGA.
  2. Oracle caches the cursor of the PL/SQL block regardless of the execution count also in the PGA.
  3. The cache has pointer to the shared SQL area. Absolutely shared SQL area is located in SGA.
  4. With cached cursors, Oracle does not release the cursor even when the cursor is considered closed. <– This is the key trick of session cursor sharing.
  5. Because the cursor is not closed, Oracle does not need to check the syntax and search the library cache. It just can go directly to the shared SQL area. Very fast and light.

Decipher? Let me show you a simple but concrete demonstration.

1. oc2.sql : Displays current open cursors for given session id and sql text

define __SID = &1

begin
  print_table('
select
  c.sid,
  c.sql_text
from 
  v$open_cursor c
where
  c.sid in (&__SID)  
  and c.sql_text like ''%/*+ session_cache */%''
'
  );
end;
/



2. Observe the open cursors while executing the statements

UKJA@ukja102> select * from v$version;

BANNER
----------------------------------------------------------------
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Prod
PL/SQL Release 10.2.0.1.0 - Production
CORE    10.2.0.1.0      Production
TNS for 32-bit Windows: Version 10.2.0.1.0 - Production
NLSRTL Version 10.2.0.1.0 - Production

UKJA@ukja102> create table t1(c1 int);

Table created.

-- Current session id 
       SID                                                                                                              
----------                                                                                                              
       149                                                                                                              

UKJA@ukja102> 
UKJA@ukja102> alter session set session_cached_cursors = 50;

Session altered.

UKJA@ukja102> -- First execution of SQL statement
UKJA@ukja102> select /*+ session_cache */ * from t1;

UKJA@ukja102> select * from dual;

UKJA@ukja102> @oc2 149   -- The cursor was closed 

PL/SQL procedure successfully completed.

UKJA@ukja102> -- Second execution of SQL statement
UKJA@ukja102> select /*+ session_cache */ * from t1;

UKJA@ukja102> select * from dual;

UKJA@ukja102> @oc2 149   -- The cursor was closed 

PL/SQL procedure successfully completed.

UKJA@ukja102> -- Thrid!!! execution of SQL statement
UKJA@ukja102> select /*+ session_cache */ * from t1;

UKJA@ukja102> select * from dual;

UKJA@ukja102> @oc2 149  -- Yes, the cursor is not closed even when I explicitly closed it.
-- It's cached
SID                           : 149                                                                                     
SQL_TEXT                      : select /*+ session_cache */ * from t1                                                   
-----------------                                                                                                       

PL/SQL procedure successfully completed.

UKJA@ukja102> -- First execution of PL/SQL block
UKJA@ukja102> begin /*+ session_cache */ dbms_lock.sleep(0.01); end;
  2  /

PL/SQL procedure successfully completed.

UKJA@ukja102> select * from dual;

UKJA@ukja102> @oc2 149  -- It's cached!
SID                           : 149                                                                                     
SQL_TEXT                      : select /*+ session_cache */ * from t1                                                   
-----------------                                                                                                       
SID                           : 149                                                                                     
SQL_TEXT                      : begin /*+ session_cache */ dbms_lock.sleep(0.01); end;                                  
-----------------                                                                                                       

PL/SQL procedure successfully completed.



I can confirm that the library cache lock is hold on the cached cursors. This is a tautology of the fact that cursors are not closed. For open cursors, Oracle holds the library cache lock(LK) on the corresponding shared SQL area(LCO) in null mode(1).

UKJA@ukja102> @lock_internal 149


149 LK 27CC5CDC            1          0 select /*+ session_cache */ *
                                        from t1

149 LK 27D9D4E8            1          0 select /*+ session_cache */ *
                                        from t1
                                        
                                        
149 LK 27EA6AC0            1          0 begin /*+ session_cache */ dbm
                                        s_lock.sleep(0.01); end;

149 LK 27FE362C            1          0 begin /*+ session_cache */ dbm
                                        s_lock.sleep(0.01); end;
                                        



The source of lock_internal script is here.

The easy but not elegant way to observe how Oracle caches the cursor is dumping process state.

 
UKJA@ukja102> alter session set events 'immediate trace name processstate level 10';

Session altered.



I would not post the result of process state dump, just because of it’s readibility and length. :)

Written by Dion Cho

March 13, 2009 at 7:11 am

v$sql_shared_cursor

with 9 comments

I hit following OTN forum article which was a discussion on typical SQL sharing problem.

There are so many reasons why Oracle does not share the same statement. Oracle records the reason in v$sql_shared_cursor view. In my local 10.2.0.1 database, v$sql_shared_cursor has 53 reasons of unshareability.

But I have a big complaint on v$sql_shared_cursor view. It has 53 columns whose value is ‘Y’ or ‘N’. It’s very annoying to display these values and find the columns whose value is ‘Y’. It’s eye-consuming job.

So I built up my own version of v$sql_shared_cursor, like following:

ed shared_cursor

declare
  c         number;
  col_cnt   number;
  col_rec   dbms_sql.desc_tab;
  col_value varchar2(4000);
  ret_val    number;
begin
  c := dbms_sql.open_cursor;
  dbms_sql.parse(c, 
      'select q.sql_text, s.* 
      from v$sql_shared_cursor s, v$sql q 
      where s.sql_id = q.sql_id 
          and s.child_number = q.child_number
          and q.sql_text like ''&1''',
      dbms_sql.native);
  dbms_sql.describe_columns(c, col_cnt, col_rec);
  
  for idx in 1 .. col_cnt loop
    dbms_sql.define_column(c, idx, col_value, 4000);
  end loop;
  
 
  ret_val := dbms_sql.execute(c);
  
  while(dbms_sql.fetch_rows(c) > 0) loop
    for idx in 1 .. col_cnt loop
      dbms_sql.column_value(c, idx, col_value);
      if col_rec(idx).col_name in ('SQL_ID', 'ADDRESS', 'CHILD_ADDRESS', 
                    'CHILD_NUMBER', 'SQL_TEXT') then
        dbms_output.put_line(rpad(col_rec(idx).col_name, 30) || 
                ' = ' || col_value);
      elsif col_value = 'Y' then
        dbms_output.put_line(rpad(col_rec(idx).col_name, 30) || 
                ' = ' || col_value);
      end if;
      
    end loop;
    
    dbms_output.put_line('--------------------------------------------------');
    
   end loop; 
  
  dbms_sql.close_cursor(c);          

end;
/


The powerful dbms_sql package enables us to display only the columns whose value is ‘Y’. The result is like following.

@shared_cursor 'select /* share_test */%'

SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2BC811D4                                                           
CHILD_NUMBER                   = 0                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                  
ADDRESS                        = 2BB29C74                                       
CHILD_ADDRESS                  = 2AB8DA4C                                                           
CHILD_NUMBER                   = 1                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2AAB1798                                                           
CHILD_NUMBER                   = 2                                                                  
AUTH_CHECK_MISMATCH            = Y                                                                  
LANGUAGE_MISMATCH              = Y                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  
                                       



Very intuitive. Following is a demonstration to detect cursor sharing problem using this script.

UKJA@ukja102> create table t1(c1 int, c2 varchar2(100));

Table created.

UKJA@ukja102> alter system flush shared_pool;

System altered.

UKJA@ukja102> var b1 number;
UKJA@ukja102> var b2 varchar2(10);
UKJA@ukja102> 
UKJA@ukja102> exec :b1 := 1;

PL/SQL procedure successfully completed.

UKJA@ukja102> exec :b2 := '0';

PL/SQL procedure successfully completed.

UKJA@ukja102> select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2;

no rows selected

UKJA@ukja102> --This is my SQL
UKJA@ukja102> @shared_cursor 'select /* share_test */%'
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2BC811D4                                                           
CHILD_NUMBER                   = 0                                                                  
--------------------------------------------------                                                  

PL/SQL procedure successfully completed.

UKJA@ukja102> --Change the optimizer mode from all_rows to first_rows
UKJA@ukja102> alter session set optimizer_mode = first_rows;

Session altered.

UKJA@ukja102> select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2;

no rows selected

UKJA@ukja102> -- Yes, mismatch in optimizer mode
UKJA@ukja102> @shared_cursor 'select /* share_test */%'
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2BC811D4                                                           
CHILD_NUMBER                   = 0                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2AB8DA4C                                                           
CHILD_NUMBER                   = 1                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  

PL/SQL procedure successfully completed.

UKJA@ukja102> --Change NLS setting
UKJA@ukja102> alter session set nls_sort = 'KOREAN_M';

Session altered.

UKJA@ukja102> select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2;

no rows selected

UKJA@ukja102> -- Mismatch in language mode and authentication
UKJA@ukja102> @shared_cursor 'select /* share_test */%'
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2BC811D4                                                           
CHILD_NUMBER                   = 0                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                  
ADDRESS                        = 2BB29C74                                       
CHILD_ADDRESS                  = 2AB8DA4C                                                           
CHILD_NUMBER                   = 1                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2AAB1798                                                           
CHILD_NUMBER                   = 2                                                                  
AUTH_CHECK_MISMATCH            = Y                                                                  
LANGUAGE_MISMATCH              = Y                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  

PL/SQL procedure successfully completed.

UKJA@ukja102> -- Now I change the length of the bind variable from 10 to 2000!!!
UKJA@ukja102> var b2 varchar2(2000);
UKJA@ukja102> exec :b2 := '0';

PL/SQL procedure successfully completed.

UKJA@ukja102> select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2;

no rows selected

UKJA@ukja102> -- Mismatch in bind variable
UKJA@ukja102> @shared_cursor 'select /* share_test */%'
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2BC811D4                                                           
CHILD_NUMBER                   = 0                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2AB8DA4C                                                           
CHILD_NUMBER                   = 1                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2AAB1798                                                           
CHILD_NUMBER                   = 2                                                                  
AUTH_CHECK_MISMATCH            = Y                                                                  
LANGUAGE_MISMATCH              = Y                                                                  
OPTIMIZER_MODE_MISMATCH        = Y                                                                  
--------------------------------------------------                                                  
SQL_TEXT                       = select /* share_test */ * from t1 where c1 = :b1 and c2 = :b2      
SQL_ID                         = 9wbx9pbrmhsxm                                                      
ADDRESS                        = 2BB29C74                                                           
CHILD_ADDRESS                  = 2B10FC70                                                           
CHILD_NUMBER                   = 3                                                                  
BIND_MISMATCH                  = Y                                                                
--------------------------------------------------        



The last example clearly shows that the length of bind variable of varchar2 type can be a source of cursor unshareability. Julian Dyke provides a wonderful explanation on this problem.

Unshareable SQL statements have some well-known problems.

  • Library cache contention due to increased scan depth
  • Execution plan change due to new optimization
  • Waste of system resource due to increased hard parse count

Don’t forget v$sql_shared_cursor. It has the answer why your statements are not shared!

Written by Dion Cho

March 5, 2009 at 5:27 am

Posted in Cursor

Tagged with ,

The Pitfall of Cursor Expression

with one comment

Cursor expression is one of the powerful but forgotten features of Oracle query. It has following syntax.

select c1, c2,
   cursor(select * from t2 where t2 where c1 = t1.c1)
from t1;

Cursor expression is a very handy way of generating multidimensional output from RDBMS. But you should recognize following pitfalls and avoid them if necessary. The pitfalls of cursor expression are

  1. View merging is disabled(as pointed out at http://download.oracle.com/docs/cd/B10500_01/server.920/a96533/opt_ops.htm)
  2. You could have excessive calls.
  3. Some confusion with sql_trace and plan statistics.

I would demonstrate above pitfalls with very simple test cases. Looks long, but you will find it very interesting.

1. Query without cursor expression. Note that inline view is successfully merged.

select /* without_cursor */
  t1.c1, x.c2
from
  t1, (select c1, c2 from t2) x
where
  t1.c1 = x.c1
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        8      0.00       0.00          0         31          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.00       0.00          0         31          0         100

Rows     Row Source Operation
-------  ---------------------------------------------------
    100  TABLE ACCESS BY INDEX ROWID T2 (cr=31 pr=0 pw=0 time=6620 us)
    201   NESTED LOOPS  (cr=23 pr=0 pw=0 time=4782 us)
    100    INDEX FULL SCAN T1_N1 (cr=8 pr=0 pw=0 time=431 us)(object id 79292)
    100    INDEX RANGE SCAN T2_N1 (cr=15 pr=0 pw=0 time=2145 us)(object id 79293)

2. Query with cursor expression. Note that we failed at view merging. The result is increased workloads with suboptimal execution plan.

select /* with_cursor */
  t1.c1, x.c2, cursor(select * from dual)
from
  t1, (select c1, c2 from t2) x
where
  t1.c1 = x.c1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       51      0.03       0.05          0        154          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       53      0.03       0.05          0        154          0         100

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  TABLE ACCESS FULL DUAL (cr=0 pr=0 pw=0 time=0 us)
    100  NESTED LOOPS  (cr=154 pr=0 pw=0 time=6135 us)
    100   VIEW  (cr=53 pr=0 pw=0 time=1466 us)
    100    TABLE ACCESS FULL T2 (cr=53 pr=0 pw=0 time=754 us)
    100   INDEX RANGE SCAN T1_N1 (cr=101 pr=0 pw=0 time=3015 us)(object id 79292)

3. Query without cursor expression. Take a close look at the parse/execute/fetch values.

select
  y.*
from
  (select level from dual connect by level <= 1000) x,
  (select * from t1 where rownum <= 10) y

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      668      0.21       0.18          0          3          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      670      0.21       0.19          0          3          0       10000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
  10000  MERGE JOIN CARTESIAN (cr=3 pr=0 pw=0 time=147360 us)
   1000   VIEW  (cr=0 pr=0 pw=0 time=18409 us)
   1000    CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=11399 us)
      1     FAST DUAL  (cr=0 pr=0 pw=0 time=13 us)
  10000   BUFFER SORT (cr=3 pr=0 pw=0 time=52983 us)
     10    VIEW  (cr=3 pr=0 pw=0 time=231 us)
     10     COUNT STOPKEY (cr=3 pr=0 pw=0 time=160 us)
     10      TABLE ACCESS FULL T1 (cr=3 pr=0 pw=0 time=94 us)

4. Query with cursor expression. The output is almost same as that of previous query, but…

Oops. No logical reads? What happened with this query?

select
  cursor(select * from t1 where rownum <= 10)
from dual
connect by level <= 1000

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      501      0.29       0.22          0          0          0        1000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      503      0.29       0.22          0          0          0        1000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  COUNT STOPKEY (cr=0 pr=0 pw=0 time=0 us)
      0   TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 time=0 us)
   1000  CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 time=14289 us)
      1   FAST DUAL  (cr=0 pr=0 pw=0 time=12 us)

The problem is that the query in the cursor expression is executed as recursive query. Look at the parse/execute/fetch values and logical reads! This recursive query was parsed and executed 1000 times, whose value is sames as the rows fetched by main query. Very  bad, isn’t it? This is one of the main performance problem of cursor expression.

SELECT "A2"."C1" "C1","A2"."C2" "C2"
FROM
 "T1" "A2" WHERE ROWNUM<=10

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1000      0.00       0.02          0          0          0           0
Execute   1000      0.09       0.04          0          0          0           0
Fetch     1000      0.32       0.27          0       3000          0       10000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     3000      0.42       0.35          0       3000          0       10000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 61  

Rows     Row Source Operation
-------  ---------------------------------------------------
     10  COUNT STOPKEY (cr=3 pr=0 pw=0 time=172 us)
     10   TABLE ACCESS FULL T1 (cr=3 pr=0 pw=0 time=98 us)

5. Another annoying problem. The main query does not show *real* execution plan. See following.

select /* with_cursor2 */
  cursor(
    select
      t1.c1, x.c2
    from t1, (select c1, c2 from t2) x
    where
      t1.c1 = x.c1
  )
from dual
Rows     Row Source Operation
-------  ---------------------------------------------------
      0  NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us)
      0   VIEW  (cr=0 pr=0 pw=0 time=0 us)
      0    TABLE ACCESS FULL T2 (cr=0 pr=0 pw=0 time=0 us)
      0   INDEX RANGE SCAN T1_N1 (cr=0 pr=0 pw=0 time=0 us)(object id 79292)
      1  FAST DUAL  (cr=0 pr=0 pw=0 time=13 us)

It looks as if the query in the cursor expression failed at view merging. But the actual execution plan from recursive query clearly says that it successfully merged the view!  Looks like a bug, doesn’t it? This annoying phenomenon is observed as of 10gR2.

SELECT "A3"."C1" "C1","A2"."C2" "C2"
FROM
 "T1" "A3", (SELECT "A4"."C1" "C1","A4"."C2" "C2" FROM "T2" "A4") "A2" WHERE
  "A3"."C1"="A2"."C1"
Rows     Row Source Operation
-------  ---------------------------------------------------
    100  TABLE ACCESS BY INDEX ROWID T2 (cr=28 pr=0 pw=0 time=7315 us)
    201   NESTED LOOPS  (cr=21 pr=0 pw=0 time=5606 us)
    100    INDEX FULL SCAN T1_N1 (cr=7 pr=0 pw=0 time=1426 us)(object id 79292)
    100    INDEX RANGE SCAN T2_N1 (cr=14 pr=0 pw=0 time=1905 us)(object id 79293)

6. The last one. Cursor expression does not go well with the plan statistics. Very disappointing.

UKJA@ukja102> select * from table                                           
  2  (dbms_xplan.display_cursor(null,null,'allstats last'));                 

PLAN_TABLE_OUTPUT                                                           
-----------------------------------------------------------------------------
SQL_ID  4um7hxd6fkkh7, child number 0                                       
-------------------------------------                                       
select /*+ gather_plan_statistics */   cursor(     select       t1.c1,      
x.c2     from t1, (select c1, c2 from t2) x     where       t1.c1 =         
x.c1   ) from dual                                                           

Plan hash value: 1702068269                                                  

-----------------------------------------------------------------------------
| Id  | Operation           | Name  | Starts | E-Rows | A-Rows |   A-Time   |
-----------------------------------------------------------------------------
|   1 |  NESTED LOOPS       |       |      0 |    100 |      0 |00:00:00.01 |
|   2 |   VIEW              |       |      0 |    100 |      0 |00:00:00.01 |
|   3 |    TABLE ACCESS FULL| T2    |      0 |    100 |      0 |00:00:00.01 |
|*  4 |   INDEX RANGE SCAN  | T1_N1 |      0 |      1 |      0 |00:00:00.01 |
|   5 |  FAST DUAL          |       |      1 |      1 |      1 |00:00:00.01 |
-----------------------------------------------------------------------------

Oops! Oracle does not report the plan statistics of the query executed in the cursor expression. Why? Not sure. Maybe some implementation limit. Looks like Oracle does not sum up the workloads of recursive query in this special case.  Another limitation of plan statistics besides the parallel execution.

Don’t forget above pitfalls when using cursor expression.





Written by Dion Cho

February 25, 2009 at 12:19 pm

Follow

Get every new post delivered to your Inbox.

Join 62 other followers