Sunday, June 26, 2011

How Consistent gets are calculated ?

Consistent gets are calculated based on session arraysize and Segment size. Watch what happens with different array size.

rajesh@ORA10GR2> create table t
  2  nologging
  3  as
  4  select * from
  5  all_objects;

Table created.

Elapsed: 00:00:04.90
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec dbms_stats.gather_table_stats(user,'T');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.62
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec show_space(USER,'T','TABLE');
l_total_blocks****************  768
l_total_bytes*****************  6291456
l_unused_blocks***************  60
l_unused_bytes****************  491520
l_last_used_extent_file_id****  7
l_last_used_extent_block_id***  104713
l_last_used_block*************  68
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  0
l_fs2_bytes*******************  0
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  688
l_full_bytes******************  5636096

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.15
rajesh@ORA10GR2>

The total size of the Table is 708 (768 - 60) Blocks.

rajesh@ORA10GR2> show arraysize;
arraysize 150
rajesh@ORA10GR2> set autotrace traceonly explain statistics;
rajesh@ORA10GR2> select * from t;

50086 rows selected.

Elapsed: 00:00:00.23
Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      | 50086 |  4548K|   161   (3)| 00:00:02 |
|   1 |  TABLE ACCESS FULL| T    | 50086 |  4548K|   161   (3)| 00:00:02 |
--------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
       1020  consistent gets
          0  physical reads
          0  redo size
    2044854  bytes sent via SQL*Net to client
       4059  bytes received via SQL*Net from client
        335  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      50086  rows processed

rajesh@ORA10GR2> set autotrace off;
rajesh@ORA10GR2>

We set the arraysize to 150, so it is 150 row / fetch. So in total its 50068/150 = 333 fetches, and table segment size is 708 blocks so in total its 1041 which matches almost with consistent gets.

rajesh@ORA10GR2> set autotrace traceonly explain statistics;
rajesh@ORA10GR2>
rajesh@ORA10GR2> show arraysize;
arraysize 500
rajesh@ORA10GR2>
rajesh@ORA10GR2> select * from t;

50086 rows selected.

Elapsed: 00:00:00.23

Execution Plan
----------------------------------------------------------
Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      | 50086 |  4548K|   161   (3)| 00:00:02 |
|   1 |  TABLE ACCESS FULL| T    | 50086 |  4548K|   161   (3)| 00:00:02 |
--------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
        793  consistent gets
          0  physical reads
          0  redo size
    2015263  bytes sent via SQL*Net to client
       1496  bytes received via SQL*Net from client
        102  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      50086  rows processed

rajesh@ORA10GR2> set autotrace off;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select ( 50086/500) + 708 from dual;

(50086/500)+708
---------------
        808.172

Elapsed: 00:00:00.03
rajesh@ORA10GR2>

As the arraysize increses consistent get's reduced. we get more row per fetch with increased array size.

rajesh@ORA10GR2> create index t_ind on t(owner,object_name,object_type);

Index created.

Elapsed: 00:00:00.82
rajesh@ORA10GR2> exec show_space(USER,'T_IND','INDEX');
l_total_blocks****************  384
l_total_bytes*****************  3145728
l_unused_blocks***************  20
l_unused_bytes****************  163840
l_last_used_extent_file_id****  7
l_last_used_extent_block_id***  104969
l_last_used_block*************  108
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  1
l_fs2_bytes*******************  8192
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  349
l_full_bytes******************  2859008

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.03
rajesh@ORA10GR2>

The total size of index T_IND is 364 (384 - 20) blocks.

rajesh@ORA10GR2> show arraysize ;
arraysize 500
rajesh@ORA10GR2>
rajesh@ORA10GR2> select owner,object_name,object_type
  2  from t;

50086 rows selected.

Elapsed: 00:00:00.18

Execution Plan
----------------------------------------------------------
Plan hash value: 1176281950

------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       | 50086 |  1956K|    80   (3)| 00:00:01 |
|   1 |  INDEX FAST FULL SCAN| T_IND | 50086 |  1956K|    80   (3)| 00:00:01 |
------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        457  consistent gets
        349  physical reads
          0  redo size
    1499995  bytes sent via SQL*Net to client
       1496  bytes received via SQL*Net from client
        102  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      50086  rows processed

rajesh@ORA10GR2>
rajesh@ORA10GR2> set autotrace off;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select ( 50086/500) + 364 from dual;

(50086/500)+364
---------------
        464.172

Elapsed: 00:00:00.03
rajesh@ORA10GR2>

Now, 464 matches with consistent gets again !

rajesh@ORA10GR2> show arraysize;
arraysize 2
rajesh@ORA10GR2>
rajesh@ORA10GR2> set autotrace traceonly explain statistics;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select owner,object_name,object_type
  2  from t;

50086 rows selected.

Elapsed: 00:00:01.96

Execution Plan
----------------------------------------------------------
Plan hash value: 1176281950

------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       | 50086 |  1956K|    80   (3)| 00:00:01 |
|   1 |  INDEX FAST FULL SCAN| T_IND | 50086 |  1956K|    80   (3)| 00:00:01 |
------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      25214  consistent gets
          0  physical reads
          0  redo size
    4667629  bytes sent via SQL*Net to client
     275858  bytes received via SQL*Net from client
      25044  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      50086  rows processed

rajesh@ORA10GR2>
rajesh@ORA10GR2> set autotrace off;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select ( 50086/2) + 364 from dual;

(50086/2)+364
-------------
        25407

Elapsed: 00:00:00.03
rajesh@ORA10GR2>
Now again consistent gets matches for the arraysize 2.

rajesh@ORA10GR2> show arraysize;
arraysize 1
rajesh@ORA10GR2>
rajesh@ORA10GR2> set autotrace traceonly explain statistics;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select owner,object_name,object_type
  2  from t;

50086 rows selected.

Elapsed: 00:00:01.95

Execution Plan
----------------------------------------------------------
Plan hash value: 1176281950

------------------------------------------------------------------------------
| Id  | Operation            | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |       | 50086 |  1956K|    80   (3)| 00:00:01 |
|   1 |  INDEX FAST FULL SCAN| T_IND | 50086 |  1956K|    80   (3)| 00:00:01 |
------------------------------------------------------------------------------

Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      25214  consistent gets
          0  physical reads
          0  redo size
    4667629  bytes sent via SQL*Net to client
     275858  bytes received via SQL*Net from client
      25044  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
      50086  rows processed

rajesh@ORA10GR2>
rajesh@ORA10GR2> set autotrace off;
rajesh@ORA10GR2>
rajesh@ORA10GR2> select ( 50086/1) + 364 from dual;

(50086/1)+364
-------------
        50450

Elapsed: 00:00:00.01
rajesh@ORA10GR2>

setting the arraysize=1 doesn't match with consistent gets, ofcourse if you set arraysize=1 internally it will be treated as arraysize=2

Now let's see what happens in case of multiple tables in a query.

rajesh@ORA10GR2> create table t1
  2  as
  3  select * from
  4  all_objects;

Table created.

Elapsed: 00:00:00.90
rajesh@ORA10GR2>
rajesh@ORA10GR2> create table t2
  2  as
  3  select * from
  4  user_objects;

Table created.

Elapsed: 00:00:00.07
rajesh@ORA10GR2>
rajesh@ORA10GR2> create table t3
  2  as
  3  select *
  4  from all_objects
  5  where object_type ='TABLE';

Table created.

Elapsed: 00:00:00.62
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec dbms_stats.gather_table_stats(user,'T1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.48
rajesh@ORA10GR2> exec dbms_stats.gather_table_stats(user,'T2');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.09
rajesh@ORA10GR2> exec dbms_stats.gather_table_stats(user,'T3');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.07
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec show_space(user,'T1','TABLE');
l_total_blocks****************  768
l_total_bytes*****************  6291456
l_unused_blocks***************  60
l_unused_bytes****************  491520
l_last_used_extent_file_id****  7
l_last_used_extent_block_id***  105353
l_last_used_block*************  68
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  0
l_fs2_bytes*******************  0
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  688
l_full_bytes******************  5636096

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
rajesh@ORA10GR2>
rajesh@ORA10GR2> select 768 - 60 from dual;

    768-60
----------
       708

Elapsed: 00:00:00.01
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec show_space(user,'T2','TABLE');
l_total_blocks****************  8
l_total_bytes*****************  65536
l_unused_blocks***************  4
l_unused_bytes****************  32768
l_last_used_extent_file_id****  7
l_last_used_extent_block_id***  104921
l_last_used_block*************  4
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  0
l_fs2_bytes*******************  0
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  1
l_full_bytes******************  8192

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.07
rajesh@ORA10GR2>
rajesh@ORA10GR2> select 8-4 from dual;

       8-4
----------
         4

Elapsed: 00:00:00.01
rajesh@ORA10GR2> exec show_space(user,'T3','TABLE');
l_total_blocks****************  32
l_total_bytes*****************  262144
l_unused_blocks***************  7
l_unused_bytes****************  57344
l_last_used_extent_file_id****  6
l_last_used_extent_block_id***  2225
l_last_used_block*************  1
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  0
l_fs2_bytes*******************  0
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  21
l_full_bytes******************  172032

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.07
rajesh@ORA10GR2>
rajesh@ORA10GR2> select 32 - 7 from dual;

      32-7
----------
        25

Elapsed: 00:00:00.01
rajesh@ORA10GR2>
rajesh@ORA10GR2> select t1.object_name,t2.object_type, t3.owner
  2  from t1 ,t2, t3
  3  where t1.object_name = t2.object_name
  4  and t1.object_type = t2.object_type
  5  and t3.object_name = t2.object_name
  6  and t3.object_type = t2.object_type
  7  /

11 rows selected.

Elapsed: 00:00:00.01

Execution Plan
----------------------------------------------------------
Plan hash value: 98820498

---------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |    16 |  1280 |   172   (3)| 00:00:03
|*  1 |  HASH JOIN          |      |    16 |  1280 |   172   (3)| 00:00:03
|*  2 |   HASH JOIN         |      |    16 |   736 |    11  (10)| 00:00:01
|   3 |    TABLE ACCESS FULL| T2   |    16 |   240 |     3   (0)| 00:00:01
|   4 |    TABLE ACCESS FULL| T3   |  1633 | 50623 |     7   (0)| 00:00:01
|   5 |   TABLE ACCESS FULL | T1   | 50086 |  1663K|   160   (2)| 00:00:02
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - access("T1"."OBJECT_NAME"="T2"."OBJECT_NAME" AND
              "T1"."OBJECT_TYPE"="T2"."OBJECT_TYPE")
   2 - access("T3"."OBJECT_NAME"="T2"."OBJECT_NAME" AND
              "T3"."OBJECT_TYPE"="T2"."OBJECT_TYPE")

Statistics
----------------------------------------------------------
          1  recursive calls
          0  db block gets
        721  consistent gets
          0  physical reads
          0  redo size
        706  bytes sent via SQL*Net to client
        396  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         11  rows processed

rajesh@ORA10GR2>
rajesh@ORA10GR2> show arraysize;
arraysize 150
rajesh@ORA10GR2>
rajesh@ORA10GR2> select (11/150)+708+4+25 from dual;


(11/150)+708+4+25
-----------------
       737.073333

Elapsed: 00:00:00.00
rajesh@ORA10GR2>
rajesh@ORA10GR2>

When pulling data from multiple tables, consistent gets are caculated based on arraysize and size of each segments involved in query execution.

JDBC Default's to arraysize of 10 even in 11GR2 server using ojdbc5.jar

create table t
nologging
as
select * from all_objects;
exec dbms_stats.gather_table_stats(user,'T');

import java.sql.*;
import oracle.jdbc.OracleDriver;
public class bind_test
{
 public static void main(String args[]) throws Exception
 {
  Class.forName("oracle.jdbc.OracleDriver");
  String url="jdbc:oracle:thin:@LDX0000040BN3Q1:1521:ora11gr2";
  Connection conn=DriverManager.getConnection(url,"rajesh","oracle");
  conn.setAutoCommit(false);
  Statement stmt=conn.createStatement();
  ResultSet rs1=stmt.executeQuery("alter session set timed_statistics=true");
  ResultSet rs2=stmt.executeQuery("alter session set events '10046 trace name context forever, level 12'");
  ResultSet rs=stmt.executeQuery("select * from T");
  while (rs.next())
  {
   System.out.println(rs.getString(1));
  }
  stmt.close();
  System.out.println("O.K");
 }
}

And Tkprof show's me this

SQL ID: ahgbnyrbh7bp1
Plan Hash: 1601196873
select *
from
 T

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     7154      0.42       0.34          0       8074          0       71537
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     7156      0.42       0.34          0       8074          0       71537
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 91 
Rows     Row Source Operation
-------  ---------------------------------------------------
  71537  TABLE ACCESS FULL T (cr=8074 pr=0 pw=0 time=171609 us cost=287 size=6939089 card=71537)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                    7155        0.00          0.01
  SQL*Net message from client                  7155        0.24          7.12
  Disk file operations I/O                        1        0.00          0.00

Sunday, June 19, 2011

Email in PL/SQL Oracle 10G

The UTL_MAIL package was introduced in Oracle 10g and it is easier to use when compared to UTL_SMTP. In order to use Oracle UTL_MAIL package you need to set a new init.ora parameter "SMTP_OUT_SERVER", set to your outgoing mailserver.

rajesh@ORA10GR2> alter system set smtp_out_server = 'mailinbound.domain.com';

System altered.

Elapsed: 00:00:00.14

rajesh@ORA10GR2> alter system set utl_file_dir = 'FILE_DIR' scope=spfile;

System altered.

Elapsed: 00:00:00.14
rajesh@ORA10GR2>

rajesh@ORA10GR2> connect sys/***** as sysdba
Connected.
sys@ORA10GR2> shutdown immediate;
Database closed.
Database dismounted.
ORACLE instance shut down.
sys@ORA10GR2> startup;
ORACLE instance started.
Database mounted.
Database opened.
sys@ORA10GR2>
sys@ORA10GR2>
sys@ORA10GR2> show parameter utl_file_dir;

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
utl_file_dir                         string      FILE_DIR
sys@ORA10GR2>

You must set UTL_FILE_DIR to a directory, where the attachment files exists

sys@ORA10GR2>
sys@ORA10GR2> show parameter smtp_out_server;
NAME                                 TYPE        VALUE
------------------------------------ ----------- -------------------------
smtp_out_server                      string      mailinbound.domain.com
sys@ORA10GR2> @C:\oracle\product\10.2.0\db_1\RDBMS\ADMIN\utlmail.sql;

Package created.

Elapsed: 00:00:00.70

Synonym created.

Elapsed: 00:00:00.10
sys@ORA10GR2>
sys@ORA10GR2> @C:\oracle\product\10.2.0\db_1\RDBMS\ADMIN\prvtmail.plb;

Package body created.

Elapsed: 00:00:00.45
No errors.
sys@ORA10GR2>
sys@ORA10GR2> grant execute on utl_mail to rajesh,scott;

Grant succeeded.

Elapsed: 00:00:00.04
sys@ORA10GR2>
sys@ORA10GR2> connect scott/tiger
Connected.
scott@ORA10GR2>
scott@ORA10GR2> begin
  2     utl_mail.SEND_ATTACH_RAW(
  3     sender=>'rajeshwaran_jeyabal@domain.com',
  4     recipients=>'rajeshwaran_jeyabal@domain.com',
  5     subject=>'Hello World',
  6     message=>'Hello World',
  7     attachment =>utl_raw.cast_to_raw('PDF_Contents'),
  8     att_filename=>'TEST_PDF.pdf');
  9
 10     utl_mail.SEND_ATTACH_VARCHAR2(
 11     sender=>'rajeshwaran_jeyabal@domain.com',
 12     recipients=>'rajeshwaran_jeyabal@domain.com',
 13     subject=>'Hello World',
 14     message=>'Hello World',
 15     attachment =>'Text_Contents',
 16     att_filename=>'log.txt');
 17  end;
 18  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.64
scott@ORA10GR2>

Oracle 10g has added over fifty new PL/SQL packages and enhanced many of the existing packages, thus expanding the Oracle DBA's toolkit once again !

Thursday, June 16, 2011

Sequences in 10G RAC

Recently we migrated our application to Oracle 10g RAC (3 Instance) and ended up with sequences created as out of order at each Instance.

Here is the snippet of code to demonstrate that.

rajesh@ORA10GR2-01> SELECT INST_ID,
  2    INSTANCE_NUMBER,
  3    INSTANCE_NAME
  4  FROM GV$INSTANCE
  5  ORDER BY INST_ID;

   INST_ID INSTANCE_NUMBER INSTANCE_NAME
---------- --------------- ----------------
         1               1 ORA10GR2-01
         2               2 ORA10GR2-02
         3               3 ORA10GR2-03


 rajesh@ORA10GR2-01> create sequence s CACHE 30;

Sequence created.

Elapsed: 00:00:00.07
rajesh@ORA10GR2-01> select SEQUENCE_NAME,ORDER_FLAG,CACHE_SIZE
  2  from user_sequences
  3  where sequence_name ='S'
  4  /

SEQUENCE_NAME                  O CACHE_SIZE
------------------------------ - ----------
S                              N         30

Elapsed: 00:00:00.17
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select s.nextval from dual;

   NEXTVAL
----------
         1

Elapsed: 00:00:00.14
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select s.nextval from dual;

   NEXTVAL
----------
         2

Elapsed: 00:00:00.25
rajesh@ORA10GR2-01>

When connecting back to Instance02 I found the sequence values different.

rajesh@ORA10GR2-01> connect rajesh/oracle@ORA10GR2-02
Connected.
rajesh@ORA10GR2-02> select s.nextval from dual;

   NEXTVAL
----------
        31

Elapsed: 00:00:00.48
rajesh@ORA10GR2-02>
rajesh@ORA10GR2-02> select s.nextval from dual;

   NEXTVAL
----------
        32

Elapsed: 00:00:00.15
rajesh@ORA10GR2-02>

When connecting back to Instance03 I found the sequence values different again.

rajesh@ORA10GR2-02> connect rajesh/oracle@ORA10GR2-03
Connected.
rajesh@ORA10GR2-03> select s.nextval from dual;

   NEXTVAL
----------
        61

Elapsed: 00:00:00.21
rajesh@ORA10GR2-03> select s.nextval from dual;

   NEXTVAL
----------
        62

Elapsed: 00:00:00.14
rajesh@ORA10GR2-03>
The reason for this out of order sequence at each instance is the sequence cache is in the shared pool, therefore sessions on the same node can share the cached entry, but sessions on different nodes cannot.

The solution to solve this sequence running out of order at each instance is to create sequence using ORDER option. which will guarantee the order in which numbers are generated.

rajesh@ORA10GR2-01> create sequence s CACHE 30 ORDER;

Sequence created.

Elapsed: 00:00:00.09
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select SEQUENCE_NAME,ORDER_FLAG,CACHE_SIZE
  2  from user_sequences
  3  where sequence_name ='S'
  4  /

SEQUENCE_NAME                  O CACHE_SIZE
------------------------------ - ----------
S                              Y         30

Elapsed: 00:00:00.10
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select s.nextval from dual;

   NEXTVAL
----------
         1

Elapsed: 00:00:00.17
rajesh@ORA10GR2-01> select s.nextval from dual;

   NEXTVAL
----------
         2

Elapsed: 00:00:00.34
rajesh@ORA10GR2-01>
Connecting back to Instance02.

rajesh@ORA10GR2-01> connect rajesh/oracle@ORA10GR2-02

Connected.
rajesh@ORA10GR2-02> select s.nextval from dual;

   NEXTVAL
----------
         3

Elapsed: 00:00:00.17
rajesh@ORA10GR2-02>
rajesh@ORA10GR2-02> select s.nextval from dual;

   NEXTVAL
----------
         4

Elapsed: 00:00:00.17
rajesh@ORA10GR2-02>
Connecting back to Instance03.

rajesh@ORA10GR2-02> connect rajesh/oracle@ORA10GR2-03
Connected.
rajesh@ORA10GR2-03> select s.nextval from dual;

   NEXTVAL
----------
         5

Elapsed: 00:00:00.14
rajesh@ORA10GR2-03>
rajesh@ORA10GR2-03> select s.nextval from dual;

   NEXTVAL
----------
         6

Elapsed: 00:00:00.17
rajesh@ORA10GR2-03>

We changed the sequence to "ordered" Now selecting on either node gets the next number as expected.

However having the sequence with CACHE and ORDER would lead to some performance implications due to cluster synchronization. In Oracle 10g RAC, if you specify the "ordered" clause for a sequence, then a global lock is allocated by the node when you access the sequence. This lock acquisition happens only at the first sequence access for the node, and subsequent uses of the sequence do not wait on this lock.


rajesh@ORA10GR2-01> create sequence s order;

Sequence created.

Elapsed: 00:00:00.01
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select SEQUENCE_NAME,ORDER_FLAG,CACHE_SIZE
  2  from user_sequences
  3  where sequence_name ='S';

SEQUENCE_NAME                  O CACHE_SIZE
------------------------------ - ----------
S                              Y         20

Elapsed: 00:00:00.01
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01>
Connected.
rajesh@ORA10GR2-01>

I was running the below Pl/SQL block evenly across all the RAC Instance.

rajesh@ORA10GR2-01>  declare
  2             k number;
  3             l_start number;
  4             l_cpu_time number;
  5     begin
  6             l_start := dbms_utility.get_time;
  7             l_cpu_time := dbms_utility.get_cpu_time;
  8     for i in 1..500000
  9     loop
 10                     select s.nextval
 11                     into k
 12                     from dual;
 13     end loop;
 14
 15             dbms_output.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
 16             dbms_output.put_line (' Total CPU time = '|| (dbms_utility.get_cpu_time - l_cpu_time) );
 17     end;
 18  /

 Total Execution time = 82110
 Total CPU time = 7057

PL/SQL procedure successfully completed.

Elapsed: 00:13:40.99
rajesh@ORA10GR2-01>

And the AWR on Instance 1 is.

   SQL Id      Time (ms)
------------- ----------
9x2hyv1prpts9    802,038
Module: SQL*Plus
OUTPUT
--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst011  Snaps: 3518-3519
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         802,038             1          3519           3519
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst011  Snaps: 3518-3519
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           802,038      802,037.9    30.0
CPU Time (ms)                                70,597       70,597.3    93.7
Executions                                        1            N/A     N/A
Buffer Gets                                 149,976      149,976.0    56.6
Disk Reads                                        3            3.0     7.7
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.0
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                          45            N/A     N/A
Cluster Wait Time (ms)                      186,959            N/A     N/AApplication Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                   13,813            N/A     N/AInvalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

And the AWR on Instance 2 is.

                Elapsed
   SQL Id      Time (ms)
------------- ----------
9x2hyv1prpts9    818,718
Module: SQL*Plus
OUTPUT
--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst012  Snaps: 3518-3519
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         818,718             1          3519           3519
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst012  Snaps: 3518-3519
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           818,718      818,718.5    31.7
CPU Time (ms)                                72,017       72,017.1    97.5
Executions                                        1            N/A     N/A
Buffer Gets                                 149,898      149,898.0    81.6
Disk Reads                                        0            0.0     0.0
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.0
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                           0            N/A     N/A
Cluster Wait Time (ms)                      135,191            N/A     N/A
Application Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                   14,768            N/A     N/A
Invalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

And the AWR on Instance 3 is.

                Elapsed
   SQL Id      Time (ms)
------------- ----------
9x2hyv1prpts9    816,826
Module: SQL*Plus
OUTPUT
--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst013  Snaps: 3518-3519
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         816,826             1          3519           3519
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst013  Snaps: 3518-3519
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           816,826      816,826.4    97.8
CPU Time (ms)                                68,859       68,858.5    90.9
Executions                                        1            N/A     N/A
Buffer Gets                                 133,660      133,660.0    28.3
Disk Reads                                        0            0.0     0.0
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.0
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                           0            N/A     N/A
Cluster Wait Time (ms)                       25,148            N/A     N/A
Application Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                    8,942            N/A     N/A
Invalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

Due to the less CACHE sequence value and ORDER attribute and since the same sequence is shared across all Instance we ended up with Clustered & Concurrency waits.

Now repeting the same test with Increased CACHE size.

rajesh@ORA10GR2-01> create sequence s CACHE 100000 order;

Sequence created.

Elapsed: 00:00:00.03
rajesh@ORA10GR2-01>
rajesh@ORA10GR2-01> select SEQUENCE_NAME,ORDER_FLAG,CACHE_SIZE
  2  from user_sequences
  3  where sequence_name ='S';

SEQUENCE_NAME                  O CACHE_SIZE
------------------------------ - ----------
S                              Y     100000

Elapsed: 00:00:00.01 

rajesh@ORA10GR2-01>  declare
  2             k number;
  3             l_start number;
  4             l_cpu_time number;
  5     begin
  6             l_start := dbms_utility.get_time;
  7             l_cpu_time := dbms_utility.get_cpu_time;
  8     for i in 1..500000
  9     loop
 10                     select s.nextval
 11                     into k
 12                     from dual;
 13     end loop;
 14
 15             dbms_output.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
 16             dbms_output.put_line (' Total CPU time = '|| (dbms_utility.get_cpu_time - l_cpu_time) );
 17     end;
 18  /

 Total Execution time = 32396
 Total CPU time = 3418

PL/SQL procedure successfully completed.

Elapsed: 00:05:23.96
rajesh@ORA10GR2-01>

AWR at Instance-01 shows

                Elapsed
   SQL Id      Time (ms)
------------- ----------
9x2hyv1prpts9    316,430
Module: SQL*Plus
OUTPUT
--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst011  Snaps: 3520-3521
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         316,430             1          3521           3521
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst011  Snaps: 3520-3521
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           316,430      316,429.6    91.0
CPU Time (ms)                                34,199       34,198.8    87.9
Executions                                        1            N/A     N/A
Buffer Gets                                     118          118.0     0.9
Disk Reads                                        0            0.0     0.0
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.1
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                           0            N/A     N/A
Cluster Wait Time (ms)                            4            N/A     N/AApplication Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                        8            N/A     N/AInvalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

AWR at Instance-02 shows

--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst012  Snaps: 3520-3521
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         320,198             1          3521           3521
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst012  Snaps: 3520-3521
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           320,198      320,198.1    96.7
CPU Time (ms)                                36,561       36,561.4    92.0
Executions                                        1            N/A     N/A
Buffer Gets                                      59           59.0     0.7
Disk Reads                                        0            0.0     0.0
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.1
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                           0            N/A     N/A
Cluster Wait Time (ms)                           12            N/A     N/A
Application Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                        9            N/A     N/AInvalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

AWR at Instance-03 shows

--------------------------------------------------------------------------------
 declare k number; l_start number; l_cpu_time number; begin l_start :=
dbms_utility.get_time; l_cpu_time := dbms_utility.get_cpu_time; for i in 1..5
00000 loop select s.nextval into k from dual; end loop; dbms_outpu
t.put_line (' Total Execution time = '|| (dbms_utility.get_time - l_start) );
          -------------------------------------------------------------
SQL ID: 9x2hyv1prpts9              DB/Inst: IRDST01/irdst013  Snaps: 3520-3521
-> 1st Capture and Last Capture Snap IDs
   refer to Snapshot IDs witin the snapshot range
-> declare k number; l_start number; l_cpu_time number; begin l...
OUTPUT
--------------------------------------------------------------------------------
    Plan Hash           Total Elapsed                 1st Capture   Last Capture
#   Value                    Time(ms)    Executions       Snap ID        Snap ID
--- ---------------- ---------------- ------------- ------------- --------------
1   0                         318,115             1          3521           3521
          -------------------------------------------------------------
Plan 1(PHV: 0)
--------------
OUTPUT
--------------------------------------------------------------------------------
Plan Statistics                    DB/Inst: IRDST01/irdst013  Snaps: 3520-3521
-> % Total DB Time is the Elapsed Time of the SQL statement divided
   into the Total Database Time multiplied by 100
Stat Name                                Statement   Per Execution % Snap
---------------------------------------- ---------- -------------- -------
Elapsed Time (ms)                           318,115      318,115.2    92.6
CPU Time (ms)                                31,745       31,745.2    83.8
Executions                                        1            N/A     N/A
Buffer Gets                                      47           47.0     0.0
Disk Reads                                        0            0.0     0.0
OUTPUT
--------------------------------------------------------------------------------
Parse Calls                                       1            1.0     0.1
Rows                                              1            1.0     N/A
User I/O Wait Time (ms)                           0            N/A     N/A
Cluster Wait Time (ms)                           11            N/A     N/A
Application Wait Time (ms)                        0            N/A     N/A
Concurrency Wait Time (ms)                        5            N/A     N/AInvalidations                                     0            N/A     N/A
Version Count                                     1            N/A     N/A
Sharable Mem(KB)                                 20            N/A     N/A
          -------------------------------------------------------------

Now the Cluster Wait Time & Concurrency Wait Time got reduced due to Increased CACHE size. which leads to less synchronization across RAC Instances.

Thursday, June 9, 2011

Direct Path Reads

I was reading from Oracle product documentation about direct path reads and here it is.

<quote>
   Direct reads read directly from disk into the PGA, again bypassing the buffer cache
</quote>

So, what is this Direct path read is about? How can we instruct optimizer to go for Direct path read to get data for queries?

In Oracle we dont need to 'define' a direct read in sql statement they just 'happen'. Parallel query for example - very often does direct reads.

rajesh@ORA10GR2> select count(*) from big_table;

  COUNT(*)
----------
  12773888

Elapsed: 00:00:32.35
rajesh@ORA10GR2>
rajesh@ORA10GR2> exec show_space(user,'BIG_TABLE','TABLE');
l_total_blocks****************  188416
l_total_bytes*****************  1543503872
l_unused_blocks***************  1665
l_unused_bytes****************  13639680
l_last_used_extent_file_id****  6
l_last_used_extent_block_id***  91657
l_last_used_block*************  6527
l_unformatted_blocks**********  0
l_unformatted_bytes***********  0
l_fs1_blocks******************  0
l_fs1_bytes*******************  0
l_fs2_blocks******************  0
l_fs2_bytes*******************  0
l_fs3_blocks******************  0
l_fs3_bytes*******************  0
l_fs4_blocks******************  0
l_fs4_bytes*******************  0
l_full_blocks*****************  186083
l_full_bytes******************  1524391936

PL/SQL procedure successfully completed.

Elapsed: 00:00:01.42
rajesh@ORA10GR2>
Then ran the below script from sql*plus
exec dbms_workload_repository.create_snapshot();

select /*+ parallel(big_table,8) */ owner,object_type,object_name
from big_table;

AWR Show's me this.

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
PX Deq Credit: send blkd            277,868     .0      17,822      64     624.4
direct path read                     23,911     .0         176       7      53.7db file scattered read               12,656     .0          32       3      28.4
db file sequential read              11,105     .0          21       2      25.0
control file parallel write           3,286     .0           9       3       7.4
control file sequential read         11,338     .0           8       1      25.5
db file parallel write                1,578     .0           5       3       3.5
SQL*Net more data to client         166,611     .0           1       0     374.4
os thread startup                        57     .0           1      24       0.1
log file parallel write               2,492     .0           1       1       5.6
enq: KO - fast object checkp              1     .0           1     813       0.0
Data file init write                     16     .0           0      26       0.0
rdbms ipc reply                          76     .0           0       4       0.2
latch free                               19     .0           0      16       0.0
PX Deq: Signal ACK                        6   66.7           0      35       0.0
SQL*Net message to client            85,410     .0           0       0     191.9
log file sync                           115     .0           0       1       0.3
log file switch completion                2     .0           0      34       0.0
kksfbc child completion                   1  100.0           0      59       0.0
cursor: pin S wait on X                   3  100.0           0      15       0.0
log buffer space                         74     .0           0       0       0.2
read by other session                     4     .0           0       4       0.0
direct path write                        22     .0           0       0       0.0
log file sequential read                  2     .0           0       5       0.0
PX qref latch                         1,658   99.9           0       0       3.7
PX Deq: Table Q Get Keys                 20     .0           0       0       0.0
direct path write temp                   10     .0           0       1       0.0
enq: RO - fast object reuse              73     .0           0       0       0.2
reliable message                         75     .0           0       0       0.2
log file single write                     2     .0           0       1       0.0
LGWR wait for redo copy                 104     .0           0       0       0.2
library cache load lock                   2     .0           0       1       0.0
row cache lock                            8     .0           0       0       0.0
db file single write                      1     .0           0       1       0.0
PX Deq: Table Q qref                      6     .0           0       0       0.0
enq: PS - contention                      3     .0           0       0       0.0
cursor: mutex S                           1     .0           0       0       0.0
Streams AQ: qmn slave idle w            345     .0       9,611   27858       0.8
Streams AQ: qmn coordinator             691   50.1       9,611   13909       1.6
virtual circuit status                  321  100.0       9,583   29853       0.7
PX Idle Wait                          3,595   99.5       7,121    1981       8.1
SQL*Net message from client          85,410     .0       6,756      79     191.9
Streams AQ: waiting for time              4  100.0       2,405  601321       0.0
PX Deq: Execution Msg                   539   34.7         407     756       1.2
jobq slave wait                          40  100.0         120    3000       0.1
PX Deq: Execute Reply                   139     .0          27     196       0.3
PX Deq Credit: need buffer              159     .0           7      45       0.4
PL/SQL lock timer                         2   50.0           1     495       0.0
PX Deq: Parse Reply                      22     .0           0       1       0.0
PX Deq: Table Q Sample                   21     .0           0       0       0.0
PX Deq: Msg Fragment                      7     .0           0       0       0.0
PX Deq: Join ACK                         17     .0           0       0       0.0
class slave wait                         30     .0           0       0       0.1
PX Deq: Table Q Normal                   10     .0           0       0       0.0
          -------------------------------------------------------------
Then ran the below script from sql*plus

exec dbms_workload_repository.create_snapshot();

select owner,object_type,object_name
from big_table;

AWR Show's me this.

                                                                   Avg
                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
db file scattered read               12,446     .0         176      14     177.8
db file sequential read               2,261     .0           6       3      32.3
control file parallel write           1,391     .0           6       4      19.9
control file sequential read          4,872     .0           3       1      69.6
SQL*Net more data to client         160,000     .0           2       0   2,285.7
db file parallel write                  468     .0           2       3       6.7
log file parallel write                 360     .0           0       1       5.1
os thread startup                        13     .0           0      22       0.2
SQL*Net message to client            85,164     .0           0       0   1,216.6
latch free                                5     .0           0      19       0.1
log file sync                            14     .0           0       3       0.2
direct path write                         4     .0           0       6       0.1
LGWR wait for redo copy                  32     .0           0       0       0.5
virtual circuit status                  139  100.0       4,164   29957       2.0
Streams AQ: qmn slave idle w            149     .0       4,152   27866       2.1
Streams AQ: qmn coordinator             298   50.0       4,152   13933       4.3
SQL*Net message from client          85,164     .0       3,352      39   1,216.6
Streams AQ: waiting for time              1  100.0       1,202 #######       0.0
class slave wait                         13     .0           0       0       0.2
          -------------------------------------------------------------

You we can see that only with parallel execution, direct path reads comes in picture.