Re: Heterogenous Service much slower in Oracle 9 than in Oracle 8

Ray Saltrelli wrote:
> Here are some excerpts from the traces of similar queries made in both
> 8.1 and 9.2. Note the timestamps of each FETCH. Each FETCH takes
> noticeably longer in the 9.2 trace than in the 8.1 trace. We have also
> tried killing our external data source immediately after issuing the
> query. Oracle 9.2 continues printing the result for a few minutes
> before it realizes that the data source is gone. This says to me that
> the external data is retrieved rather quickly but either Oracle itself
> or the hsolesql agent is processing at a much slower rate. What do you
> guys think?
>
> Oracle 8.1:
> PARSING IN CURSOR #1 len=81 dep=0 uid=21 oct=3 lid=21 tim=329450221
> hv=1548259522 ad='3959c64'
> select datavalue, timestamp from numericlog where logname =
> 'SIN-000000:MEASURE'
> END OF STMT
> PARSE #1:c=0,e=32,p=0,cr=151,cu=8,mis=0,r=0,dep=0,og=4,tim=329450221
> EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=329450223
> FETCH #1:c=0,e=114,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=329450337
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450337
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450337
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450340
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450343
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450343
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450343
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450345
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450345
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450346
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450348
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450348
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450348
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450348
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450351
> FETCH #1:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450378
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450378
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450379
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450381
> FETCH #1:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=329450414
>
> Oracle 9.2:
> PARSING IN CURSOR #1 len=83 dep=0 uid=25 oct=3 lid=25 tim=5723763408
> hv=332440534 ad='7a761818'
> select datavalue,timestamp from numericlog where logname =
> 'BrewKettle1:AmountHops'
> END OF STMT
> PARSE
> #1:c=125000,e=1995480,p=0,cr=186,cu=1,mis=1,r=0,dep=0,og=4,tim=5723763402
> EXEC #1:c=0,e=745630,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=5724509151
> *** 2006-08-18 10:35:51.944
> FETCH
> #1:c=0,e=15340838,p=0,cr=0,cu=0,mis=0,r=16,dep=0,og=4,tim=5739850977
> FETCH #1:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739884166
> FETCH #1:c=0,e=139,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739912404
> FETCH #1:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739940546
> FETCH #1:c=0,e=150,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739946464
> FETCH #1:c=0,e=89,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739957140
> FETCH #1:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739962330
> FETCH #1:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739966427
> FETCH #1:c=0,e=86,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739971045
> FETCH #1:c=0,e=90,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739976880
> FETCH #1:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739981946
> FETCH #1:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739986043
> FETCH #1:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739991143
> FETCH #1:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5739996514
> FETCH #1:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740034067
> FETCH #1:c=0,e=88,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740039386
> FETCH #1:c=0,e=84,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740043947
> FETCH #1:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740048719
> FETCH #1:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740052944
> FETCH #1:c=0,e=74,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740057122
> FETCH #1:c=0,e=83,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740062735
> FETCH #1:c=0,e=95,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=4,tim=5740067207

Unfortunately, you'll need a 10046 trace level 12 so that one can see the wait events. The FETCH is longer, but where is it spending it's time waiting? My guess is that it would be related to either some sort of 'db file sequential|scattered read' event or sending data to/from the client. If it is the latter, then it is a communication issue. If it is the former, then it is a tuning issue and you'll want to look at the EXPLAIN PLAN differences in your two versions. My guess is that both versions do not give the same explain plan. But these are just guesses without any specific evidence to go on....

Cheers,
Brian

-- 
===================================================================

Brian Peasland
dba_at_nospam.peasland.net
http://www.peasland.net

Remove the "nospam." from the email address to email me.


"I can give it to you cheap, quick, and good.
Now pick two out of the three" - Unknown