Skip to Main Content
  • Questions
  • Slow Full Table Scan on an IO sufficient machine

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Mike.

Asked: September 19, 2016 - 7:40 am UTC

Last updated: September 21, 2016 - 10:13 pm UTC

Version: 12.1.0.2.0

Viewed 10K+ times! This question is

You Asked

Hi Tom,

I am spotting a performance bottleneck when performing Full Table Scan on all the tables. Take a small table example,

SQL> SELECT COUNT(*) FROM schema.frozen_woappoint;
COUNT(*)
----------
1767373

SQL> select segment_name,segment_type,bytes/1024/1024 MB from dba_segments where segment_type='TABLE' and segment_name='FROZEN_WOAPPOINT';
SEGMENT_NAME SEGMENT_TYPE MB
---------------------------------------- ------------------ ----------
FROZEN_WOAPPOINT TABLE 144

I found it super slow (3 minutes) when loading to SSIS. To rule out other factors like driver / network / buffer, I perform simply local machine SQL*Plus query:

SQL> set termout off
SQL> set time off
16:40:58 SQL>
16:41:03 SQL> @speeding.sql
16:43:29 SQL>

Where speeding.sql is a SELECT * STATMENT and this table has no index.

So it still takes more than 2 minutes. I know it's always subjective to say fast or slow. But the observation is that on the DB machine, no matter CPU / RAM / IO / Network are all very idle with no bottleneck found. Therefore I performed a 10046 trace to look at it.

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 117826 15.17 15.43 17379 134063 0 1767373
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 117828 15.17 15.44 17379 134063 0 1767373

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 998
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1767373 1767373 1767373 TABLE ACCESS FULL FROZEN_WOAPPOINT (cr=134063 pr=17379 pw=0 time=9836353 us cost=4787 size=123716110 card=1767373)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 117826 0.00 0.65
direct path read 2 0.00 0.00
SQL*Net message from client 117826 73.68 261.22
********************************************************************************

It's direct path read, and most of the time spent on "SQL*Net message from client". From google and your web site I'm told this is 1) Network issue 2) Application design let DB waiting for its own input. But my case is local machine using local login and my client is the 64-bit SQL*Plus of the same ORACLE_HOME.

I have tried further tests:
1) arraysize 3000: several seconds gain only
2) force parallel query 4: No gain in elapsed time
3) alter session set db_file_multiblock_read_count = 0; : No gain in elapsed time
4) Bypass buffer cache -> Actually it's already direct path read but I tried it anyway but no luck

SQL> desc axis.frozen_woappoint;
Name Null? Type
----------------------------------------- -------- ----------------------------
WAP_JOB_PRE NOT NULL VARCHAR2(6)
WAP_JOB_NO NOT NULL VARCHAR2(10)
WAP_EMPNO VARCHAR2(10)
WAP_APPOINT_DATE DATE
WAP_ARRIVAL_DATE DATE
WAP_APPOINT_SLOT VARCHAR2(2)
WAP_STATUS VARCHAR2(2)
WAP_LINE_NO NOT NULL NUMBER(12)
WAP_PRINT_IND VARCHAR2(1)
WAP_PRINT_DATE DATE
WAP_CLIENT_REF VARCHAR2(10)
WAP_APPOINT_STATUS VARCHAR2(2)
WAP_TRADE VARCHAR2(4)
WAP_WORK_SLOTS NUMBER(4)
WAP_REASON VARCHAR2(4)
WAP_SCHEDULER_APPOINT_ID VARCHAR2(10)
WAP_SCHEDULER_WORKFLOW VARCHAR2(4)
WAP_CHANGED_DATE DATE
WAP_REVIEW_REQ VARCHAR2(1)
WAP_REVIEWED_BY VARCHAR2(20)
WAP_REVIEWED_DATE DATE

SQL>
DB Version: 12.1.0.2.0 No any patch applied
SGA: 6GB
PGA: 4GB
Windows 2008 R2
Virtual Machine with Xeon 4 Core + 16GB RAM

Actually I have seen all the tables have the same slow response time in FTS. I thought it's an IO issue but IO is mostly idle during testing. We're building a template for a Data warehouse and the data copy speed to staging is critical for the whole stack. Thank you for any comment / input you may have.

and Connor said...

select * from T

over a network is perhaps not a good test of your I/O as you can see from the wait stats.

Let's try your other query instead, ie

set timing on
exec dbms_monitor.session_trace_enable(waits=>true)
SELECT COUNT(*) FROM schema.frozen_woappoint;
exec dbms_monitor.session_trace_disable

and lets see what the elapsed time and waits are for that one.




Rating

  (5 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

To Mike | on 2 mins execution time

Rajeshwaran, Jeyabal, September 20, 2016 - 2:03 pm UTC

Please use the code button, without that it was horrible to read !

So it still takes more than 2 minutes.

No, looking at the Tkprof provide it took only 15 secs and the query got completed and you kept the sql*plus session idle for 261 sec ( without sending any message/request to the server)
http://docs.oracle.com/database/121/REFRN/GUID-DFF273D1-3A48-424D-89F8-1971AC95E31B.htm#REFRN00632

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 117826 15.17 15.43 17379 134063 0 1767373 
------- ------ -------- ---------- ---------- ---------- ---------- ---------- 
total 117828 15.17 15.44 17379 134063 0 1767373 

Misses in library cache during parse: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: 998 
Number of plan statistics captured: 1 

Rows (1st) Rows (avg) Rows (max) Row Source Operation 
---------- ---------- ---------- --------------------------------------------------- 
1767373 1767373 1767373 TABLE ACCESS FULL FROZEN_WOAPPOINT (cr=134063 pr=17379 pw=0 time=9836353 us cost=4787 size=123716110 card=1767373) 

Elapsed times include waiting on following events: 
Event waited on Times Max. Wait Total Waited 
---------------------------------------- Waited ---------- ------------ 
SQL*Net message to client 117826 0.00 0.65 
direct path read 2 0.00 0.00 
SQL*Net message from client 117826 73.68 261.22 
******************************************************************************** 


Table sized 144 MB is really, really tiny these days.

Here is my demo on more than 1GB sized table from 12c database.

demo@ORA12C> exec show_space('BIG_TABLE');
Unformatted Blocks .....................               0
FS1 Blocks (0-25)  .....................               0
FS2 Blocks (25-50) .....................               0
FS3 Blocks (50-75) .....................               0
FS4 Blocks (75-100).....................              21
Full Blocks        .....................         157,101
Total Blocks............................         158,240
Total Bytes.............................   1,296,302,080
Total MBytes............................           1,236
Unused Blocks...........................               0
Unused Bytes............................               0
Last Used Ext FileId....................               8
Last Used Ext BlockId...................         350,848
Last Used Block.........................             296

PL/SQL procedure successfully completed.

demo@ORA12C> @tkfilename.sql
D:\APP\VNAMEIT\diag\rdbms\ora12c\ora12c\trace\ora12c_ora_6784.trc


PL/SQL procedure successfully completed.

demo@ORA12C> @tktrace.sql

Session altered.


PL/SQL procedure successfully completed.

demo@ORA12C> select /*+ full(t) */ count(*) from big_table t;

  COUNT(*)
----------
  10000000

1 row selected.

demo@ORA12C> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options


and the Tkprof shows this.
SQL ID: 1rp4sd53cubpy Plan Hash: 599409829

select /*+ full(t) */ count(*) 
from
 big_table t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.09          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      1.21      15.52     157122     157134          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      1.21      15.61     157122     157134          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 135  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=157134 pr=157122 pw=0 time=15526145 us)
  10000000   10000000   10000000   TABLE ACCESS FULL BIG_TABLE (cr=157134 pr=157122 pw=0 time=12837620 us cost=43042 size=0 card=10000000)


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
  direct path read                             4828        0.24         13.20
  SQL*Net message from client                     2        0.00          0.00



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

To Connor on "Set Termout off" from sql*plus

Rajeshwaran, Jeyabal, September 20, 2016 - 2:09 pm UTC

select * from T

over a network is perhaps not a good test of your I/O as you can see from the wait stats.

Let's try your other query instead, ie

set timing on
exec dbms_monitor.session_trace_enable(waits=>true)
SELECT COUNT(*) FROM schema.frozen_woappoint;
exec dbms_monitor.session_trace_disable


would you still recommend to got with COUNT(*) option rather than using "set Termout off" from sql*plus ( ofcourse with no index in place, count(*) and select * , both end up with FTS)

exec dbms_monitor.session_trace_enable(waits=>true) 
set termout off
select * from T;
set termout on
exec dbms_monitor.session_trace_disable 

Chris Saxon
September 20, 2016 - 5:01 pm UTC

'termout' controls data display, not data fetching, eg

SQL> @stat
Enter value for stat_prefix: bytes sent via SQL*Net

       SID NAME                                                    VALUE
---------- -------------------------------------------------- ----------
        13 bytes sent via SQL*Net to client                         9263
        13 bytes sent via SQL*Net to dblink                            0

SQL> host cat c:\temp\x.sql
set termout off
select * from t;
set termout on


SQL> @c:\temp\x.sql
SQL> @stat
Enter value for stat_prefix: bytes sent via SQL*Net

       SID NAME                                                    VALUE
---------- -------------------------------------------------- ----------
        13 bytes sent via SQL*Net to client                     12678153
        13 bytes sent via SQL*Net to dblink                            0



So I wanted to make sure they werent being impacted by that. (We dont know if they are on the server or on a client machine)

count(*) result

Mike Chan, September 21, 2016 - 7:48 am UTC

SQL> set timing on
SQL> exec dbms_monitor.session_trace_enable(waits=>true)

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
SQL> SELECT COUNT(*) FROM axis.frozen_woappoint;

  COUNT(*)
----------
   1767373

Elapsed: 00:00:00.32
SQL> exec dbms_monitor.session_trace_disable

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01
SQL>

Connor McDonald
September 21, 2016 - 10:13 pm UTC

That took 0.3 seconds - which conflicts with your "its slow" post from before.

Now the count(*) might have used an index (but still should have been a direct read).

Anyway, try this


SELECT /*+ full(t) */ COUNT(*) FROM axis.frozen_woappoint t;

to make we do full table scan, and then see how performance goes. If its slow, then you need to show us the trace data.

Mike Chan, September 21, 2016 - 7:51 am UTC

I have worked years on Exadata and they're really fast.
Therefore when I changed the job and seen FTS response time like this I can't even sure whether it's normal for non-exadata vm. Thanks.

FTS timecount

A reader, September 22, 2016 - 8:07 am UTC

I think I should close the thread. Now I test with the same method and things suddenly go very fast. Need to approach infrat team and seek any changes on the VM. Thank you very much!

09:05:06 SQL> @speeding.sql
09:05:11 SQL>


SQL> set time on timing on
08:58:53 SQL> SELECT /*+ full(t) */ COUNT(*) FROM axis.frozen_woappoint t;

  COUNT(*)
----------
   1767373

Elapsed: 00:00:00.31
08:58:55 SQL>

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.