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

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

Mark D Powell wrote:
> EdStevens wrote:
> > Ray Saltrelli wrote:
> > > My database allows users to query data external to Oracle using
> > > Heterogeneous Services' OLE interface. I had a query that did 4 joins
> > > on this external data that would complete in roughly 10 of 15 minutes
> > > in Oracle 8.1.7.4. Now that I am using Oracle 9.2.0.6, the same query
> > > on the same data takes almost 2 hours! I have been able to determine
> > > that the bottle neck is in Oracle but I do not know where or how. Does
> > > anyone know why this is happening and if there is anything I can do
> > > about it? Thanks.
> >
> > Sounds like a perfect candidate to capture a 10046 trace and see where
> > it is spending its time.
>
> I agree with Ed, as this may just be a tuning opportunity rather than a
> version specific feature condition.
>
> IMHO -- Mark D Powell --
Received on Fri Aug 18 2006 - 10:00:29 CDT