We are using version 11.2.0.4 of oracle. We just found a query which used to complete in ~1hr daily has just end up running into 5hrs+ and was not completing. Then looking into more , i found the table which normally used 'Direct path read' for scanning table tab1 is just end up in doing lot of 'Db file sequential read'. and after killing that execution and letting the job to rerun, it completed in again ~1hr. So wondering what made oracle to scan the full partition of the table with 'db file sequential read'?
i had collected the real time monitoring plan for both the executions, before kill and after kill when it reran successfully. also collected the session stats when it was entering into doing lot of DB file sequential read for doing FTS. I want expert suggestion, how to track down the issue, so it wont appear in future again?
********************* Long running , using DB file sequential read for FTS*********************************
Global Information
------------------------------
Status : EXECUTING
SQL Execution ID : 16777216
Execution Started : 07/11/2017 01:38:41
First Refresh Time : 07/11/2017 01:38:45
Last Refresh Time : 07/11/2017 09:50:29
Duration : 29547s
Fetch Calls : 23010
Global Stats
============================================================================================================
| Elapsed | Cpu | IO | Application | Concurrency | Fetch | Buffer | Read | Read | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs | Bytes | Reqs | Bytes |
============================================================================================================
| 29589 | 2042 | 27531 | 14 | 2.43 | 23010 | 41M | 17M | 231GB | 7690 | 901MB |
============================================================================================================
SQL Plan Monitoring Details (Plan Hash Value=4053309622)
=================================================================================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Write | Write | Mem | Temp | Activity | Activity Detail | Progress |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | Reqs | Bytes | | | (%) | (# samples) | |
=================================================================================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 22750 | +1697 | 1 | 5M | | | | | | | | | |
| 1 | FILTER | | | | 22750 | +1697 | 1 | 5M | | | | | | | | | |
| -> 2 | HASH JOIN | | 1 | 250M | 28875 | +679 | 1 | 5M | | | | | 681M | | 0.02 | Cpu (2) | |
| 3 | PART JOIN FILTER CREATE | :BF0000 | 1 | 1M | 1 | +679 | 1 | 5M | | | | | | | | | |
| 4 | HASH JOIN SEMI | | 1 | 1M | 254 | +426 | 1 | 5M | 4529 | 531MB | 7690 | 901MB | | | | | |
| 5 | HASH JOIN RIGHT SEMI | | 6 | 1M | 503 | +4 | 1 | 9M | | | | | | | | | |
| 6 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 1 | +4 | 1 | 1 | | | | | | | | | |
| 7 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +4 | 1 | 1 | | | | | | | | | |
| 8 | HASH JOIN RIGHT SEMI | | 355 | 1M | 503 | +4 | 1 | 9M | | | | | | | | | |
| 9 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 1 | +4 | 1 | 1 | | | | | | | | | |
| 10 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +4 | 1 | 1 | | | | | | | | | |
| 11 | HASH JOIN | | 4610 | 1M | 591 | +4 | 1 | 11M | | | | | | | | | |
| 12 | TABLE ACCESS FULL | TAB4 | 79321 | 8859 | 1 | +4 | 1 | 475 | | | | | | | | | |
| 13 | PARTITION RANGE ITERATOR | | 4291 | 1M | 254 | +341 | 1 | 40M | | | | | | | | | |
| 14 | TABLE ACCESS FULL | TAB2 | 4291 | 1M | 649 | +4 | 2 | 40M | 179K | 46GB | | | | | | | 100% |
| 15 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 18 | +662 | 1 | 1 | 1 | 8192 | | | | | | | |
| 16 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +662 | 1 | 1 | 2 | 16384 | | | | | | | |
| -> 17 | PARTITION RANGE JOIN-FILTER | | 34G | 249M | 28873 | +681 | 1 | 180M | | | | | | | | | |
| -> 18 | TABLE ACCESS FULL | TAB1 | 34G | 249M | 28875 | +679 | 2 | 180M | 17M | 184GB | | | | | 99.98 | Cpu (367) | 50% |
| | | | | | | | | | | | | | | | | latch: object queue header operation (2) | |
| | | | | | | | | | | | | | | | | db file sequential read (9626) | |
| | | | | | | | | | | | | | | | | direct path read (7) | |
| 19 | TABLE ACCESS BY INDEX ROWID | TAB5 | 1 | 1 | 1 | +4 | 1 | 1 | | | | | | | | | |
| 20 | INDEX UNIQUE SCAN | TAB5_Pk | 1 | | 1 | +4 | 1 | 1 | | | | | | | | | |
=================================================================================================================================================================================================================================================
********************* Completed in normal time when reran*********************************
Global Information
------------------------------
Status : DONE (ALL ROWS)
Instance ID : 1
SQL Execution ID : 16777216
Execution Started : 07/11/2017 08:31:04
First Refresh Time : 07/11/2017 08:31:10
Last Refresh Time : 07/11/2017 09:38:49
Duration : 4065s
Fetch Calls : 331337
Global Stats
=======================================================================================================================
| Elapsed | Cpu | IO | Application | Concurrency | Other | Fetch | Buffer | Read | Read | Write | Write |
| Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Waits(s) | Calls | Gets | Reqs | Bytes | Reqs | Bytes |
=======================================================================================================================
| 3605 | 622 | 2909 | 1.07 | 0.02 | 73 | 331K | 18M | 1M | 134GB | 7690 | 901MB |
=======================================================================================================================
SQL Plan Monitoring Details (Plan Hash Value=4053309622)
=================================================================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Write | Write | Mem | Temp | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | Reqs | Bytes | (Max) | (Max) | (%) | (# samples) |
=================================================================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 646 | +1817 | 1 | 5M | | | | | | | 0.42 | Cpu (15) |
| 1 | FILTER | | | | 646 | +1817 | 1 | 5M | | | | | | | | |
| 2 | HASH JOIN | | 1 | 251M | 2996 | +787 | 1 | 5M | | | | | 681M | | 12.45 | Cpu (441) |
| 3 | PART JOIN FILTER CREATE | :BF0000 | 1 | 1M | 8 | +785 | 1 | 5M | | | | | | | 0.03 | Cpu (1) |
| 4 | HASH JOIN SEMI | | 1 | 1M | 389 | +404 | 1 | 5M | 4529 | 531MB | 7690 | 901MB | 1G | 1G | 1.04 | Cpu (17) |
| | | | | | | | | | | | | | | | | direct path read temp (8) |
| | | | | | | | | | | | | | | | | direct path write temp (12) |
| 5 | HASH JOIN RIGHT SEMI | | 6 | 1M | 458 | +6 | 1 | 9M | | | | | 417K | | 0.08 | Cpu (3) |
| 6 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 1 | +6 | 1 | 1 | | | | | | | | |
| 7 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +6 | 1 | 1 | | | | | | | | |
| 8 | HASH JOIN RIGHT SEMI | | 374 | 1M | 458 | +6 | 1 | 9M | | | | | 401K | | 0.03 | Cpu (1) |
| 9 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 1 | +6 | 1 | 1 | | | | | | | | |
| 10 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +6 | 1 | 1 | | | | | | | | |
| 11 | HASH JOIN | | 4857 | 1M | 462 | +6 | 1 | 11M | | | | | 3M | | 0.14 | Cpu (5) |
| 12 | TABLE ACCESS FULL | TAB4 | 79321 | 8859 | 7 | +2 | 1 | 475 | 228 | 112MB | | | | | 0.17 | Cpu (2) |
| | | | | | | | | | | | | | | | | db file scattered read (4) |
| 13 | PARTITION RANGE ITERATOR | | 4521 | 1M | 142 | +326 | 1 | 40M | | | | | | | | |
| 14 | TABLE ACCESS FULL | TAB2 | 4521 | 1M | 757 | +8 | 2 | 40M | 231K | 58GB | | | | | 20.41 | enq: KO - fast object checkpoint (1) |
| | | | | | | | | | | | | | | | | Cpu (109) |
| | | | | | | | | | | | | | | | | db file parallel read (1) |
| | | | | | | | | | | | | | | | | db file sequential read (170) |
| | | | | | | | | | | | | | | | | direct path read (442) |
| 15 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 3 | 17 | +776 | 1 | 1 | | | | | | | | |
| 16 | INDEX RANGE SCAN | TAB3_Pk | 1 | 2 | 1 | +776 | 1 | 1 | | | | | | | | |
| 17 | PARTITION RANGE JOIN-FILTER | | 34G | 249M | 2989 | +794 | 1 | 222M | | | | | | | | |
| 18 | TABLE ACCESS FULL | TAB1 | 34G | 249M | 3273 | +792 | 2 | 222M | 945K | 76GB | | | | | 65.20 | enq: KO - fast object checkpoint (1) |
| | | | | | | | | | | | | | | | | Cpu (174) |
| | | | | | | | | | | | | | | | | db file parallel read (2) |
| | | | | | | | | | | | | | | | | db file sequential read (1185) |
| | | | | | | | | | | | | | | | | direct path read (947) |
| | | | | | | | | | | | | | | | | read by other session (1) |
| 19 | TABLE ACCESS BY INDEX ROWID | TAB5 | 1 | 1 | 1 | +6 | 1 | 1 | | | | | | | | |
| 20 | INDEX UNIQUE SCAN | TAB5_Pk | 1 | | 1 | +6 | 1 | 1 | | | | | | | | |
=================================================================================================================================================================================================================================
AUTO Trace Plan:
-----------------
Execution Plan
----------------------------------------------------------
Plan hash value: 4053309622
--------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time | Pstart| Pstop |
--------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 328 | | 252M (2)|842:35:01 | | |
|* 1 | FILTER | | | | | | | | |
|* 2 | HASH JOIN | | 1 | 328 | | 252M (2)|842:35:01 | | |
| 3 | PART JOIN FILTER CREATE | :BF0000 | 1 | 301 | | 2119K (1)| 07:03:52 | | |
|* 4 | HASH JOIN SEMI | | 1 | 301 | | 2119K (1)| 07:03:52 | | |
|* 5 | HASH JOIN RIGHT SEMI | | 6 | 1452 | | 2119K (1)| 07:03:52 | | |
|* 6 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 59 | | 3 (0)| 00:00:01 | | |
|* 7 | INDEX RANGE SCAN | TAB3_Pk | 1 | | | 2 (0)| 00:00:01 | | |
|* 8 | HASH JOIN RIGHT SEMI | | 375 | 68625 | | 2119K (1)| 07:03:52 | | |
|* 9 | TABLE ACCESS BY INDEX ROWID| TAB3 | 1 | 59 | | 3 (0)| 00:00:01 | | |
|* 10 | INDEX RANGE SCAN | TAB3_Pk | 1 | | | 2 (0)| 00:00:01 | | |
|* 11 | HASH JOIN | | 4871 | 589K| 4056K| 2119K (1)| 07:03:52 | | |
|* 12 | TABLE ACCESS FULL | TAB4 | 84752 | 3062K| | 8860 (1)| 00:01:47 | | |
| 13 | PARTITION RANGE ITERATOR | | 4516 | 383K| | 2110K (1)| 07:02:03 | 2 | 3 |
|* 14 | TABLE ACCESS FULL | TAB2 | 4516 | 383K| | 2110K (1)| 07:02:03 | 2 | 3 |
|* 15 | TABLE ACCESS BY INDEX ROWID | TAB3 | 1 | 59 | | 3 (0)| 00:00:01 | | |
|* 16 | INDEX RANGE SCAN | TAB3_Pk | 1 | | | 2 (0)| 00:00:01 | | |
| 17 | PARTITION RANGE JOIN-FILTER | | 34G| 856G| | 250M (2)|834:45:18 |:BF0000|:BF0000|
| 18 | TABLE ACCESS FULL | TAB1 | 34G| 856G| | 250M (2)|834:45:18 |:BF0000|:BF0000|
|* 19 | TABLE ACCESS BY INDEX ROWID | TAB5 | 1 | 6 | | 1 (0)| 00:00:01 | | |
|* 20 | INDEX UNIQUE SCAN | TAB5_Pk | 1 | | | 0 (0)| 00:00:01 | | |
--------------------------------------------------------------------------------------------------------------------------------------
Top Session stats when it was running long:
*******************************************
cell physical IO interconnect bytes 164038090752
physical read bytes 163093798912
physical read total bytes 163093094400
logical read bytes from cache 93494173696
file io wait time 10066345950
session pga memory max 1809448352
session uga memory max 1709782272
session connect time 1499751519
process last non-idle time 1499751519
physical write bytes 944947200
physical write total bytes 944947200
session pga memory 723516832
session uga memory 683733576
table scan rows gotten 353144755
bytes sent via SQL*Net to client 244914496
consistent gets 24637334
session logical reads 24637252
physical reads 19908909
table scan blocks gotten 13273424
physical reads direct 13272010
consistent gets direct 13224476
no work - consistent read gets 13202293
consistent gets from cache 11412858
consistent gets - examination 11360300
consistent changes 11240266
transaction tables consistent reads - undo records applied 11235794
non-idle wait count 7347087
physical read IO requests 6848068
physical read total IO requests 6848042
shared hash latch upgrades - no wait 6822010
free buffer inspected 6710002
free buffer requested 6639543
physical reads cache 6636900
hot buffers moved to head of LRU 2054366
DB time 1212059
non-idle wait time 1165855
user I/O wait time 1164044
workarea memory allocated 665377
dirty buffers inspected 341197
Number of read IOs issued 206644
physical read total multi block requests 206643
bytes received via SQL*Net from client 155424
data blocks consistent reads - undo records applied 120180
physical writes direct 115350
physical writes 115350
physical writes direct temporary tablespace 115350
physical writes non checkpoint 115350
CPU used by this session 101694
CPU used when call started 101694
physical reads direct temporary tablespace 67935
rollbacks only - consistent read gets 66371
user calls 21532
SQL*Net roundtrips to/from client 21529
Requests to/from client 21528
shared hash latch upgrades - wait 16961
physical write total IO requests 7690
physical write IO requests 7690
commit txn count during cleanout 4867
cleanout - number of ktugct calls 4856
immediate (CR) block cleanout applications 4855
cleanouts only - consistent read gets 4843
CR blocks created 2617
prefetched blocks aged out before use 2240