Skip to Main Content
  • Questions
  • Update query is very slow for first time

Breadcrumb

Question and Answer

Tom Kyte

Thanks for the question, R.

Asked: May 04, 2004 - 9:27 pm UTC

Last updated: May 05, 2004 - 3:03 pm UTC

Version: 9.2.0.4

Viewed 1000+ times

You Asked

have a query which is always taking very long time when I executed first time (when the data is not available in the db buffer and when it needs to go for disk reads). The same query is returning the results very fast on subsequent executions. Here is the info.

Stats from 1st iteration:

call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 1 0.20 0.19 0 0 0 0

Execute 1 0.00 0.00 0 0 0 0

Fetch 4 8.15 220.84 19846 100074 0 40

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 6 8.35 221.04 19846 100074 0 40



Stats from subsequent iterations:



call count cpu elapsed disk query current rows

------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse 1 0.13 0.12 0 0 0 0

Execute 1 0.01 0.00 0 0 0 0

Fetch 4 4.39 4.43 65 100074 0 40

------- ------ -------- ---------- ---------- ---------- ---------- ----------

total 6 4.53 4.56 65 100074 0 40


I surprised to see 216 seconds for 19k disk reads. Can you through some light on my problem? Where should I look into to get the I/O information and other details? Please let me know if you need more information to comment on this?

Thanks in advance.






and Tom said...

that is almost 100 physical IO's per second -- depending on your disk system, that might be "pretty good" (typical off the shelf stuff).

Most likely they are random scattered IO's (eg: you are using an index perhaps -- no idea since you've not shared the query plan, nor the query with me) -- the worst kind.

Beyond that, not much I can say -- not much here to comment on (no real detail)



Rating

  (1 rating)

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

Comments

Thanks for your comments

A reader, May 05, 2004 - 1:19 pm UTC

Sorry for not sending detailed information. Here is the actual query and query plan along with stats from tkprof. Please let me know if you need any other information.

Query is :

SELECT *
FROM (SELECT x.*, rank()
OVER (ORDER BY create_date DESC, ROWNUM) AS rnk,
max(ROWNUM)
OVER (ORDER BY create_date DESC
ROWS BETWEEN UNBOUNDED PRECEDING
AND UNBOUNDED FOLLOWING) AS max_rownum
FROM (SELECT tr.track_id,
tr.create_date create_date,
tr.ndata,
trtype.track_type_id ,
trtype.custom_name,
trtype.description,
trtype.name,
person.first_name,
person.last_name,
person.middle_name,
person.person_id,
sys_con.p_object_id,
sys_con.p_class_id,
sys_con.title
FROM (SELECT team_obj.object_id
FROM member, team_obj
WHERE member.team_id =
team_obj.team_id
AND member.user_id = 5000482
AND member.current_record = 1
AND team_obj.class_id =
100) access_sql, sys_con,
track tr, track_type trtype,
accounts u, person
WHERE access_sql.object_id =
sys_con.parent_object_id
AND sys_con.p_class_id = 100
AND sys_con.class_id = 103
AND tr.track_type_id =
trtype.track_type_id
AND person.person_id = u.person_id
AND u.user_id = tr.enacting_user_id
AND track_id = sys_con.object_id
AND tr.create_date >= to_date('01/14/2004 06:00:00',
'MM/DD/YYYY HH24:MI:SS')
AND tr.create_date < to_date('04/22/2004 05:00:00',
'MM/DD/YYYY HH24:MI:SS')) x)
WHERE rnk BETWEEN 1 AND 40

#### First Execution (with lot of disk reads) #########

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.20 0.19 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 4 8.15 220.84 19846 100074 0 40
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 8.35 221.04 19846 100074 0 40

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
40 VIEW (cr=100074 r=19846 w=0 time=220847577 us)
8328 WINDOW SORT (cr=100074 r=19846 w=0 time=220821167 us)
8328 COUNT (cr=100074 r=19846 w=0 time=220230482 us)
8328 HASH JOIN (cr=100074 r=19846 w=0 time=220218437 us)
8328 HASH JOIN (cr=100011 r=19784 w=0 time=219845714 us)
8328 HASH JOIN (cr=99948 r=19722 w=0 time=219374414 us)
8328 NESTED LOOPS (cr=99914 r=19690 w=0 time=218997807 us)
36264 NESTED LOOPS (cr=27396 r=10985 w=0 time=123362241 us)
571 HASH JOIN (cr=649 r=647 w=0 time=3300976 us)
572 TABLE ACCESS BY INDEX ROWID MEMBER (cr=396 r=396 w=0 time=2327122 us)
572 INDEX RANGE SCAN MEMBER_USER_ID_X (cr=3 r=3 w=0 time=48706 us)(object id 47080)
73495 TABLE ACCESS FULL TEAM_OBJECT (cr=253 r=251 w=0 time=789521 us)
36264 TABLE ACCESS BY INDEX ROWID SYS_CON (cr=26747 r=10338 w=0 time=119976607 us)
36264 INDEX RANGE SCAN SYSC____UNIQUE_X (cr=1253 r=501 w=0 time=6300281 us)(object id 47012)
8328 TABLE ACCESS BY INDEX ROWID TRACK (cr=72518 r=8705 w=0 time=95266573 us)
36252 INDEX UNIQUE SCAN TRACK_PK (cr=36266 r=990 w=0 time=4932292 us)(object id 47100)
209 TABLE ACCESS FULL TRACK_TYPE (cr=34 r=32 w=0 time=128424 us)
3911 TABLE ACCESS FULL ACCOUNTS (cr=63 r=62 w=0 time=248368 us)
2966 TABLE ACCESS FULL PERSON (cr=63 r=62 w=0 time=148845 us)

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

#########Second execution (minimul disk reads)################

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.13 0.12 0 0 0 0
Execute 1 0.01 0.00 0 0 0 0
Fetch 4 4.39 4.43 65 100074 0 40
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 4.53 4.56 65 100074 0 40

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 64

Rows Row Source Operation
------- ---------------------------------------------------
40 VIEW (cr=100074 r=65 w=0 time=4432858 us)
8328 WINDOW SORT (cr=100074 r=65 w=0 time=4397879 us)
8328 COUNT (cr=100074 r=65 w=0 time=3808207 us)
8328 HASH JOIN (cr=100074 r=65 w=0 time=3792008 us)
8328 HASH JOIN (cr=100011 r=12 w=0 time=3481629 us)
8328 HASH JOIN (cr=99948 r=0 w=0 time=3231675 us)
8328 NESTED LOOPS (cr=99914 r=0 w=0 time=3010420 us)
36264 NESTED LOOPS (cr=27396 r=0 w=0 time=1313841 us)
571 HASH JOIN (cr=649 r=0 w=0 time=380509 us)
572 TABLE ACCESS BY INDEX ROWID MEMBER (cr=396 r=0 w=0 time=10081 us)
572 INDEX RANGE SCAN MEMBER_USER_ID_X (cr=3 r=0 w=0 time=1426 us)(object id 47080)
73495 TABLE ACCESS FULL TEAM_OBJECT (cr=253 r=0 w=0 time=190094 us)
36264 TABLE ACCESS BY INDEX ROWID SYS_CON (cr=26747 r=0 w=0 time=864936 us)
36264 INDEX RANGE SCAN SYSC____UNIQUE_X (cr=1253 r=0 w=0 time=230021 us)(object id 47012)
8328 TABLE ACCESS BY INDEX ROWID TRACK (cr=72518 r=0 w=0 time=1374262 us)
36252 INDEX UNIQUE SCAN TRACK_PK (cr=36266 r=0 w=0 time=724303 us)(object id 47100)
209 TABLE ACCESS FULL TRACK_TYPE (cr=34 r=0 w=0 time=1158 us)
3911 TABLE ACCESS FULL ACCOUNTS (cr=63 r=12 w=0 time=36879 us)
2966 TABLE ACCESS FULL PERSON (cr=63 r=53 w=0 time=107842 us)

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


My storage is a EMC box. I dont know internal details. How to find out the max disk reads it can support?



Tom Kyte
May 05, 2004 - 3:03 pm UTC

I'd ask my EMC representative if 100 random IO's/sec is "ok" or not. Much of your IO is random IO from an index:


8328 NESTED LOOPS (cr=99914 r=19690 w=0 time=218997807 us)
36264 NESTED LOOPS (cr=27396 r=10985 w=0 time=123362241 us)
571 HASH JOIN (cr=649 r=647 w=0 time=3300976 us)
572 TABLE ACCESS BY INDEX ROWID MEMBER (cr=396 r=396 w=0
572 INDEX RANGE SCAN MEMBER_USER_ID_X (cr=3 r=3 w=0 time=48706
73495 TABLE ACCESS FULL TEAM_OBJECT (cr=253 r=251 w=0 time=789521
36264 TABLE ACCESS BY INDEX ROWID SYS_CON (cr=26747 r=10338 w=0
36264 INDEX RANGE SCAN SYSC____UNIQUE_X (cr=1253 r=501 w=0
8328 TABLE ACCESS BY INDEX ROWID TRACK (cr=72518 r=8705 w=0
36252 INDEX UNIQUE SCAN TRACK_PK (cr=36266 r=990 w=0 time=4932292

in the nested loops.