Very slow fetches with high cputime
From: <ronpet_at_zonnet.nl>
Date: Mon, 16 Feb 2009 16:10:31 +0100
Message-ID: <20090216161031.49ym7mwess084gc0_at_webmail.versatel.nl>
Dear list,
------- ------ -------- ---------- ---------- ---------- ----------
total 604 170203.78 167091.28 44687 2765869668 0
Date: Mon, 16 Feb 2009 16:10:31 +0100
Message-ID: <20090216161031.49ym7mwess084gc0_at_webmail.versatel.nl>
Dear list,
I'm trying to fix a performance issue on a query that runs 48 hours,
where it normally runs for 5 minutes.
During last slow-run, I activated a 10046 traceevent, to find out where
time is spend on.
Query stats (tkprof) are:
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0
0
Execute 0 0.00 0.00 0 0 0
0
Fetch 604 170203.78 167091.28 44687 2765869668 0
661012
------- ------ -------- ---------- ---------- ---------- ----------
total 604 170203.78 167091.28 44687 2765869668 0
661012
Misses in library cache during parse: 0
Parsing user id: 71
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net more data to client 5448 0.00 0.51 db file sequential read 12574 0.14 36.56 db file scattered read 424 0.05 4.81 SQL*Net message from client 605 0.02 4.74 SQL*Net message to client 604 0.00 0.00 latch: cache buffers chains 992 0.45 241.80 read by other session 25 0.01 0.06 latch free 54 0.30 14.29 ********************************************************************************
Since an average fetch takes about 5 minutes, I browsed through the trace-file. I noticed that:
* a FETCH cputime (c=) itself is about 5 minutes * a FETCH elapsetime (e=) is often smaller the FETCH cpu-time * the total of WAIT's is only about 2 seconds
Does anyone have anyone have idea what's making the fetch so slow and why FETCH elapsetime is smaller than FETCH cpu-time. My main concern is to find out how I can solve this performance issue.
I included a part of the 10046 tracefile (between 2 fetches) below.
Thnx for any feedback,
Ronald Peters
- 2009-02-15 07:30:13.118 FETCH #4:c=779570000,e=761559505,p=145,cr=12835365,cu=0,mis=0,r=1096,dep=0,og=1,tim=26023307089030 WAIT #4: nam='SQL*Net message from client' ela= 8564 driver id=1413697536 #bytes=1 p3=0 obj#=4603 tim=26023307097782 WAIT #4: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=4603 tim=26023307127822
- 2009-02-15 07:31:11.791 WAIT #4: nam='db file sequential read' ela= 403 file#=25 block#=185099 blocks=1 obj#=4603 tim=26023364387816 WAIT #4: nam='db file sequential read' ela= 431 file#=24 block#=210004 blocks=1 obj#=4603 tim=26023365764647
- 2009-02-15 07:31:49.781 WAIT #4: nam='SQL*Net more data to client' ela= 87 driver id=1413697536 #bytes=8714 p3=0 obj#=4603 tim=26023401487444
- 2009-02-15 07:32:17.119 WAIT #4: nam='db file sequential read' ela= 477 file#=25 block#=185100 blocks=1 obj#=4603 tim=26023428185451 WAIT #4: nam='db file sequential read' ela= 5379 file#=25 block#=185561 blocks=1 obj#=4603 tim=26023432401181
- 2009-02-15 07:33:04.941 WAIT #4: nam='SQL*Net more data to client' ela= 96 driver id=1413697536 #bytes=8720 p3=0 obj#=4603 tim=26023474886312
- 2009-02-15 07:34:03.849 WAIT #4: nam='db file sequential read' ela= 452 file#=25 block#=185101 blocks=1 obj#=4603 tim=26023532414156
- 2009-02-15 07:34:27.762 WAIT #4: nam='SQL*Net more data to client' ela= 100 driver id=1413697536 #bytes=8709 p3=0 obj#=4603 tim=26023555766901
- 2009-02-15 07:35:08.351 WAIT #4: nam='db file sequential read' ela= 446 file#=25 block#=185102 blocks=1 obj#=4603 tim=26023595404265
- 2009-02-15 07:35:21.656 WAIT #4: nam='SQL*Net more data to client' ela= 100 driver id=1413697536 #bytes=8714 p3=0 obj#=4603 tim=26023608397703
- 2009-02-15 07:35:35.829 WAIT #4: nam='db file sequential read' ela= 373 file#=25 block#=185103 blocks=1 obj#=4603 tim=26023622238292
- 2009-02-15 07:35:47.691 WAIT #4: nam='SQL*Net more data to client' ela= 103 driver id=1413697536 #bytes=8713 p3=0 obj#=4603 tim=26023633822568
- 2009-02-15 07:36:02.325 WAIT #4: nam='db file sequential read' ela= 460 file#=25 block#=185104 blocks=1 obj#=4603 tim=26023648113351
- 2009-02-15 07:36:35.331 WAIT #4: nam='SQL*Net more data to client' ela= 102 driver id=1413697536 #bytes=8714 p3=0 obj#=4603 tim=26023680347056
- 2009-02-15 07:36:54.892 WAIT #4: nam='db file sequential read' ela= 833 file#=25 block#=185105 blocks=1 obj#=4603 tim=26023699449899
- 2009-02-15 07:37:24.211 WAIT #4: nam='SQL*Net more data to client' ela= 92 driver id=1413697536 #bytes=8716 p3=0 obj#=4603 tim=26023728081929
- 2009-02-15 07:37:54.758 WAIT #4: nam='db file sequential read' ela= 415 file#=25 block#=185106 blocks=1 obj#=4603 tim=26023757912148
- 2009-02-15 07:44:16.786 WAIT #4: nam='db file sequential read' ela= 8435 file#=23 block#=213328 blocks=1 obj#=4603 tim=26024130989289 WAIT #4: nam='db file sequential read' ela= 8359 file#=25 block#=185406 blocks=1 obj#=4603 tim=26024131063149
- 2009-02-15 07:49:27.199 WAIT #4: nam='db file sequential read' ela= 2519 file#=23 block#=213330 blocks=1 obj#=4603 tim=26024434129585 WAIT #4: nam='db file sequential read' ela= 10767 file#=25 block#=185162 blocks=1 obj#=4603 tim=26024442552207 WAIT #4: nam='SQL*Net more data to client' ela= 97 driver id=1413697536 #bytes=8712 p3=0 obj#=4603 tim=26024443296687 WAIT #4: nam='db file sequential read' ela= 6924 file#=27 block#=134031 blocks=1 obj#=4603 tim=26024443788258
- 2009-02-15 07:49:41.157 WAIT #4: nam='db file sequential read' ela= 7179 file#=26 block#=165302 blocks=1 obj#=4603 tim=26024447759981 WAIT #4: nam='db file sequential read' ela= 5310 file#=25 block#=185259 blocks=1 obj#=4603 tim=26024447944080 WAIT #4: nam='db file sequential read' ela= 7539 file#=26 block#=165129 blocks=1 obj#=4603 tim=26024448366144 WAIT #4: nam='db file sequential read' ela= 6410 file#=27 block#=134299 blocks=1 obj#=4603 tim=26024448397926 WAIT #4: nam='db file sequential read' ela= 8976 file#=25 block#=185555 blocks=1 obj#=4603 tim=26024448577466 WAIT #4: nam='db file sequential read' ela= 457 file#=27 block#=133912 blocks=1 obj#=4603 tim=26024448788306 WAIT #4: nam='db file sequential read' ela= 3449 file#=27 block#=134221 blocks=1 obj#=4603 tim=26024448805222 WAIT #4: nam='db file sequential read' ela= 4854 file#=25 block#=185460 blocks=1 obj#=4603 tim=26024448980110 WAIT #4: nam='db file sequential read' ela= 6900 file#=23 block#=213695 blocks=1 obj#=4603 tim=26024449133433 WAIT #4: nam='db file sequential read' ela= 5651 file#=27 block#=134116 blocks=1 obj#=4603 tim=26024454626052
- 2009-02-15 07:49:51.436 WAIT #4: nam='db file sequential read' ela= 5857 file#=26 block#=165242 blocks=1 obj#=4603 tim=26024457798604 WAIT #4: nam='db file sequential read' ela= 7028 file#=23 block#=213540 blocks=1 obj#=4603 tim=26024458531304 WAIT #4: nam='db file sequential read' ela= 8395 file#=26 block#=165191 blocks=1 obj#=4603 tim=26024462223834 WAIT #4: nam='db file sequential read' ela= 4750 file#=27 block#=134263 blocks=1 obj#=4603 tim=26024467241086 WAIT #4: nam='SQL*Net more data to client' ela= 64 driver id=1413697536 #bytes=8715 p3=0 obj#=4603 tim=26024467241334
- 2009-02-15 07:50:01.748 WAIT #4: nam='db file sequential read' ela= 15506 file#=27 block#=134177 blocks=1 obj#=4603 tim=26024467868191 WAIT #4: nam='db file sequential read' ela= 9143 file#=26 block#=165293 blocks=1 obj#=4603 tim=26024468069792 WAIT #4: nam='db file sequential read' ela= 6631 file#=27 block#=134005 blocks=1 obj#=4603 tim=26024470727348
- 2009-02-15 07:50:13.480 WAIT #4: nam='db file sequential read' ela= 5018 file#=23 block#=213573 blocks=1 obj#=4603 tim=26024479325131 WAIT #4: nam='db file sequential read' ela= 472 file#=23 block#=213331 blocks=1 obj#=4603 tim=26024486309958
- 2009-02-15 07:50:24.432
WAIT #4: nam='db file sequential read' ela= 7697 file#=25 block#=185352
blocks=1 obj#=4603 tim=26024490020807
FETCH
#4:c=1216790000,e=1189423570,p=35,cr=20074148,cu=0,mis=0,r=1096,dep=0,og=1,tim=26024496521407
...
-- http://www.freelists.org/webpage/oracle-lReceived on Mon Feb 16 2009 - 09:10:31 CST