Hi all,

I am running the following SQL statement:

INSERT /*+APPEND*/ INTO S_ETL_I_IMG_6 (ROW_ID, MODIFICATION_NUM,
OPERATION, LAST_UPD)
SELECT /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ ROW_ID
,MODIFICATION_NUM ,'I' ,LAST_UPD
FROM S_ASSET WHERE S_ASSET.LAST_UPD > TO_DATE('2006-06-02 02:26:36',
'YYYY-MM-DD HH:MI:SS')
AND NOT EXISTS ( SELECT ROW_ID ,MODIFICATION_NUM ,'I' ,LAST_UPD
FROM S_ETL_R_IMG_6
WHERE S_ETL_R_IMG_6.ROW_ID = S_ASSET.ROW_ID
AND S_ETL_R_IMG_6.MODIFICATION_NUM = S_ASSET.MODIFICATION_NUM
AND S_ETL_R_IMG_6.LAST_UPD = S_ASSET.LAST_UPD )

The execution plan for this statement is:

-----------------------------------------------------------------
| Id | Operation | Name | Rows |
-----------------------------------------------------------------
| 0 | INSERT STATEMENT | | |
| 1 | LOAD AS SELECT | | |
| 2 | FILTER | | |
| 3 | INDEX FAST FULL SCAN | S_ASSET_BT_W1_X | 33324 |
| 4 | TABLE ACCESS BY INDEX ROWID| S_ETL_R_IMG_6 | 1 |
| 5 | INDEX RANGE SCAN | S_ETL_R_IMG_6_M1 | 26 |
-----------------------------------------------------------------


This query is running inexplicably slow. I think the execution plan is
reasonably optimal. However when I query the V$SESSION_WAIT view
repeatedly, I am getting the wait event as:

SID EVENT P1 P2 P3
WAIT_TIME SECONDS_IN_WAIT
----- ------------------------------ ---------- ---------- ----------
---------- ---------------
71 db file sequential read 263 50960 1
1 897


The p1, p2 and p3 remain the same. Only the SECONDS_IN_WAIT count keeps
on increasing in steps of 3 (reached 990 right now).

I am at a loss as what to make of this wait event. Does this mean that
Oracle is taking time to read that one block into memory? Does this
indicate hot-spots in the disk (I am not very clear of this concept!!)


Could anybody please help in explaining this behaviour and suggest a
possible remedy.


Many thanks,
Charu.

joshic75@gmail.com wrote:
> Hi all,
>
> I am running the following SQL statement:
>
> INSERT /*+APPEND*/ INTO S_ETL_I_IMG_6 (ROW_ID, MODIFICATION_NUM,
> OPERATION, LAST_UPD)
> SELECT /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ ROW_ID
> ,MODIFICATION_NUM ,'I' ,LAST_UPD
> FROM S_ASSET WHERE S_ASSET.LAST_UPD > TO_DATE('2006-06-02 02:26:36',
> 'YYYY-MM-DD HH:MI:SS')
> AND NOT EXISTS ( SELECT ROW_ID ,MODIFICATION_NUM ,'I' ,LAST_UPD
> FROM S_ETL_R_IMG_6
> WHERE S_ETL_R_IMG_6.ROW_ID = S_ASSET.ROW_ID
> AND S_ETL_R_IMG_6.MODIFICATION_NUM = S_ASSET.MODIFICATION_NUM
> AND S_ETL_R_IMG_6.LAST_UPD = S_ASSET.LAST_UPD )
>
> The execution plan for this statement is:
>
> -----------------------------------------------------------------
> | Id | Operation | Name | Rows |
> -----------------------------------------------------------------
> | 0 | INSERT STATEMENT | | |
> | 1 | LOAD AS SELECT | | |
> | 2 | FILTER | | |
> | 3 | INDEX FAST FULL SCAN | S_ASSET_BT_W1_X | 33324 |
> | 4 | TABLE ACCESS BY INDEX ROWID| S_ETL_R_IMG_6 | 1 |
> | 5 | INDEX RANGE SCAN | S_ETL_R_IMG_6_M1 | 26 |
> -----------------------------------------------------------------
>
>
> This query is running inexplicably slow. I think the execution plan is
> reasonably optimal. However when I query the V$SESSION_WAIT view
> repeatedly, I am getting the wait event as:
>
> SID EVENT P1 P2 P3
> WAIT_TIME SECONDS_IN_WAIT
> ----- ------------------------------ ---------- ---------- ----------
> ---------- ---------------
> 71 db file sequential read 263 50960 1
> 1 897
>
>
> The p1, p2 and p3 remain the same. Only the SECONDS_IN_WAIT count keeps
> on increasing in steps of 3 (reached 990 right now).
>
> I am at a loss as what to make of this wait event. Does this mean that
> Oracle is taking time to read that one block into memory? Does this
> indicate hot-spots in the disk (I am not very clear of this concept!!)
>
>
> Could anybody please help in explaining this behaviour and suggest a
> possible remedy.
>
>
> Many thanks,
> Charu.

Hi Charu,

What version/OS? What kind of disk is this on? Are you seeing I/O
waits at the OS?

Regards,

Steve

joshic75@gmail.com wrote:
> Hi all,
>
> I am running the following SQL statement:
>
> INSERT /*+APPEND*/ INTO S_ETL_I_IMG_6 (ROW_ID, MODIFICATION_NUM,
> OPERATION, LAST_UPD)
> SELECT /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ ROW_ID
> ,MODIFICATION_NUM ,'I' ,LAST_UPD
> FROM S_ASSET WHERE S_ASSET.LAST_UPD > TO_DATE('2006-06-02 02:26:36',
> 'YYYY-MM-DD HH:MI:SS')
> AND NOT EXISTS ( SELECT ROW_ID ,MODIFICATION_NUM ,'I' ,LAST_UPD
> FROM S_ETL_R_IMG_6
> WHERE S_ETL_R_IMG_6.ROW_ID = S_ASSET.ROW_ID
> AND S_ETL_R_IMG_6.MODIFICATION_NUM = S_ASSET.MODIFICATION_NUM
> AND S_ETL_R_IMG_6.LAST_UPD = S_ASSET.LAST_UPD )
>
> The execution plan for this statement is:
>
> -----------------------------------------------------------------
> | Id | Operation | Name | Rows |
> -----------------------------------------------------------------
> | 0 | INSERT STATEMENT | | |
> | 1 | LOAD AS SELECT | | |
> | 2 | FILTER | | |
> | 3 | INDEX FAST FULL SCAN | S_ASSET_BT_W1_X | 33324 |
> | 4 | TABLE ACCESS BY INDEX ROWID| S_ETL_R_IMG_6 | 1 |
> | 5 | INDEX RANGE SCAN | S_ETL_R_IMG_6_M1 | 26 |
> -----------------------------------------------------------------
>
>
> This query is running inexplicably slow. I think the execution plan is
> reasonably optimal. However when I query the V$SESSION_WAIT view
> repeatedly, I am getting the wait event as:
>
> SID EVENT P1 P2 P3
> WAIT_TIME SECONDS_IN_WAIT
> ----- ------------------------------ ---------- ---------- ----------
> ---------- ---------------
> 71 db file sequential read 263 50960 1
> 1 897
>
>
> The p1, p2 and p3 remain the same. Only the SECONDS_IN_WAIT count keeps
> on increasing in steps of 3 (reached 990 right now).
>
> I am at a loss as what to make of this wait event. Does this mean that
> Oracle is taking time to read that one block into memory? Does this
> indicate hot-spots in the disk (I am not very clear of this concept!!)
>
>
> Could anybody please help in explaining this behaviour and suggest a
> possible remedy.
>
>
> Many thanks,
> Charu.

What version of Oracle?
Rerun the EXPLAIN PLAN using DBMS_XPLAN if 9i or greater without the
hints and with the hints.
--
Daniel A. Morgan
University of Washington
damorgan@x.washington.edu
(replace x with u to respond)
Puget Sound Oracle Users Group
www.psoug.org

Hi Steve and Dan,

Many thanks for replying. My apologies - I should have mentioned the
version before hand.

Anyway its 9.2.0.6 EE. OS is Solaris 8.

I had a chat with our DBA who said that statspack shows the average db
file sequential read times between 2 to 11 ms, which seems to be quite
healthy.

The hardware is quite powerful with 24 CPUs, 16GB RAM , SAN storage
etc. So I doubt that it will be a problem at the OS level.

Of late I am seeing this behaviour (huge db file sequential read waits
on the same block) on different databases. So I was wondering if
anybody else had seen this behaviour before and knows the reason behind
it.

Ours is a data warehousing environment, so the queries process large
volumes of data. However we still have a setup that favours indexed
scans (no partitioning, parallelism, bitmap indexes as yet). Also we
have manipulated the system statistics to reduce the SREADTIM compared
to MREADTIM to favour indexed scans. I sometimes wonder if that might
be the reason for seeing such behaviour.

Would anybody like to throw more light on this?

Many thanks,
Charu.

joshic75@gmail.com wrote:
> Hi Steve and Dan,
>
> Many thanks for replying. My apologies - I should have mentioned the
> version before hand.
>
> Anyway its 9.2.0.6 EE. OS is Solaris 8.
>
> I had a chat with our DBA who said that statspack shows the average db
> file sequential read times between 2 to 11 ms, which seems to be quite
> healthy.
>
> The hardware is quite powerful with 24 CPUs, 16GB RAM , SAN storage
> etc. So I doubt that it will be a problem at the OS level.
>
> Of late I am seeing this behaviour (huge db file sequential read waits
> on the same block) on different databases. So I was wondering if
> anybody else had seen this behaviour before and knows the reason behind
> it.
>
> Ours is a data warehousing environment, so the queries process large
> volumes of data. However we still have a setup that favours indexed
> scans (no partitioning, parallelism, bitmap indexes as yet). Also we
> have manipulated the system statistics to reduce the SREADTIM compared
> to MREADTIM to favour indexed scans. I sometimes wonder if that might
> be the reason for seeing such behaviour.
>
> Would anybody like to throw more light on this?
>
> Many thanks,
> Charu.

Charu,

Have you set a 10046 trace? 900 seconds for single block read is not
good. 3 seconds is the timeout on this event before it is posted
again, so there is some reason that Oracle cannot get that block. I
would be curious to see what the raw 10046 trace looks like. Does it
literally look something similar to the following?

WAIT #1: nam='db file sequential read' ela= 3000000 file#=263
block#=50960 blocks=1 obj#=0 tim=64996433721
WAIT #1: nam='db file sequential read' ela= 3000000 file#=263
block#=50960 blocks=1 obj#=0 tim=64999433721
WAIT #1: nam='db file sequential read' ela= 3000000 file#=263
block#=50960 blocks=1 obj#=0 tim=65002433721
WAIT #1: nam='db file sequential read' ela= 3000000 file#=263
block#=50960 blocks=1 obj#=0 tim=65005433721
WAIT #1: nam='db file sequential read' ela= 3000000 file#=263
block#=50960 blocks=1 obj#=0 tim=65008433721
....

Regards,

Steve

joshic75@gmail.com wrote:
> Hi Steve and Dan,
>
> Many thanks for replying. My apologies - I should have mentioned the
> version before hand.
>
> Anyway its 9.2.0.6 EE. OS is Solaris 8.
>
> I had a chat with our DBA who said that statspack shows the average db
> file sequential read times between 2 to 11 ms, which seems to be quite
> healthy.
>
> The hardware is quite powerful with 24 CPUs, 16GB RAM , SAN storage
> etc. So I doubt that it will be a problem at the OS level.
>
> Of late I am seeing this behaviour (huge db file sequential read waits
> on the same block) on different databases. So I was wondering if
> anybody else had seen this behaviour before and knows the reason behind
> it.
>
> Ours is a data warehousing environment, so the queries process large
> volumes of data. However we still have a setup that favours indexed
> scans (no partitioning, parallelism, bitmap indexes as yet). Also we
> have manipulated the system statistics to reduce the SREADTIM compared
> to MREADTIM to favour indexed scans. I sometimes wonder if that might
> be the reason for seeing such behaviour.
>
> Would anybody like to throw more light on this?
>
> Many thanks,
> Charu.

I am going to morph from instructor to student and await Jonathan Lewis
who will hopefully respond.

Until then I will paraphrase what I have heard Jonathan say: Give the
optimizer the best, most complete, and most accurate information from
which to make decisions. Altering your system stats may be part of the
problem but it may also be helping some queries while hurting others.
I'd certainly be inclined to return them to their default and see what
affect it would have (hopefully on a test box).
--
Daniel A. Morgan
University of Washington
damorgan@x.washington.edu
(replace x with u to respond)
Puget Sound Oracle Users Group
www.psoug.org

On Tue, 04 Jul 2006 08:02:03 -0700, joshic75 wrote:

>
> Could anybody please help in explaining this behaviour and suggest a
> possible remedy.

What you have shown is consistent with the reasonable expectation. You are
doing single block reads aka "db file sequential read" and your plan shows
that you're using the index. Unfortunately, you're accessing only indexes,
as the consequence of the /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ . Get
rid of that hint and you will probably perform fewer db file scattered
read events, also known as "multiblock reads". In the end, multiblock
reads should be faster. Your INDEX_FFS hint was probably a trick to make
"NOT EXISTS" predicate work faster. The "NOT EXISTS" can sometimes be
re-formulated as minus, which I find easier to understand and optimize.

--
http://www.mgogala.com

Mladen Gogala wrote:
> On Tue, 04 Jul 2006 08:02:03 -0700, joshic75 wrote:
>
> >
> > Could anybody please help in explaining this behaviour and suggest a
> > possible remedy.
>
> What you have shown is consistent with the reasonable expectation. You are
> doing single block reads aka "db file sequential read" and your plan shows
> that you're using the index. Unfortunately, you're accessing only indexes,
> as the consequence of the /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ . Get
> rid of that hint and you will probably perform fewer db file scattered
> read events, also known as "multiblock reads". In the end, multiblock
> reads should be faster. Your INDEX_FFS hint was probably a trick to make
> "NOT EXISTS" predicate work faster. The "NOT EXISTS" can sometimes be
> re-formulated as minus, which I find easier to understand and optimize.
>
> --
> http://www.mgogala.com

This depends on the data. A MINUS will almost always full scan at
least one table in the query being "minused". An EXISTS will run once
for each row returned by the outer query (33,000 times in this case).
Depending on how much data is in S_ETL_R_IMG_6, it may be better or
worse. If S_ETL_R_IMG_6 is small, it will be better, if large...

Regards,

Steve

On 4 Jul 2006 10:10:19 -0700, joshic75@gmail.com wrote:

>The hardware is quite powerful with 24 CPUs, 16GB RAM , SAN storage
>etc. So I doubt that it will be a problem at the OS level.


Or someone subscribes to the 'More is better' tuning methodology.
That methodology is poweful enough to bring any server on it's knees.
You are sure you are not incurring 'buffer busy waits' on exactly that
block?

--
Sybrand Bakker, Senior Oracle DBA

<joshic75@gmail.com> a écrit dans le message de news: 1152025323.596622.207890@m79g2000cwm.googlegroups. com...
| Hi all,
|
| I am running the following SQL statement:
|
| INSERT /*+APPEND*/ INTO S_ETL_I_IMG_6 (ROW_ID, MODIFICATION_NUM,
| OPERATION, LAST_UPD)
| SELECT /*+ index_ffs(s_asset, s_asset_bt_w1_x) */ ROW_ID
| ,MODIFICATION_NUM ,'I' ,LAST_UPD
| FROM S_ASSET WHERE S_ASSET.LAST_UPD > TO_DATE('2006-06-02 02:26:36',
| 'YYYY-MM-DD HH:MI:SS')
| AND NOT EXISTS ( SELECT ROW_ID ,MODIFICATION_NUM ,'I' ,LAST_UPD
| FROM S_ETL_R_IMG_6
| WHERE S_ETL_R_IMG_6.ROW_ID = S_ASSET.ROW_ID
| AND S_ETL_R_IMG_6.MODIFICATION_NUM = S_ASSET.MODIFICATION_NUM
| AND S_ETL_R_IMG_6.LAST_UPD = S_ASSET.LAST_UPD )
|
| The execution plan for this statement is:
|
| -----------------------------------------------------------------
|| Id | Operation | Name | Rows |
| -----------------------------------------------------------------
|| 0 | INSERT STATEMENT | | |
|| 1 | LOAD AS SELECT | | |
|| 2 | FILTER | | |
|| 3 | INDEX FAST FULL SCAN | S_ASSET_BT_W1_X | 33324 |
|| 4 | TABLE ACCESS BY INDEX ROWID| S_ETL_R_IMG_6 | 1 |
|| 5 | INDEX RANGE SCAN | S_ETL_R_IMG_6_M1 | 26 |
| -----------------------------------------------------------------
|
|
| This query is running inexplicably slow. I think the execution plan is
| reasonably optimal. However when I query the V$SESSION_WAIT view
| repeatedly, I am getting the wait event as:
|
| SID EVENT P1 P2 P3
| WAIT_TIME SECONDS_IN_WAIT
| ----- ------------------------------ ---------- ---------- ----------
| ---------- ---------------
| 71 db file sequential read 263 50960 1
| 1 897
|
|
| The p1, p2 and p3 remain the same. Only the SECONDS_IN_WAIT count keeps
| on increasing in steps of 3 (reached 990 right now).
|
| I am at a loss as what to make of this wait event. Does this mean that
| Oracle is taking time to read that one block into memory? Does this
| indicate hot-spots in the disk (I am not very clear of this concept!!)
|
|
| Could anybody please help in explaining this behaviour and suggest a
| possible remedy.
|
|
| Many thanks,
| Charu.
|

From doc. about v$session_wait.seconds_in_wait:

<quote>
If WAIT_TIME > 0, then SECONDS_IN_WAIT is the seconds since the start of the last wait
....
WAIT_TIME = duration of last wait
</quote>

Your last wait time lasted 1cs and it started 897s before.

Regards
Michel Cadot