Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Archive for the ‘Wait Event’ Category

Disabling direct path read for the serial full table scan – 11g

with 11 comments

It’s a good news – Oracle 11g has implemented direct path read for the serial full table scan!

But I don’t like this kind of one-way optimization. What I want is to enable/disable it whenever I want it – putting Oracle under my control.

So I had a research for a couple of hours and found how to disable it. Oracle 11g has introduced 10949 event to control this.

UKJA@ukja116> @oerr 10949
10949                                                                           
 "Disable autotune direct path read for full table scan"                        
// *Cause:                                                                      
// *Action:  Disable autotune direct path read for serial full table scan.      
//                                                                              

Here is a simple and dirty example how to use this event.

1. Create a table big enough to meet the threshold which seems to be 5 * _small_table_threshold.

UKJA@ukja116> col value new_value sth
UKJA@ukja116> @para small_table
old   9: and i.ksppinm like '%&1%'
new   9: and i.ksppinm like '%small_table%'

NAME                           VALUE                IS_DEFAUL SES_MODIFI        
------------------------------ -------------------- --------- ----------        
SYS_MODIFI                                                                      
----------                                                                      
DESCRIPTION                                                                     
--------------------------------------------------------------------------------
_small_table_threshold         637                  TRUE      true              
deferred                                                                        
threshold level of table size for direct reads                                  
                                                                                
Elapsed: 00:00:00.04
UKJA@ukja116> 
UKJA@ukja116> create table t1(c1 number, c2 char(2000), c3 char(2000), c4 char(2000));

Table created.

Elapsed: 00:00:00.21
UKJA@ukja116> insert into t1
  2  select level, 'x', 'x', 'x'
  3  from dual connect by level <= 10 + 5*&sth;
old   3: from dual connect by level <= 10 + 5*&sth
new   3: from dual connect by level <= 10 + 5*637

3195 rows created.

Elapsed: 00:00:01.14
UKJA@ukja116> commit;

Commit complete.

Elapsed: 00:00:00.00
UKJA@ukja116> @gather t1
UKJA@ukja116> exec dbms_stats.gather_table_stats(user, '&1', no_invalidate=>false);

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.68

2. Now I compare the wait event(direct path read vs. db file scattered read) of the two queries – one with 10949 disabled(default) and the other with 10949 enabled.

-- case#1
alter system flush buffer_cache;
alter session set events '10046 trace name context forever, level 8';
select count(*) from t1;

-- case#2
alter system flush buffer_cache;
alter session set events '10046 trace name context forever, level 8';
alter session set events '10949 trace name context forever, level 1';
select count(*) from t1;

3. Do you see that 10949 enabled one behaves just like the previous version? The famous db file scattered read event!

SQL ID : 5bc0v4my7dvr5
select count(*) 
from
 t1

-- Case #1
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file sequential read                         3        0.02          0.04
  db file scattered read                          1        0.02          0.02
  direct path read                              231        0.29          1.67
  SQL*Net message from client                     2        0.03          0.03


-- Case #2
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  db file scattered read                        213        0.26          1.77
  SQL*Net message from client                     2        0.00          0.00

Don’t forget 10949 event when you want to disable this great feature for any reason!

Footnote1:What you should keep in mind is that this is not a CBO feature but a runtime execution engine feature. It would always show the same execution plan – TABLE ACCESS FULL. When the execution engine runs this operation, it determines how to read the table(direct path read or conventional path read) considering various factors.

Footnote2:There is “_serial_direct_read” parameter which forces the full scan on the big table to be a direct read – The opposite of 10949 event.

Advertisements

Written by Dion Cho

July 21, 2009 at 3:38 am

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

When do we have SQL*Net message from dblink wait events?

with 3 comments

One of my colleagues asked me a very simple question like this.

When I execute the query containing dblink, exactly when do I have to wait the “SQL*Net message from dblink” event?

Simple, at first thought, but at second thought, it made me dumb.

So I made a very simple test case to investigate how Oracle processes the remote query. Here is my simple but stupid demonstration.

1. Make a query which needs long hard parse time. Following query joins 211 tables and needs tens of seconds to be optimized.

select count(*) from T_HIST@UKJA102, T_NO_PART@UKJA102, T_PART1@UKJA102,        
T_PART2@UKJA102, T_PART3@UKJA102, T_CURSOR@UKJA102, T_SOURCE@UKJA102,           
MV_SOURCE@UKJA102, RUN_STATS@UKJA102, T_BUG2@UKJA102, ..., T_PRED1@UKJA102,
 dual@UKJA102 where 1 = 0;                     



2. Genereate 2 10046 trace files. One with hard parse, the other with soft parse, like this.

connect id/pwd
alter session set events '10046 trace name context forever, level 8';
execute_above_long_parsed_remote_query;  -- this would be hard parse

connect id/pwd
alter session set events '10046 trace name context forever, level 8';
execute_above_long_parsed_remote_query;  -- this would be soft parse


From the trace files, I got following conclusion.
(This is a conclusion just based on my simple test case. Do not take it as a fact)

  • In the soft parse phase(syntax check would be more appropriate expression), Oracle needs to have dblink communications to identify the remote objects. In my simple test case with 211 remote objects involved, Oracle exchanged 432 messages. Hence 432 SQL*Net message from dblink wait events.
  • In the hard parse phase(optimization would be more appropriate expression), Oracle sends the remote-part query and waits for the remote database to optimize the query(if not yet optimized). Hence one long SQL*Net message from dblink here.
  • In the fetch phase, as we already know, Oracle communicates with the remote database to retrieve the data. More fetches, more SQL*Net message from dblink events.



One thing to note is that Oracle always needs to validate the remote objects without regard to the hard parse being existent. In the above test case, Oracle always does 423 dblink communication at minimum before executing the query.

I’ve thought that the process waiting for the SQL*Net message from dblink is always in the fetch phase, but above test case made me realize it was too naive assumption. I would like to have more detailed and delicate investigation on this topic next time.

PS) And, the terminology of soft parse and hard parse is always confusing. It’s not technologically strict, but looks like kind of marketing term.

Written by Dion Cho

May 26, 2009 at 8:39 am

Releasing library cache pin

with 12 comments

Interesting question from one of my customers.

One of the sessions was killed in the process of debugging a procedure with Toad. But the library cache pin continued to be hold and couldn’t recompile or modify the procedure.

Even “shutdow immediate” got blocked, so the only one I could do was “shutdown abort”.

Why is this happening and how do I force the release of the library cache pin.

The answer is simple and clear.


When the session got termininated unsuccessfully hodling library cache pin, there is a chance that library cache pin is still hold. Killing the corresponding perfectly would release the library cache pin.

What does this mean? I’ve built up very simple test case to prove my viewpoint.

-- Session #1
-- Create procedure PROC1 which sleeps 1000 sec
UKJA@ukja102> create or replace procedure proc1
  2  is
  3  begin
  4     dbms_lock.sleep(1000);
  5
  6  end;
  7  /

Procedure created.


-- Execute procedure proc1. It would be blocked due to the TX lock contention.
-- And kill the session simply with Ctrl+C
-- The problem is that killing session with Ctrl+C(especially on Windows)
-- does not actually kill the corresponding process.
UKJA@ukja102> exec proc1;
^C
C:\Documents and Settings\exem>sqlplus ukja/ukja@ukja102

-- Session #2
-- Okay, now the session #1 got killed. 
-- But how about the procedure itself? Is it terminated or alive?
SYS@ukja10> @lock_internal 144 PROC1

       SID TY handle            mod        req NAME
---------- -- ---------- ---------- ---------- ------------------------------
       142 LK 2A3557A8            1          0 PROC1
       142 LN 2A3557A8            2          0 PROC1  <-- Here!

SYS@ukja10> @lco 2A3557A8 %

KGLHDADR                      : 2A3557A8
KGLNAOBJ                      : PROC1
TYPE                          : Parent
LOCK_HOLDER                   : 142
KGLLKMOD                      : 1
KGLLKREQ                      : 0
PIN_HOLDER                    : 142
KGLPNMOD                      : 2    <-- Here
KGLPNREQ                      : 0
-----------------

PL/SQL procedure successfully completed.

-- The session is alive holding the shared library cache pin on the PROC1.
-- No change on the procedure is allowed. Ouch!
-- It would be alive forever without proper cleanout for the corresponding resources.

-- Session #2
-- Kill the corresponding process(thread) using orakill
-- On unix, kill command
SYS@ukja10> ho orakill UKJA10 5288

Kill of thread id 5288 in instance UKJA10 successfully signalled.

-- After a couple of seconds, PMON would cleanout the resource of the killed process
-- And the library cache pin got released. 
UKJA@ukja102> @lco 2A3557A8 %
KGLHDADR                      : 2A3557A8
KGLNAOBJ                      : PROC1
TYPE                          : Parent
LOCK_HOLDER                   :
KGLLKMOD                      :
KGLLKREQ                      :
PIN_HOLDER                    :
KGLPNMOD                      :
KGLPNREQ                      :
-----------------

PL/SQL procedure successfully completed.



I hope that this simple and stupid test case clearly explains what I’m trying to say.
(lock_internal.sql is here and lco.sql is here)

I’m not sure why Toad did not release the libary cache pin in the above question. Debugging functionality given by Toad(and Oracle!) might have some critical sections that hold library cache pin on the procedure(which would be quite natural with debugging function) and fail to release it without proper termination process.




Written by Dion Cho

May 15, 2009 at 6:54 am

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 ,

Another way to use trace file

with 6 comments

I believe that many of you sometimes have strong need for customized trace analysis.

For instance, see following wait records of 10046 trace file.

...
WAIT #11: nam='buffer busy waits' ela= 4 file#=17 block#=2313 class#=8 obj#=81140 tim=520863116874
WAIT #11: nam='buffer busy waits' ela= 5456 file#=17 block#=2624 class#=1 obj#=81140 tim=520864249735
WAIT #11: nam='buffer busy waits' ela= 6 file#=17 block#=2569 class#=8 obj#=81140 tim=520864249933
...



What I want is to sort the buffer busy waits events by the class# like this:

CLASS#            CNT ELAPSED
---------- ---------- -------
8                1456    3.01
1                 420    1.54
4                   5     .00
35                  2     .00
77                  1     .00



But traditional tkprof has no such things. So what can I do? Hire developer? Do some excelling?

Nope. My approach is totally 100% SQL based, which is quite natural and easy for me. :) Most of all, it’s totally free. :)

Let’s see how I do it.

1. Create directory and array

-- create directory and varchar2 array
col value new_value user_dump_directory;

select value from v$parameter where name = 'user_dump_dest';

create or replace directory user_dump_dir as '&user_dump_directory';

create or replace type varchar2_array as table of varchar2(4000);
/



2. Create pipelined table function with utl_file package. If you’re not familiar with pipelined table function, visit here.

-- create get_trace_file1 function
create or replace function get_trace_file1(s_id number default userenv('sid'))
return varchar2_array
pipelined
as
  v_handle  utl_file.file_type;
  v_filename  varchar2(2000);
  v_line      varchar2(4000);
begin
  -- get exact file_name
  select i.value||'_ora_'||p.spid||'.trc' into v_filename
  from v$process p, v$session s, 
    (select value from v$parameter where name = 'instance_name') i
  where p.addr = s.paddr 
        and s.sid = s_id
  ;
  
  v_handle := utl_file.fopen('USER_DUMP_DIR', v_filename, 'R', 32767);
  
  loop
    begin
      utl_file.get_line(v_handle, v_line);
    exception when no_data_found then
      exit;
    end;
    
    pipe row(v_line);
  end loop;
  
  return;
end;
/

-- create get_trace_file2 function
create or replace function get_trace_file2(file_name in varchar2)
return varchar2_array
pipelined
as
  v_handle  utl_file.file_type;
  v_line      varchar2(20000);
begin
  
  v_handle := utl_file.fopen('USER_DUMP_DIR', file_name, 'R', 32767);
  
  loop
    begin
      utl_file.get_line(v_handle, v_line);
    exception when no_data_found then
      exit;
    end;
    
    pipe row(v_line);
  end loop;
  
  return;
end;
/



3. Good. Let’s play with it

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

select count(*) from t1;

alter session set events '10046 trace name context off';

select * from table(get_trace_file1);

Dump file c:\oracle\admin\ukja10\udump\ukja10_ora_2820.trc
Thu Mar 19 15:10:10 2009
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU                 : 2 - type 586
Process Affinity    : 0x00000000
Memory (Avail/Total): Ph:1481M/3070M, Ph+PgF:3140M/4960M, VA:1359M/2047M
Instance name: ukja10

Redo thread mounted by this instance: 1

Oracle process number: 16

Windows thread id: 2820, image: ORACLE.EXE (SHAD)


*** ACTION NAME:() 2009-03-19 15:10:10.109
*** MODULE NAME:(SQL*Plus) 2009-03-19 15:10:10.109
*** SERVICE NAME:(UKJA10) 2009-03-19 15:10:10.109
*** SESSION ID:(157.1205) 2009-03-19 15:10:10.109
=====================
PARSING IN CURSOR #1 len=68 dep=0 uid=61 oct=42 lid=61 tim=172367882897 hv=740818757 ad='27e12b14'
alter session set events '10046 trace name context forever, level 8'
END OF STMT
...



4. Very cool. Now I sort the buffer busy waits event by class# like this.(Actually, not that elegant query)

col class# format a10
col elapsed format 99.99

with t as (
  select /*+ materialize */
    column_value as line, 
    instr(column_value, 'ela=') ei, 
    instr(column_value, 'file#=') fi,
    instr(column_value, 'block#=') bi,
    instr(column_value, 'class#=') ci,
    instr(column_value, 'obj#=') oi,
    instr(column_value, 'tim=') ti
  from table(get_trace_file2('trc_1.trc'))
  --from table(get_trace_file2('trc_2.trc'))
  where 
    instr(column_value, 'WAIT #2: nam=''buffer busy waits''') > 0
    --instr(column_value, 'WAIT #11: nam=''buffer busy waits''') > 0
)
select
  class# 
  , count(1) as cnt
  , sum(elapsed)/1000000 as elapsed
from
  (
    select
      substr(line, ei+4, fi-ei-4) as elapsed,
      substr(line, fi+6, bi-fi-6) as file#,
      substr(line, bi+7, ci-bi-7) as block#,
      substr(line, ci+7, oi-ci-7) as class#,
      substr(line, oi+5, ti-oi-5) as obj#,
      substr(line, ti+4) as tim
    from
      t 
  ) x
group by 
  class#
order by 
  2 desc, 3 desc
;



What I’m actually doing is:

  1. trc_1.trc file contains the 10046 trace result with 40K extent size in ASSM.
  2. trc_2.trc file contains the 10046 trace result with 10M extent size in ASSM.
  3. 10 concurrent sessions insert into the table with 10046 trace enabled.
  4. I’d like to analyze how extent size affects the pattern of buffer contention.

Here is the result.

-- when extent size is 40K
CLASS#            CNT ELAPSED
---------- ---------- -------
8                 285    1.40
1                 215    4.64
4                  42     .01
9                   2     .00
19                  1     .00
33                  1     .00

-- when extent size is 10M
CLASS#            CNT ELAPSED
---------- ---------- -------
8                1456    3.01
1                 420    1.54
4                   5     .00
35                  2     .00
77                  1     .00



See the diffference. With big extent size, we have major buffer contention on 1st level bitmap block(8). With (too) smaller extent size, the major contention is on data block(1).

Hm… What does this mean? Well, it’s not the topic. :)

My point here is that Oracle has more funtionality than you imagine. Simple tricks with pipelined table function and utl_file package made it possible for me to analyze the whole new pattern of wait events.

PS) Instead of pipelined table function, the external table is also feasible. But I believe that the pipeline table function version is far more elegant.

Written by Dion Cho

March 19, 2009 at 6:49 am

Heavy reads on the library cache related v$ views.

with 6 comments

Riyaji posted a very interesting case here.

I have similar experience in my customer sites that a specific query which was designed to monitor the library cache suddenly got extremely slow and made the whole system perform poor.

When implementing the library cache/shared pool monitoring query, 2 things borne in mind.

  • When poorly designed, the query would require CPU and latch acquisition very aggressively, which would result in the heavy latch contention.
  • Because this query reads the memory structure(library cache/shared pool), no logical reads would be reported. It would be very confusing at first time – the query with high CPU usage is not reading anything at all?

Here is a simple demonstration.

@mon_on userenv('sid')

-- Poorly designed query on the library cache
select /*+ ordered use_nl(s1, s2) */ 
  count(*)
from v$sql s1, v$sql s2
;

@mon_off

@mon_show

-- Notice that only 40 logical reads reported
01. statistics
NAME                                             DIFF       VALUE1       VALUE2
---------------------------------------- ------------ ------------ ------------
...
DB time                                         1,496        5,360        6,856
CPU used by this session                        1,477        5,295        6,772
CPU used when call started                      1,477        5,295        6,772
...
session logical reads                              40        4,347        4,387
db block changes                                   34        6,349        6,383
consistent changes                                 22        3,211        3,233
db block gets                                      22        3,340        3,362
db block gets from cache                           22        3,340        3,362
consistent gets                                    18        1,007        1,025
consistent gets from cache                         18        1,007        1,025

-- But consumed 15sec!
02. time model                                                                 
                                                                               
STAT_NAME                                        DIFF       VALUE1       VALUE2
---------------------------------------- ------------ ------------ ------------
DB time                                    14,956,306   53,699,686   68,655,992
sql execute elapsed time                   14,949,563   53,616,498   68,566,061
DB CPU                                     14,732,737   52,980,340   67,713,077
parse time elapsed                              6,489      150,264      156,753
...

-- See the aggressive library cache latch acquistion?
LATCH_NAME                         D_GETS   D_MISSES   D_SLEEPS  D_IM_GETS
------------------------------ ---------- ---------- ---------- ----------
library cache                     2639468          5          0          0
SQL memory manager workarea li        339          0          0          0
st latch                                                                  
...


Well, the problem is absolutely poor execution plan. Nested full scan on the X$KGLCURSOR_CHILD view!

explain plan for
select /*+ ordered use_nl(s1, s2) */ 
  count(*)
from v$sql s1, v$sql s2
;

----------------------------------------------------------------------------------------
| Id  | Operation          | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |                   |     1 |    26 |     0   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE    |                   |     1 |    26 |            |          |
|   2 |   NESTED LOOPS     |                   |     1 |    26 |     0   (0)| 00:00:01 |
|*  3 |    FIXED TABLE FULL| X$KGLCURSOR_CHILD |     1 |    13 |     0   (0)| 00:00:01 |
|*  4 |    FIXED TABLE FULL| X$KGLCURSOR_CHILD |     1 |    13 |     0   (0)| 00:00:01 |
----------------------------------------------------------------------------------------



V$views and X$views are not some magical things that are automatically highly efficient. They are just memory structures that sometimes need the protection of latches. Keep this in mind when implementing monitoring queries.

PS) @mon_on, @mon_off and @mon_show are my own scripts for session diff.

Written by Dion Cho

March 16, 2009 at 9:07 am

Posted in Wait Event

Tagged with , ,