Very slow fetches with high cputime
- From: ronpet@xxxxxxxxx
- To: oracle-l@xxxxxxxxxxxxx
- Date: Mon, 16 Feb 2009 16:10:31 +0100
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
...
-----------------------------------------------------------
--
//www.freelists.org/webpage/oracle-l
Other related posts:
