Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

serial table scan with direct path read compared to db file scattered read

Mich TalebzadehJan 10 2012 — edited Jan 30 2012
Hi,

The environment
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit

8K block size 

db_file_multiblock_read_count is 128

show sga

Total System Global Area 1.6702E+10 bytes
Fixed Size                  2219952 bytes
Variable Size            7918846032 bytes
Database Buffers         8724152320 bytes
Redo Buffers               57090048 bytes

16GB of SGA with 8GB of db buffer cache.

-- database is built on Solid State Disks

-- SQL trace and wait events

DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true )

-- The underlying table is called tdash. It has 1.7 Million rows based on data in all_objects. NO index 

TABLE_NAME                             Rows Table Size/MB      Used/MB    Free/MB
------------------------------ ------------ ------------- ------------ ----------
TDASH                             1,729,204        15,242       15,186         56

TABLE_NAME                     Allocated blocks Empty blocks Average space/KB Free list blocks
------------------------------ ---------------- ------------ ---------------- ----------------
TDASH                                 1,943,823        7,153              805                0
Objectives

To show that when serial scans are performed on database built on Solid State Disks (SSD) compared to Magnetic disks (HDD), the performance gain is far less compared to random reads with index scans on SSD compared to HDD

Approach

We want to read the first 100 rows of tdash table randomly into buffer, taking account of wait events and wait times generated. The idea is that on SSD the wait times will be better compared to HDD but not that much given the serial nature of table scans.

The code used
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'test_with_tdash_ssdtester_noindex';
DECLARE
        type array is table of tdash%ROWTYPE index by binary_integer;
        l_data array;
        l_rec tdash%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;

        DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
        FOR rs IN 1 .. 100
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM tdash WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;
/
Server is rebooted prior to any tests

Whern run as default, the optimizer (although some attribute this to the execution engine) chooses direct path read into PGA in preference to db file scattered read.
With this choice it takes 6,520 seconds to complete the query. The results are shown below
SQL ID: 78kxqdhk1ubvq
Plan Hash: 1148949653
SELECT *
FROM
 TDASH WHERE OBJECT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          2         47          0           0
Execute    100      0.00       0.00          1         51          0           0
Fetch      100     10.88    6519.89  194142802  194831012          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      201     10.90    6519.90  194142805  194831110          0         100

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)   (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL TDASH (cr=1948310 pr=1941430 pw=0 time=0 us cost=526908 size=8091 card=1)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'TDASH' (TABLE)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        3        0.00          0.00
  db file sequential read                         2        0.00          0.00
  direct path read                          1517504        0.05       6199.93
  asynch descriptor resize                      196        0.00          0.00
********************************************************************************

DECLARE
        type array is table of tdash%ROWTYPE index by binary_integer;
        l_data array;
        l_rec tdash%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
        FOR rs IN 1 .. 100
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM tdash WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      3.84       4.03        320      48666          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      3.84       4.03        320      48666          0           1

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)

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

SQL ID: 9babjv8yq8ru3
Plan Hash: 0
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;


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

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)

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



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      3.84       4.03        320      48666          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      3.84       4.03        320      48666          0           2

Misses in library cache during parse: 0
Misses in library cache during execute: 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
  SQL*Net message from client                     2        0.00          0.00
  log file sync                                   1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.01       0.00          2         47          0           0
Execute    129      0.01       0.00          1         52          2           1
Fetch      140     10.88    6519.89  194142805  194831110          0         130
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      278     10.91    6519.91  194142808  194831209          2         131

Misses in library cache during parse: 9
Misses in library cache during execute: 8

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         5        0.00          0.00
  Disk file operations I/O                        3        0.00          0.00
  direct path read                          1517504        0.05       6199.93
  asynch descriptor resize                      196        0.00          0.00

  102  user  SQL statements in session.
   29  internal SQL statements in session.
  131  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: mydb_ora_16394_test_with_tdash_ssdtester_noindex.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
     102  user  SQL statements in trace file.
      29  internal SQL statements in trace file.
     131  SQL statements in trace file.
      11  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           ssdtester.plan_table
             Schema was specified.
             Table was created.
             Table was dropped.
 1531657  lines in trace file.
    6520  elapsed seconds in trace file.
I then force the query not to use direct path read by invoking
ALTER SESSION SET EVENTS '10949 trace name context forever, level 1'  -- No Direct path read  ;
In this case the optimizer uses db file scattered read predominantly and the query takes 4,299 seconds to finish which is around 34% faster than using direct path read (default).

The report is shown below
SQL ID: 78kxqdhk1ubvq
Plan Hash: 1148949653
SELECT *
FROM
 TDASH WHERE OBJECT_ID = :B1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          2         47          0           0
Execute    100      0.00       0.00          2         51          0           0
Fetch      100    143.44    4298.87  110348670  194490912          0         100
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      201    143.45    4298.88  110348674  194491010          0         100

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)   (recursive depth: 1)

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  TABLE ACCESS FULL TDASH (cr=1944909 pr=1941430 pw=0 time=0 us cost=526908 size=8091 card=1)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   TABLE ACCESS   MODE: ANALYZED (FULL) OF 'TDASH' (TABLE)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        3        0.00          0.00
  db file sequential read                    129759        0.01         17.50
  db file scattered read                    1218651        0.05       3770.02
  latch: object queue header operation            2        0.00          0.00
********************************************************************************

DECLARE
        type array is table of tdash%ROWTYPE index by binary_integer;
        l_data array;
        l_rec tdash%rowtype;
BEGIN
        SELECT
                a.*
                ,RPAD('*',4000,'*') AS PADDING1
                ,RPAD('*',4000,'*') AS PADDING2
        BULK COLLECT INTO
        l_data
        FROM ALL_OBJECTS a;
        DBMS_MONITOR.SESSION_TRACE_ENABLE ( waits=>true );
        FOR rs IN 1 .. 100
        LOOP
                BEGIN
                        SELECT * INTO l_rec FROM tdash WHERE object_id = l_data(rs).object_id;
                EXCEPTION
                  WHEN NO_DATA_FOUND THEN NULL;
                END;
        END LOOP;
END;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      3.92       4.07        319      48625          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      3.92       4.07        319      48625          0           1

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)

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

SQL ID: 9babjv8yq8ru3
Plan Hash: 0
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;


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

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 96  (SSDTESTER)

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



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      3.92       4.07        319      48625          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      3.92       4.07        319      48625          0           2

Misses in library cache during parse: 0
Misses in library cache during execute: 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
  SQL*Net message from client                     2        0.00          0.00
  log file sync                                   1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        9      0.01       0.00          2         47          0           0
Execute    129      0.00       0.00          2         52          2           1
Fetch      140    143.44    4298.87  110348674  194491010          0         130
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      278    143.46    4298.88  110348678  194491109          2         131

Misses in library cache during parse: 9
Misses in library cache during execute: 8

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    129763        0.01         17.50
  Disk file operations I/O                        3        0.00          0.00
  db file scattered read                    1218651        0.05       3770.02
  latch: object queue header operation            2        0.00          0.00

  102  user  SQL statements in session.
   29  internal SQL statements in session.
  131  SQL statements in session.
    1  statement EXPLAINed in this session.
********************************************************************************
Trace file: mydb_ora_26796_test_with_tdash_ssdtester_noindex_NDPR.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
     102  user  SQL statements in trace file.
      29  internal SQL statements in trace file.
     131  SQL statements in trace file.
      11  unique SQL statements in trace file.
       1  SQL statements EXPLAINed using schema:
           ssdtester.plan_table
             Schema was specified.
             Table was created.
             Table was dropped.
 1357958  lines in trace file.
    4299  elapsed seconds in trace file.
I note that there are 1,517,504 waits with direct path read with total time of nearly 6,200 seconds. In comparison with no direct path read, there are 1,218,651 db file scattered read waits with total wait time of 3,770 seconds. My understanding is that direct path read can use single or multi-block read into the PGA. However db file scattered reads do multi-block read into multiple discontinuous SGA buffers. So it is possible given the higher number of direct path waits that the optimizer cannot do multi-block reads (contigious buffers within PGA) and hence has to revert to single blocks reads which results in more calls and more waits?.

Appreciate any advise and apologies for being long winded.

Thanks,

Mich
Comments
Locked Post
New comments cannot be posted to this locked post.
Post Details
Locked on Feb 27 2012
Added on Jan 10 2012
18 comments
1,399 views