Skip to Main Content
  • Questions

  • Slow query with high wait on db file sequential read

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, Jaruwan.

Asked: June 04, 2012 - 11:48 am UTC

Last updated: March 11, 2013 - 8:16 am UTC

Version: 11.2.0.3

Viewed 10K+ times! This question is

You Asked

I have a production database running on RDBMS 11.2.0.3 and serving as a BI report, multiple dashboard reports running with slow response time, high wait event on db sequential read on partitioned tables (partitioned on regions (AMER, APAC and EMEA). Our storage is on ASM on tier 1 data (fastest). Is there anything I can do to improve the query runtime?

Example of wait event
WAIT #4575645344: nam='db file sequential read' ela= 339 file#=12 block#=939391 blocks=1 obj#=98282 tim=11248103069561
WAIT #4575645344: nam='db file sequential read' ela= 342 file#=12 block#=939392 blocks=1 obj#=98282 tim=11248103070120
WAIT #4575645344: nam='db file sequential read' ela= 342 file#=12 block#=939393 blocks=1 obj#=98282 tim=11248103070636
WAIT #4575645344: nam='db file sequential read' ela= 387 file#=12 block#=939394 blocks=1 obj#=98282 tim=11248103071259
WAIT #4575645344: nam='db file sequential read' ela= 339 file#=12 block#=939395 blocks=1 obj#=98282 tim=11248103071811
WAIT #4575645344: nam='db file sequential read' ela= 310 file#=12 block#=939396 blocks=1 obj#=98282 tim=11248103072275
WAIT #4575645344: nam='db file sequential read' ela= 440 file#=12 block#=939397 blocks=1 obj#=98282 tim=11248103072934
WAIT #4575645344: nam='db file sequential read' ela= 336 file#=12 block#=939398 blocks=1 obj#=98282 tim=11248103073393
WAIT #4575645344: nam='db file sequential read' ela= 327 file#=12 block#=939399 blocks=1 obj#=98282 tim=11248103073912

sql> select owner,object_name,subobject_name from dba_objects where object_id = '98282'
SQL> /

OWNER OBJECT_NAME SUBOBJECT_NAME
---------- -------------------- ------------------------------
DWH_GLOBAL W_SALES_CYCLE_LINE_F AMER

Top user events from ASH
event "db file sequential read" %event - 94.30

Top DB Objects from ASH
event "dwh_global.w_sales_cycle_line_f(AMER)" %activity=92.57%

Tkprof output (run after I flush all buffer cache)
WITH
SAWITH0 AS (select sum(case when T96574.W_XACT_TYPE_CODE = 'Regular' then T93511.X_REQ_DT_SHIPPED_LATE_LNS else NULL end ) as c1,
sum(case when T96574.W_XACT_TYPE_CODE = 'Regular' then T93511.X_REQ_DT_SHIPPED_EARLY_LNS else NULL end ) as c2,
sum(case when T96574.W_XACT_TYPE_CODE = 'Regular' then T93511.X_TOTAL_SHIPPED_LNS else NULL end ) as c3,
sum(case when T96574.W_XACT_TYPE_CODE = 'Regular' then T93511.X_REQ_DT_SHIPPED_ONTIME_LNS else NULL end ) as c4,
T312200.PER_NAME_ENT_PERIOD as c5,
T312200.ENT_PERIOD_START_DT as c6
from
W_DAY_D T312200 /* Dim_W_DAY_D_Actual_Last_Shipped */ ,
W_BUSN_LOCATION_D T95031 /* Dim_W_BUSN_LOCATION_D_Plant */ ,
W_SALES_CYCLE_LINE_F T93511 /* Fact_W_SALES_CYCLE_LINE_F */ ,
W_XACT_TYPE_D T96574 /* Dim_W_XACT_TYPE_D_Sales_Ordlns */
where ( T93511.PLANT_LOC_WID = T95031.ROW_WID
and T93511.ACT_LAST_SHIPPED_ON_DT_WID = T312200.ROW_WID
and T93511.XACT_TYPE_WID = T96574.ROW_WID
and T93511.DATASOURCE_NUM_ID = T95031.DATASOURCE_NUM_ID
and T93511.DELETE_FLG = 'N'
and T93511.DATASOURCE_NUM_ID = T96574.DATASOURCE_NUM_ID
and T93511.DATASOURCE_NUM_ID = 4.0
and T95031.COUNTRY_NAME = 'United States'
and T95031.DATASOURCE_NUM_ID = 4.0
and '2011 / 05' < T312200.PER_NAME_MONTH
and (T95031.ROW_WID in (0) or T95031.BUSN_LOC_TYPE in ('PLANT')) )
group by T312200.PER_NAME_ENT_PERIOD, T312200.ENT_PERIOD_START_DT)
select distinct SAWITH0.c5 as c1,
SAWITH0.c4 as c2,
SAWITH0.c3 as c3,
case when SAWITH0.c3 = 0 then 0 else SAWITH0.c4 / nullif( SAWITH0.c3, 0) * 100 end as c4,
SAWITH0.c2 as c5,
SAWITH0.c1 as c6,
SAWITH0.c6 as c7
from
SAWITH0
order by c7

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.12 0 0 0 0
Execute 1 0.03 1.29 76 704 28 0
Fetch 2 25.62 579.47 237344 250068 3 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 25.72 580.90 237420 250772 31 12

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
12 12 12 TEMP TABLE TRANSFORMATION (cr=250772 pr=237420 pw=7 time=580766361 us)
0 0 0 LOAD AS SELECT (cr=684 pr=58 pw=2 time=1049509 us)
1704 1704 1704 TABLE ACCESS BY INDEX ROWID W_DAY_D (cr=684 pr=57 pw=0 time=3666225 us cost=0 size=220980 card=1740)
1704 1704 1704 INDEX RANGE SCAN W_DAY_D_M60 (cr=3 pr=3 pw=0 time=33438 us cost=0 size=0 card=1740)(object id 205210)
0 0 0 LOAD AS SELECT (cr=10 pr=10 pw=1 time=118648 us)
42 42 42 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=10 pr=9 pw=0 time=54257 us cost=15 size=1080 card=30)
42 42 42 TABLE ACCESS BY LOCAL INDEX ROWID W_BUSN_LOCATION_D PARTITION: 1 1 (cr=10 pr=9 pw=0 time=54197 us cost=15 size=1080 card=30)
42 42 42 BITMAP CONVERSION TO ROWIDS (cr=8 pr=7 pw=0 time=47395 us)
1 1 1 BITMAP AND (cr=8 pr=7 pw=0 time=47341 us)
2 2 2 BITMAP INDEX SINGLE VALUE W_BUSN_LOC_D_M3 PARTITION: 1 1 (cr=4 pr=3 pw=0 time=24440 us)(object id 141361)
1 1 1 BITMAP OR (cr=4 pr=4 pw=0 time=22836 us)
1 1 1 BITMAP INDEX SINGLE VALUE W_BUSN_LOC_D_M13 PARTITION: 1 1 (cr=2 pr=2 pw=0 time=11448 us)(object id 141376)
1 1 1 BITMAP CONVERSION FROM ROWIDS (cr=2 pr=2 pw=0 time=11348 us)
1 1 1 SORT ORDER BY (cr=2 pr=2 pw=0 time=11332 us)
1 1 1 INDEX RANGE SCAN W_BUSN_LOC_D_P1 PARTITION: 1 1 (cr=2 pr=2 pw=0 time=11230 us cost=2 size=0 card=0)(object id 141296)
0 0 0 LOAD AS SELECT (cr=10 pr=8 pw=4 time=120518 us)
4358 4358 4358 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=10 pr=7 pw=0 time=55915 us cost=5 size=91518 card=4358)
4358 4358 4358 INDEX FAST FULL SCAN W_XACT_TYPE_D_U2 PARTITION: 1 1 (cr=10 pr=7 pw=0 time=54402 us cost=5 size=91518 card=4358)(object id 148481)
12 12 12 SORT GROUP BY (cr=250068 pr=237344 pw=0 time=579475379 us cost=8015 size=5463512 card=29693)
1723214 1723214 1723214 HASH JOIN (cr=250068 pr=237344 pw=0 time=467427194 us cost=7522 size=5463512 card=29693)
4358 4358 4358 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1F_490D08CF (cr=7 pr=4 pw=0 time=2614 us cost=5 size=91518 card=4358)
1723214 1723214 1723214 HASH JOIN (cr=250061 pr=237340 pw=0 time=464782400 us cost=7516 size=4839959 card=29693)
1704 1704 1704 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1D_490D08CF (cr=5 pr=2 pw=0 time=3922 us cost=6 size=203580 card=1740)
1723214 1723214 1723214 HASH JOIN (cr=250056 pr=237338 pw=0 time=462382480 us cost=7510 size=1365878 card=29693)
42 42 42 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1E_490D08CF (cr=4 pr=1 pw=0 time=13235 us cost=3 size=270 card=30)
1723214 1723214 1723214 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=250052 pr=237337 pw=0 time=458150125 us cost=7506 size=1098641 card=29693)
1723214 1723214 1723214 TABLE ACCESS BY LOCAL INDEX ROWID W_SALES_CYCLE_LINE_F PARTITION: 1 1 (cr=250052 pr=237337 pw=0 time=457531613 us cost=7506 size=1098641 car
d=29693)
1723214 1723214 1723214 BITMAP CONVERSION TO ROWIDS (cr=13633 pr=918 pw=0 time=6372139 us)
46 46 46 BITMAP AND (cr=13633 pr=918 pw=0 time=6679579 us)
59 59 59 BITMAP MERGE (cr=355 pr=248 pw=0 time=2042492 us)
23814 23814 23814 BITMAP KEY ITERATION (cr=355 pr=248 pw=0 time=1293967 us)
42 42 42 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1E_490D08CF (cr=2 pr=0 pw=0 time=1090 us cost=3 size=180 card=30)
23814 23814 23814 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F32 PARTITION: 1 1 (cr=353 pr=248 pw=0 time=15029255 us)(object id 122471)
46 46 46 BITMAP MERGE (cr=4010 pr=203 pw=0 time=1215799 us)
526 526 526 BITMAP KEY ITERATION (cr=4010 pr=203 pw=0 time=1366057 us)
1704 1704 1704 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1D_490D08CF (cr=3 pr=0 pw=0 time=3844 us cost=6 size=10440 card=1740)
526 526 526 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F52 PARTITION: 1 1 (cr=4007 pr=203 pw=0 time=443799 us)(object id 122451)
59 59 59 BITMAP MERGE (cr=9188 pr=387 pw=0 time=2702418 us)
40575 40575 40575 BITMAP KEY ITERATION (cr=9188 pr=387 pw=0 time=996154 us)
4358 4358 4358 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1F_490D08CF (cr=5 pr=0 pw=0 time=4181 us cost=5 size=21790 card=4358)
40575 40575 40575 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F47 PARTITION: 1 1 (cr=9183 pr=387 pw=0 time=13576647 us)(object id 122316)
4810 4810 4810 BITMAP INDEX SINGLE VALUE W_SLS_CC_LN_F_M1 PARTITION: 1 1 (cr=80 pr=80 pw=0 time=14835 us)(object id 122311)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 237409 0.93 548.09
Disk file operations I/O 12 0.00 0.00
CSS initialization 1 0.07 0.07
CSS operation: query 6 0.00 0.00
CSS operation: action 1 0.00 0.00
direct path write temp 3 0.01 0.02
db file scattered read 4 0.03 0.05
SQL*Net message to client 2 0.00 0.00
asynch descriptor resize 2 0.00 0.00
SQL*Net message from client 2 0.00 0.00
********************************************************************************

and Tom said...

there is nothing useful here - could you read this??? I sure cannot. (use the code button so we have a fixed width font so we can actually read this)


It looks like you are getting IO's in the 0.002 (2ms) timeframe, that is excellent. 548.09/237409

You are doing 237,420 of them - when you do a lot of something, no matter how fast it is, it adds up.

they are all db file sequential reads - index reads - perhaps you have over indexed.


the only way to make this query faster would be to find a way to do it that uses less physical IO or *better* physical IO (like big juicy multiblock reads)



Rating

  (6 ratings)

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

Comments

Jaruwan Na Ranong, June 04, 2012 - 12:38 pm UTC

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

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
12 12 12 TEMP TABLE TRANSFORMATION (cr=250772 pr=237420 pw=7 time=580766361 us)
0 0 0 LOAD AS SELECT (cr=684 pr=58 pw=2 time=1049509 us)
1704 1704 1704 TABLE ACCESS BY INDEX ROWID W_DAY_D (cr=684 pr=57 pw=0 time=3666225 us cost=0 size=220980 card=1740)
1704 1704 1704 INDEX RANGE SCAN W_DAY_D_M60 (cr=3 pr=3 pw=0 time=33438 us cost=0 size=0 card=1740)(object id 205210)
0 0 0 LOAD AS SELECT (cr=10 pr=10 pw=1 time=118648 us)
42 42 42 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=10 pr=9 pw=0 time=54257 us cost=15 size=1080 card=30)
42 42 42 TABLE ACCESS BY LOCAL INDEX ROWID W_BUSN_LOCATION_D PARTITION: 1 1 (cr=10 pr=9 pw=0 time=54197 us cost=15 size=1080 card=30)
42 42 42 BITMAP CONVERSION TO ROWIDS (cr=8 pr=7 pw=0 time=47395 us)
1 1 1 BITMAP AND (cr=8 pr=7 pw=0 time=47341 us)
2 2 2 BITMAP INDEX SINGLE VALUE W_BUSN_LOC_D_M3 PARTITION: 1 1 (cr=4 pr=3 pw=0 time=24440 us)(object id 141361)
1 1 1 BITMAP OR (cr=4 pr=4 pw=0 time=22836 us)
1 1 1 BITMAP INDEX SINGLE VALUE W_BUSN_LOC_D_M13 PARTITION: 1 1 (cr=2 pr=2 pw=0 time=11448 us)(object id 141376)
1 1 1 BITMAP CONVERSION FROM ROWIDS (cr=2 pr=2 pw=0 time=11348 us)
1 1 1 SORT ORDER BY (cr=2 pr=2 pw=0 time=11332 us)
1 1 1 INDEX RANGE SCAN W_BUSN_LOC_D_P1 PARTITION: 1 1 (cr=2 pr=2 pw=0 time=11230 us cost=2 size=0 card=0)(object id 141296)
0 0 0 LOAD AS SELECT (cr=10 pr=8 pw=4 time=120518 us)
4358 4358 4358 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=10 pr=7 pw=0 time=55915 us cost=5 size=91518 card=4358)
4358 4358 4358 INDEX FAST FULL SCAN W_XACT_TYPE_D_U2 PARTITION: 1 1 (cr=10 pr=7 pw=0 time=54402 us cost=5 size=91518 card=4358)(object id 148481)
12 12 12 SORT GROUP BY (cr=250068 pr=237344 pw=0 time=579475379 us cost=8015 size=5463512 card=29693)
1723214 1723214 1723214 HASH JOIN (cr=250068 pr=237344 pw=0 time=467427194 us cost=7522 size=5463512 card=29693)
4358 4358 4358 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1F_490D08CF (cr=7 pr=4 pw=0 time=2614 us cost=5 size=91518 card=4358)
1723214 1723214 1723214 HASH JOIN (cr=250061 pr=237340 pw=0 time=464782400 us cost=7516 size=4839959 card=29693)
1704 1704 1704 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1D_490D08CF (cr=5 pr=2 pw=0 time=3922 us cost=6 size=203580 card=1740)
1723214 1723214 1723214 HASH JOIN (cr=250056 pr=237338 pw=0 time=462382480 us cost=7510 size=1365878 card=29693)
42 42 42 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1E_490D08CF (cr=4 pr=1 pw=0 time=13235 us cost=3 size=270 card=30)
1723214 1723214 1723214 PARTITION LIST SINGLE PARTITION: KEY KEY (cr=250052 pr=237337 pw=0 time=458150125 us cost=7506 size=1098641 card=29693)
1723214 1723214 1723214 TABLE ACCESS BY LOCAL INDEX ROWID W_SALES_CYCLE_LINE_F PARTITION: 1 1 (cr=250052 pr=237337 pw=0 time=457531613 us cost=7506 size=1098641 car
d=29693)
1723214 1723214 1723214 BITMAP CONVERSION TO ROWIDS (cr=13633 pr=918 pw=0 time=6372139 us)
46 46 46 BITMAP AND (cr=13633 pr=918 pw=0 time=6679579 us)
59 59 59 BITMAP MERGE (cr=355 pr=248 pw=0 time=2042492 us)
23814 23814 23814 BITMAP KEY ITERATION (cr=355 pr=248 pw=0 time=1293967 us)
42 42 42 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1E_490D08CF (cr=2 pr=0 pw=0 time=1090 us cost=3 size=180 card=30)
23814 23814 23814 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F32 PARTITION: 1 1 (cr=353 pr=248 pw=0 time=15029255 us)(object id 122471)
46 46 46 BITMAP MERGE (cr=4010 pr=203 pw=0 time=1215799 us)
526 526 526 BITMAP KEY ITERATION (cr=4010 pr=203 pw=0 time=1366057 us)
1704 1704 1704 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1D_490D08CF (cr=3 pr=0 pw=0 time=3844 us cost=6 size=10440 card=1740)
526 526 526 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F52 PARTITION: 1 1 (cr=4007 pr=203 pw=0 time=443799 us)(object id 122451)
59 59 59 BITMAP MERGE (cr=9188 pr=387 pw=0 time=2702418 us)
40575 40575 40575 BITMAP KEY ITERATION (cr=9188 pr=387 pw=0 time=996154 us)
4358 4358 4358 TABLE ACCESS FULL SYS_TEMP_0FD9E6F1F_490D08CF (cr=5 pr=0 pw=0 time=4181 us cost=5 size=21790 card=4358)
40575 40575 40575 BITMAP INDEX RANGE SCAN W_SLS_CC_LN_F_F47 PARTITION: 1 1 (cr=9183 pr=387 pw=0 time=13576647 us)(object id 122316)
4810 4810 4810 BITMAP INDEX SINGLE VALUE W_SLS_CC_LN_F_M1 PARTITION: 1 1 (cr=80 pr=80 pw=0 time=14835 us)(object id 122311)
Tom Kyte
June 04, 2012 - 12:56 pm UTC

the answer is the same, you need to make it do less physical IO - I don't know what else I can say honestly.


And this is still not very readable :)


but in any case - one would need a ton of information to "tune" a query - like knowledge of the schema, the question being asked, the data patterns (how the rows are actually physically loaded on disk - in what order) and so on (I don't want all of that, I cannot just tune queries like that)

for "auto tuning" advice, run it through a sql tuning set and see what OEM says.


Jaruwan Na Ranong, June 06, 2012 - 10:59 am UTC

If I can not make less I/O reading, is there possibility that the query can run in multiple threads and still reading index wihout doing full tablescan especially W_SALES_CYCLE_LINE_F partition (AMER).
Tom Kyte
June 06, 2012 - 11:35 am UTC

no, not really.

Jaruwan Na Ranong, June 06, 2012 - 11:42 am UTC

I have run the SQL tuning advisor from OEM and no recommendation generated. So basically the query perform on its best already based on current configuration of everything. So index scaning can not be run in parallel unless it is fast full scan index?

Tom Kyte
June 06, 2012 - 1:02 pm UTC

correct, unless they are partitioned.

but even so, if you go parallel, you'll increase the IO wait times for each individual IO since you'll be hitting it even harder than you are now.

why are you afraid of a full scan?

Jaruwan Na Ranong, June 06, 2012 - 2:59 pm UTC

We partition table DWH_GLOBAL.W_SALES_CYCLE_LINE_F on region, currently we use partition "AMER" (where datasource_num_id = 4.0) and the query seem to after 10% of partition. I have tried with full tablescan on DWH_GLOBAL.W_SALES_CYCLE_LINE_F (AMER) and it run longer. And based on the WHERE clause only 2 columns that seem to be candidate for partition (DELETE_FLG and DATASOURCE_NUM_ID), right now DELETE_FLG = 'N' is entire AMER partition.

History of file# or object# for db file sequetial read evet

Pratik Shah, March 08, 2013 - 8:59 am UTC

Hello sir,
Is there any way I can see history of "db file sequential read" event for one session? Basically I want to know that on which object the session spent more time while doing "db file sequetial read". There is a performance issue with of merge statement and I don't have trace enabled for the session. But at runtime, I noticed in v$session.event = 'db file sequential read' and v$session.p1= 'undo tablespace file id'.

Regards,
Pratik Shah
Tom Kyte
March 11, 2013 - 8:16 am UTC

the ASH repository can give you some glimpse into that, but we do not store anywhere the entire history - not even close, not even a tiny bit close. that would be *huge*

use ASH to see what that statement was mostly waiting on. It'll give you a good picture.

A reader, September 16, 2022 - 4:35 am UTC


more

Connor and Chris don't just spend all day on AskTOM. You can also catch regular content via Connor's blog and Chris's blog. Or if video is more your thing, check out Connor's channel and Chris's channel from their Youtube channels. And of course, keep up to date with AskTOM via the official twitter account.

More to Explore

Performance

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