Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Archive for the ‘Misc.’ Category

Underperformance of V$SQL_OPTIMIZER_ENV

with 8 comments

A couple of days ago, I was trying to search the non-default optimizer environments(aka. parameters) of a specific SQL query which has multiple child cursors. But it soon turned out that it’s almost impossible to search this simple view just because of the underperformance.

Followings are what I mean.

1. Create simple objects and gather statistics with histogram.

TPACK@ukja1106> select * from v$version;

BANNER
------------------------------------------------------------------------

Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production

TPACK@ukja1106> create table t1(c1 int, c2 int);

Table created.

TPACK@ukja1106> 
TPACK@ukja1106> insert into t1 select level, mod(level,5) from dual
  2  connect by level <= 10000;

10000 rows created.

TPACK@ukja1106> 
TPACK@ukja1106> create index t1_n1 on t1(c1);

Index created.

TPACK@ukja1106> 
TPACK@ukja1106> exec dbms_stats.gather_table_stats(user, 't1', method_opt=>'for columns size 5 c1 size 5 c2');

PL/SQL procedure successfully completed.

2. Now I create 200 child cursors for a simple query using the notorious combination of SIMILAR cursor sharing and histogram.

TPACK@ukja1106> -- session #1
TPACK@ukja1106> alter session set cursor_sharing = similar;

Session altered.

TPACK@ukja1106> 
TPACK@ukja1106> declare
  2    v_cnt   number;
  3  begin
  4    for idx in 1 .. 200 loop
  5      execute immediate 'select count(*) from t1 where c1 = ' || idx || ' and c2 = ' || idx
  6        into v_cnt;
  7    end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Now I have 200 child cursors.

TPACK@ukja1106> -- version count
TPACK@ukja1106> select version_count from v$sqlarea where sql_id = '&sql_id';

VERSION_COUNT
-------------
          200

3. But the problem is that simple search on V$SQL_OPTIMIZER_ENV is extremely slow. Following simple lookup takes 17.3 sec to be accomplished.

TPACK@ukja1106> -- get sql optimizer env
TPACK@ukja1106> select count(*) from v$sql_optimizer_env
  2  where sql_id = '&sql_id' and child_number = &child_number;

  COUNT(*)
----------
        37

Elapsed: 00:00:17.29

The bigger problem is that this simple query eats up 100% of CPU and makes the whole system hang with the library cache related contention as the count of the child cursors increases. Restarting the instance was the only way to continue my test.

4. The query follows the effective index range scan on the fixed index. No more tuning available.

TPACK@ukja1106> explain plan for
  2  select count(*) from v$sql_optimizer_env
  3  where sql_id = '&sql_id' and child_number = &child_number;

-----------------------------------------------------------------------------------------------
| Id  | Operation                | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                    |     1 |    47 |     0   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE          |                    |     1 |    47 |            |          |
|*  2 |   FIXED TABLE FIXED INDEX| X$KQLFSQCE (ind:2) |     1 |    47 |     0   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter("KQLFSQCE_SQLID"='ftg19cu1jf8st' AND "KQLFSQCE_CHNO"=0 AND
              "INST_ID"=USERENV('INSTANCE') AND BITAND("KQLFSQCE_FLAGS",8)=0 AND
              (BITAND("KQLFSQCE_FLAGS",4)=0 OR BITAND("KQLFSQCE_FLAGS",2)=0))

5. Querying the time model and latch activity tells nothing meaningful. It would have been an aggressive mutex activity which made my laptop hang as this is 11g enviroment.

TIME       DB time                                     17572455
TIME       sql execute elapsed time                    17562899
TIME       DB CPU                                      17500000

LATCH      session allocation                             31344
LATCH      DML lock allocation                            21187
LATCH      row cache objects                              12711
LATCH      shared pool                                     9956
LATCH      cache buffers chains                            8095

I’ve profiled the callstack and got nothing meaningful. It just shows the API call for the X$VIEW lookup.

STACK_TRACE                                                                         HIT_CNT    HIT_PCT
-------------------------------------------------------------------------------- ---------- ----------
00000000                                                                                 10        100
 ->7C80B710
  ->_OracleThreadStart@4()
   ->_opimai()
    ->_opimai_real()
     ->_sou2o()
      ->_opidrv()
       ->_opiodr()
        ->_opiino()
         ->_opitsk()
          ->_ttcpip()
           ->_opiodr()
            ->_kpoal8()
             ->_opifch2()
              ->_qergsFetch()
               ->_qerfxFetch()
                ->_kqlfsqce()
                 ->_kglic()
                  ->_kglic0()
                   ->_kgligi()
                    ->_kqlfsqcet()  <-- X$VIEW
                     ->_kghalf()
                      ->00000000
                       ->7C80B710
                        ->_OracleOradebugThreadStart@4()
                         ->_ssthreadsrgruncallback()
                          ->_ksdxcb()
                           ->_ksdxfdmp()
                            ->_ksedst_tracecb()
                             ->_ksedst1()
                              ->_skdstdst()

This problem was reproducible only when the query has many(over 200?) child cursors. And the V$[SYS|SES]_OPTIMIZER_ENV view did not have such problem.

Metalink didn’t give any bug related to V$SQL_OPTIMIZER_ENV. So I suspect that this is not a bug, but the lookup code for the view has some under-optimized part on which I have no control.

— Appended : 2010/5/20
This behavior is likely to be dependent on versions. I would share the result of more comprehensive tests on this in case something meaningful found.

— Appended : 2010/5/28
It looks like OS problem. More specifically, this unpderperformance took only in Oracle on Windows. Didn’t have a chance to dig it in more detail.

Written by Dion Cho

May 20, 2010 at 2:21 am

Posted in Misc.

Tagged with

Finding out the row cache lock holder through V$ view

with 2 comments

Hanganalyze is always the best tool for finding row cache lock holder as following.

connect sys/oracle as sydba

oradebug setmypid
oradebug hanganalyze 3


-- trace file
==============
HANG ANALYSIS:
==============
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
    <0/158/44363/0x3424fb7c/5504/No Wait>
 -- <0/134/928/0x3424f58c/4600/row cache lock>

Am I able to find out the row cache lock holder only through V$ views? The answer is YES and it’s what V$ROWCACHE_PARENT view is meant for.

Let me explain with simple test case.

Create a sequence object with NOCACHE attribute and let two sessions invoke the sequence.nextvalue function recursively. Oracle needs to hold the row cache lock in 5(SRX) mode when calling NEXTVALUE on the nocached sequence, which means it’s very easy to replay the row cache lock contention.

create sequence s1 nocache;

-- temp.sql
declare
 v_value   number;
begin
  for idx in 1 .. 100000 loop
   select s1.nextval into v_value from dual;
  end loop;
end;
/

ho start sqlplus ukja/ukja@ukja1021 @temp
ho start sqlplus ukja/ukja@ukja1021 @temp

Now query on the V$ROWCACHE_PARENT view like following and you get the ID of the row cache lock holder.

col sid new_value sid

select h.address, h.saddr, s.sid, h.lock_mode
from v$rowcache_parent h, v$rowcache_parent w, v$session s
where h.address = w.address and
			w.saddr = (select saddr from v$session where event = 'row cache lock' 
									and rownum = 1) and
			h.saddr = s.saddr and
			h.lock_mode > 0
;

ADDRESS  SADDR           SID  LOCK_MODE
-------- -------- ---------- ----------
283AFB50 3432EB34        145          5

With the session id found out, it’s not a big deal to get the detailed information on the holder session.

UKJA@ukja1021> @session &sid
UKJA@ukja1021> set echo off
01. basic session info
SID                           : 145
SERIAL#                       : 447
SPID                          : 2328
MACHINE                       : POWER_GROUP\UKJAX
PROGRAM                       : sqlplus.exe
PGA                           : 515668
UGA                           : 156280
LAST_CALL_ET                  : 13
LOGON_TIME                    : 2009/10/15 13:50:31
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.03
02. session wait
SID                           : 145
EVENT                         : row cache lock
P1                            : 13
P1RAW                         : 0000000D
P2                            : 0
P2RAW                         : 00
P3                            : 5
P3RAW                         : 00000005
SECONDS_IN_WAIT               : 0
STATE                         : WAITING
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
03. process info
PID                           : 23
PROGRAM                       : ORACLE.EXE (SHAD)
PGA_USED_MEM                  : 324361
PGA_ALLOC_MEM                 : 623853
PGA_MAX_MEM                   : 623853
-----------------

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
04. sql info
SID                           : 141
SHARABLE_MEM                  : 8640
PERSISTENT_MEM                : 1156
RUNTIME_MEM                   : 592
EXECUTIONS                    : 100000
FETCHES                       : 100000
BUFFER_GETS                   : 403341
SQL_TEXT                      : SELECT S1.NEXTVAL FROM DUAL
-----------------


05. sql plan info

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------

SQL_ID  8c3n1ysfzzd1z, child number 0
-------------------------------------
SELECT S1.NEXTVAL FROM DUAL

Plan hash value: 2479889702

-----------------------------------------------------------------
| Id  | Operation        | Name | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------
|   0 | SELECT STATEMENT |      |       |     2 (100)|          |
|   1 |  SEQUENCE        | S1   |       |            |          |
|   2 |   FAST DUAL      |      |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------
...

Well, it’s just good to find out the usage of the view whose usage is never well known. :)

Written by Dion Cho

October 15, 2009 at 6:44 am

Posted in Misc.

Tagged with ,

DBMS_ADVANCED_REWRITE and DML

with 5 comments

Oracle 10g has introduced DBMS_ADVANCED_REWRITE package which enables a specific query to be transformed to another form. Very powerful feature, but this is designed for DW not OLTP. Thus has following restrictions.

  1. Does not work with the bind variables.(Metalink Doc ID. 392214.1)
  2. Only works for the SELECT statement.
  3. Does not work when the base table is modified through DML.

It’s not well known how to avoid 3rd restriction. The only way I got from some test cases is to use QUERY_REWRITE_INTEGRITY parameter.

Let me explain through simple test case.

1. Make objects.

UKJA@ukja1106> create table t1
  2  as select level as c1, level as c2
  3  from dual
  4  connect by level <= 1000;

Table created.

Elapsed: 00:00:00.04

UKJA@ukja1106> create index t1_n1 on t1(c1);

Index created.

Elapsed: 00:00:00.03

UKJA@ukja1106> exec dbms_stats.gather_table_stats(user,'t1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.18

2. The SELECT statement has FULL hint and (naturally) follows full table scan.

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |     7 |    10   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |     7 |    10   (0)| 00:00:01 |
--------------------------------------------------------------------------

3. How to fix it? DBMS_ADVANCED_REWRITE package would give you the power to change the SELECT statement on the fly with QUERY_REWRITE_INTEGRITY parameter set to TRUSTED.

UKJA@ukja1106> begin
  2  
  3  	     sys.dbms_advanced_rewrite.declare_rewrite_equivalence(
  4  	     'test_rewrite',
  5  	     'select /*+ full(t1) */ * from t1 where c1 = 1',
  6  	     'select /*+ index(t1) */ c1, c2 from t1 where c1 = 1',
  7  	     false,
  8  	     'text_match');
  9  end;
 10  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01

UKJA@ukja1106> alter session set query_rewrite_integrity=trusted;

Session altered.

Elapsed: 00:00:00.00

4. Now you have a plan with magical index range scan.

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |     1 |     7 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1    |     1 |     7 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T1_N1 |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

5. But one simple DML would prevent rewrite from happening.

UKJA@ukja1106> insert into t1 values(1, 1);

1 row created.

Elapsed: 00:00:00.00

UKJA@ukja1106> commit;

Commit complete.

Elapsed: 00:00:00.00

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |     7 |    10   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |     7 |    10   (0)| 00:00:01 |
--------------------------------------------------------------------------

6. One way to avoid this restriction is to set QUERY_REWRITE_INTEGRITY parameter to STALE_TOLERATED.

UKJA@ukja1106> alter session set query_rewrite_integrity=stale_tolerated;

Session altered.

Elapsed: 00:00:00.00

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |     1 |     7 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1    |     1 |     7 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T1_N1 |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

7. Now DML does not prevent the rewrite from happening.

UKJA@ukja1106> insert into t1 values(1, 1);

1 row created.

Elapsed: 00:00:00.01

UKJA@ukja1106> commit;

Commit complete.

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |     1 |     7 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1    |     1 |     7 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T1_N1 |     1 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

8. But here you have another restriction. If the DML is not committed, the rewrite would fail even with STALE_TOLERATED setting.

UKJA@ukja1106> insert into t1 values(1, 1);

1 row created.

Elapsed: 00:00:00.01

UKJA@ukja1106> explain plan for
  2  select /*+ full(t1) */ * from t1 where c1 = 1;

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     1 |     7 |    10   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T1   |     1 |     7 |    10   (0)| 00:00:01 |
--------------------------------------------------------------------------

Hm… there seems to be really many restrictions for OLTP, but these would not make any problem for DW. But I believe that even OLTP would get a big and good effect when used in the right place.

Footnote:It makes me a bit gloomy not to post on OOW events but on these little tips. Well, the only consolation is that San Francisco is very far from here and I really hate long-distance journey. :(

Written by Dion Cho

October 13, 2009 at 5:43 am

Posted in Misc.

Tuning query on the fixed table

with 2 comments

Oracle performance monitoring is very oftenly followed by querying on the fixed table(x$ table). Query on the fixed table means a direct access on the SGA memory area, which means the promised efficiency.

But this does not mean that you don’t need to care about the performance. Reading memory is fast, but hundreds of megabytes of memory makes the situation far worse than you imagine. Just for this reason, many fixed tables have indexes.

UKJA@ukja1021> desc v$indexed_fixed_column
           Name                            Null?    Type
           ------------------------------- -------- ----------------------------
    1      TABLE_NAME                               VARCHAR2(30)
    2      INDEX_NUMBER                             NUMBER
    3      COLUMN_NAME                              VARCHAR2(30)
    4      COLUMN_POSITION                          NUMBER

For instance, X$KGLOB table which represents the list of LCO(Library Cache Object) has following two indexes.

UKJA@ukja1021> exec print_table('select * from v$indexed_fixed_column -
> 		  where table_name = ''X$KGLOB''');
TABLE_NAME                    : X$KGLOB
INDEX_NUMBER                  : 1
COLUMN_NAME                   : KGLNAHSH
COLUMN_POSITION               : 0
-----------------
TABLE_NAME                    : X$KGLOB
INDEX_NUMBER                  : 2
COLUMN_NAME                   : KGLOBT03
COLUMN_POSITION               : 0
-----------------

We have indexes on SQL Hash Value(KGLNAHSH) and SQL ID(KGLOBT03) columns. This means that you should always try to query X$KGLOB table through these two columns.

Here I make a simple test case to demonstrate the usefulness of the indexes on the fixed table.

1. Execute a simple SQL statement and extract SQL ID.

UKJA@ukja1021> select * from t1;

no rows selected

Elapsed: 00:00:00.00
UKJA@ukja1021> col sql_id new_value sql_id
UKJA@ukja1021> select regexp_replace(plan_table_output,
  2  				     'SQL_ID[[:blank:]]+([[:alnum:]]+),.*', '\1') as sql_id
  3  from table(dbms_xplan.display_cursor)
  4  where plan_table_output like 'SQL_ID%';

SQL_ID
--------------------------------------------------------------------------------
27uhu2q2xuu7r

2. Execute two SQL statements which query X$KGLOB table through KGNAOBJ(without index) and KGLOBT03(with index) column respectively.

UKJA@ukja1021> select count(*) from sys.xm$kglob
  2  where kglnaobj = 'select * from t1';

  COUNT(*)
----------
         2

Elapsed: 00:00:00.06
UKJA@ukja1021> 
UKJA@ukja1021> select count(*) from sys.xm$kglob
  2  where kglobt03 = '&sql_id';
old   2: where kglobt03 = '&sql_id'
new   2: where kglobt03 = '27uhu2q2xuu7r'

  COUNT(*)
----------
         2

Elapsed: 00:00:00.01

3. TKPROF result on both of the SQL statements.

select count(*) from sys.xm$kglob
where kglnaobj = '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        2      0.06       0.05          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.06       0.05          0          0          0           1

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=0 pr=0 pw=0 time=59402 us)
      2   FIXED TABLE FULL X$KGLOB (cr=0 pr=0 pw=0 time=43810 us)

select count(*) from sys.xm$kglob
where kglobt03 = '27uhu2q2xuu7r'

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        2      0.00       0.00          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          0          0           1

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=0 pr=0 pw=0 time=167 us)
      2   FIXED TABLE FIXED INDEX X$KGLOB (ind:2) (cr=0 pr=0 pw=0 time=120 us)

Interpretation:

  • Logical reads is 0 on both cases.Fixed table is read by direct access on the memory not by scanning database blocks. For this reason logical reads has no meaning here.
  • Execution plan cleary shows that the first one follows full scan(FIXED TABLE FULL) and the second one follows index scan(FIXED TABLE FIXED INDEX (ind:2)).
  • This makes the difference of 0.05s and 0s of the elapsed time.

Keep in mind the fact that the traditional way of comparing the logical reads is useless in this test case.

4. My personal monitoring script shows following additional info.

@mon_on userenv('sid')

select count(*) from sys.xm$kglob
where kglnaobj = 'select * from t1';

@mon_off

select count(*) from sys.xm$kglob
where kglobt03 = '&amp;sql_id';

@mon_off2
@mon_show2
...
02. time model

STAT_NAME                                   VALUE1         VALUE2           DIFF
----------------------------------- -------------- -------------- --------------
DB time                                    166,458        115,196        -51,262
sql execute elapsed time                   164,356        113,308        -51,048
DB CPU                                     134,972        103,749        -31,223
...

03. latch

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
library cache                       -4186          0          0          0
row cache objects                     -45          0          0          0
enqueues                              -19          0          0          0
enqueue hash chains                   -18          0          0          0
...

The biggest difference lies on the library cache latchacquisition count. Full scan on X$KGLOB needs far more library cache latch acquisition than index scan. More scans on the memory means more CPU assumption, more latch acquisition and potential concurrency problem.

Carelessly written monitoring scripts are likely to make unwanted side effects especially without the knowledge on these facts. Even many commerical monitoring tools are making these kinds of mistakes.

Same principles can be applied to the dictionary views. Following post is reporting an interesting investigation on the performance of querying dictionary views.

Written by Dion Cho

September 29, 2009 at 8:09 am

Posted in Misc.

Tagged with

Reducing CLOB concatenation

with 5 comments

One of my customers had this requirement – producing a SQL statement dynamically whose text length is over 300KB(Do not blame me for this).

Their first PL/SQL code was like following.
(Let me tell you this is a very simplified version of their code)

UKJA@ukja1021> create or replace function make_long_sql(p_idx in number)
  2  return clob
  3  is
  4  	     v_clob	     clob;
  5  begin
  6  	     v_clob := 'select ';
  7  	     for idx in 1 .. p_idx loop
  8  		     v_clob := v_clob||to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';
  9  	     end loop;
 10  	     v_clob := v_clob || '1 from dual';
 11  
 12  	     return v_clob;
 13  end;
 14  /

Function created.

No special things. The code is just concatenating CLOB variable with a couple of strings.

But the performance was very disappointing. Following code takes 46sec.

UKJA@ukja1021> exec :c := make_long_sql(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:46.00  

Their actual PL/SQL code took over 5 minutes to make 150KB of SQL text. So they called me for help.

My prescription was to use temporary VARCHAR2 variable instead of direct CLOB concatenation, like following.

UKJA@ukja1021> create or replace function make_long_sql2(p_idx in number)
  2  return clob
  3  is
  4  	     v_clob	     clob;
  5  	     v_varchar	     varchar2(1000);  -- Note this
  6  begin
  7  	     v_clob := 'select ';
  8  	     for idx in 1 .. p_idx loop
  9  		     v_varchar := to_char(p_idx)||', '||to_char(p_idx+1)||','||to_char(p_idx+2)||',';  -- Use temporary VARCHAR2
 10  		     v_clob := v_clob||v_varchar;
 11  	     end loop;
 12  	     v_clob := v_clob || '1 from dual';
 13  
 14  	     return v_clob;
 15  end;
 16  /

Function created.

Here I have a dramatic result. The elapsed time got reduced from 42 sec to 0.5 sec.

UKJA@ukja1021> exec :c := make_long_sql2(10000);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.50

Their actual PL/SQL code now takes 5 sec instead of 5 min.

What makes this big difference? V$SESTAT view and V$LATCH view show some hints for this performance variation.

NAME                                           VALUE1       VALUE2         DIFF
---------------------------------------- ------------ ------------ ------------
session logical reads                      17,376,991      133,035  -17,243,956
db block gets from cache                   15,764,933      102,971  -15,661,962
db block gets                              15,764,933      102,971  -15,661,962
consistent changes                          6,024,802       17,697   -6,007,105
db block changes                            6,024,814       17,710   -6,007,104
consistent gets from cache                  1,612,058       30,064   -1,581,994
consistent gets                             1,612,058       30,064   -1,581,994
free buffer requested                       1,432,143           49   -1,432,094
calls to get snapshot scn: kcmgss             480,030       40,019     -440,011
lob writes                                    120,008       10,004     -110,004
lob writes unaligned                          119,962       10,004     -109,958
lob reads                                      60,001       10,001      -50,000
...

LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
cache buffers chains            -45091211          0          0   -1399062
object queue header operation    -2864253          0          0          0
cache buffers lru chain          -2864138          0          0          0
simulator hash latch              -164417          0          0          0
simulator lru latch               -112459          0          0     -51952
...

Do you see the difference between logical reads, LOB reads and LOB writes? Also of the latch acquistion?

Jonathan Lewis has already given a good explanation here.
http://jonathanlewis.wordpress.com/2009/07/09/concatenating-lobs/

There are a couple of things you should keep in mind when using CLOB for producing a big SQL statement, and this post is just abount one of them. I would cover other stuffs in detail next time.

Written by Dion Cho

August 22, 2009 at 12:25 am

Posted in Misc.

Difficulty of making reproducible test case

with 2 comments

Let me show you the difficulty of making reproducible test case.

First of all, take a look at following OTN forum.

The test case authored by Tom Kyte is so famous and natural that it is really hard to find out the flaws. But even this kind of historically proven simple test case fails at being a reproducible test case.

See following test case why it is that difficult to make a reproducible test case.

1. My Oracle

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

2. Create small undo tablespace to make it easy to hit ORA-01555 error.

alter system set undo_tablespace=UNDOTBS1;

drop table t purge;
create table t as select * from all_objects;  
create index t_idx on t(object_id);

drop tablespace small_undo including contents and datafiles;
create undo tablespace small_undo datafile size 200k;

alter system set undo_tablespace=SMALL_UNDO;
alter system flush buffer_cache;

3. Following is one of the most famous test case that is promised to hit ORA-01555 error, but…

UKJA@ukja102> begin
  2          for x in ( select * from t where object_id > 0 )
  3          loop
  4                  update t set object_name = lower(object_name)
  5                    where object_id = x.object_id and rownum=1;
  6                  commit;
  7          end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.  -- Why no ORA-01555???

It does not hit ORA-01555. What is happening here?

4. One of the reasons is that in the recent versions of Oracle, the select statement in the above test case takes table full scan, not index scan.

explain plan for select * from t where object_id > 0;

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      | 50000 |  4541K|   186  (17)| 00:00:03 |
|*  1 |  TABLE ACCESS FULL| T    | 50000 |  4541K|   186  (17)| 00:00:03 |
--------------------------------------------------------------------------

With full table scan working, Oracle would read the blocks sequentially and do not have repeated visit on the blocks modified by the internal update. So we would have very low chance to hit ORA-01555 error.

5. Okay, now I give INDEX hint to force the index scan, but Oracle still denies to produce ORA-01555.

UKJA@ukja102> create table t as select * from all_objects where rownum <= &1;
old   1: create table t as select * from all_objects where rownum <= &1
new   1: create table t as select * from all_objects where rownum <= 1000

Table created.

UKJA@ukja102> begin
  2          for x in ( select /*+ index(t) */ * from t where object_id > 0 )
  3          loop
  4                  update t set object_name = lower(object_name)
  5                    where object_id = x.object_id and rownum=1;
  6                  commit;
  7          end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.   -- Again no ORA-01555 error?

6. The reason is that the number of 1000 rows is too small to overwrite the undo which the select statement needs. For 10000 rows, we finally hit ORA-01555.

UKJA@ukja102> create table t as select * from all_objects where rownum <= &1;
old   1: create table t as select * from all_objects where rownum <= &1
new   1: create table t as select * from all_objects where rownum <= 10000

Table created.

UKJA@ukja102> begin
  2          for x in ( select /*+ index(t) */ * from t where object_id > 0 )
  3          loop
  4                  update t set object_name = lower(object_name)
  5                    where object_id = x.object_id and rownum=1;
  6                  commit;
  7          end loop;
  8  end;
  9  / 
begin
*
ERROR at line 1:
ORA-01555: snapshot too old: rollback segment number  with name "" too small
ORA-06512: at line 2

When you have small number of objects in your database, the test case would not work at all.

7. There would be many other restrictions when Oracle does not hit ORA-01555.

What makes me shocked(as always) is that making reproducible test case(anywhere, anytime) is really difficult thing even with very simple scenarios. So you need to be very careful when you give someone a test case – it would have many restrictions and flaws than you’ve imagined.

Written by Dion Cho

August 4, 2009 at 10:18 am

Posted in Misc.

Serial Direct Path Read and Block Cleanout(11g)

with 2 comments

Chris Antognini posted an article about the serial direct path read and repeated block cleanout problem here. I’d just like to add my own interpretation on this phenomenon.

In summary,

  1. Oracle needs to cleanout the dirty blocks to determine the status of the block and rolls them back if necessary.
  2. But it does not mean that Oracle modifies the dirty blocks. It just checks the status of the dirty blocks.
  3. So, it does not generate redo and does not physically cleanout the dirty blocks.

Following is the the result of block dump which helps you to understand exactly when Oracle physically modifies the dirty block.

-- before update
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0007.00a.000036ed  0x00c0032b.1929.08  C---    0  scn 0x07df.2427c615
0x02   0x0000.000.00000000  0x00000000.0000.00  ----    0  fsc 0x0000.00000000

-- after update
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0007.00a.000036ed  0x00c0032b.1929.08  C---    0  scn 0x07df.2427c615
0x02   0x0006.001.0000480a  0x00c010b1.17f3.02  ----    1  fsc 0x0000.00000000 (cleanout is delayed)

-- after direct path read
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0007.00a.000036ed  0x00c0032b.1929.08  C---    0  scn 0x07df.2427c615
0x02   0x0006.001.0000480a  0x00c010b1.17f3.02  ----    1  fsc 0x0000.00000000 (wasn't cleaned out)

-- after conventional path read
 Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
0x01   0x0007.00a.000036ed  0x00c0032b.1929.08  C---    0  scn 0x07df.2427c615
0x02   0x0006.001.0000480a  0x00c010b1.17f3.02  C---    0  scn 0x07df.2427ffae (was cleaned out)

Statistics shows another insight.
(block count# is 6010 in my test case)

-- after direct path read
consistent gets from cache                      6,025
consistent gets - examination                   6,011
immediate (CR) block cleanout applicatio        6,010
ns                                                   
cleanout - number of ktugct calls               6,010
cleanouts only - consistent read gets           6,010
commit txn count during cleanout                6,010
redo size                                       4,112

-- after conventional read
redo size                                     438,084
session logical reads                          12,103
consistent gets                                12,076
consistent gets from cache                     12,076
redo entries                                    6,025
consistent gets - examination                   6,016
cleanout - number of ktugct calls               6,016
cleanouts only - consistent read gets           6,010
immediate (CR) block cleanout applicatio        6,010
ns                                                   
commit txn count during cleanout                6,010
consistent gets from cache (fastpath)           5,668

We can tell that Oracle internally cleans out the dirty blocks from the statistics. But the serial direct path read does not load the current version of the block into the buffer cache. So it cannot modify the current block. It just reads the disk-version of the blocks from the data file and refers to the undo to cleanout the dirty blocks.

I think that it is unfair to call this a problem, but under certain situation it might cause problems like ORA-01555 error or repeated reads on the undo.

Footnote1:The traditional term of cleanout meant the modification on the dirty block to me, but I realized that I need more sophiscated terminology.

Footnote2: I believe that the parallel direct path read has the same design and feature with regard to the cleanout mechanism.

Written by Dion Cho

July 29, 2009 at 4:15 am

Posted in I/O, Misc.

Tagged with ,

Follow

Get every new post delivered to your Inbox.

Join 68 other followers