Exit
  • Global community
    • Language:
      • Deutsch
      • English
      • Español
      • Français
      • Português
  • 日本語コミュニティ
  • 한국 커뮤니티
0

Oracle proc call from CF has 4sec overhead

LEGEND ,
Apr 15, 2008 Apr 15, 2008
G'day
I've been troubleshooting a slow-running Oracle (9i) proecdure call, which
was coming in at 4sec. When run via a Oracle SQL Developer window, it runs
in 0ms, which is more like what I'd expect form the amount of work it's
doing.

I applied FusionReactor to the situation, and it's reporting that the proc
is indeed *running* in 0ms, but the added overhead of CF calling it is
4sec. From the "Longest JDBC" screen, the figures were:

Total Time(ms): 3845
DB Time(ms): 0

What on earth is CF doing?

Notes:
- it's returning zero rows, so it's not a data-transmission overhead.
- the DB is running on the same box as CF.
- it's not a one-off. Running the proc with different input data (which
would yield any number of rows returned from 0 to 30000-odd) seems to make
little difference. The DB side of things runs between 0-100ms, and then
there's close to a 4sec overhead added by CF.

The stored proc is running a couple of select queries (a value from the
first contributing to the second), and returning a single resultant record
set. Nothing complicated.

Any ideas?

--
Adam
TOPICS
Database access
612
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Apr 15, 2008 Apr 15, 2008
Sorry, some software / versions:

Test 1 - my dev laptop:
CF: 8, multi-server, Windows XP Pro
Oracle: Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production (same
machine)
JDBC: macromedia.jdbc.oracle.OracleDriver v3.50

Test 2 - QA server:
CF: 7.0.2, multi-server, Windows 2k3 Server
Oracle: Oracle9i Enterprise Edition Release 9.2.0.1.0 - Production (same
machine)
JDBC: macromedia.jdbc.oracle.OracleDriver v3.50

Test 3 - production:
CF: 7.0.2, multi-server, Windows 2k3 Server
Oracle: Oracle9i Release 9.2.0.8.0 - 64bit Production (that's on a separate
Solaris box, not sure of version)
JDBC: macromedia.jdbc.oracle.OracleDriver v3.50


All are experiencing similar results.


--
Adam
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Mentor ,
Apr 15, 2008 Apr 15, 2008
Is the problem with a single SP, or set of SPs, or all of your proc calls? If it is just one, you might provide your PL/SQL and ColdFusion cfstoredproc/cfprocparam/cfprocresult tags so that we may have a chance of spotting something.

Phil
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Apr 15, 2008 Apr 15, 2008
> Is the problem with a single SP, or set of SPs, or all of your proc calls? If

It was happening on more than just that one, but it's the one that's called
the most frequently, so sticks out more. I'm offsite @ present so can't
check more thoroughly if it's that package, or all, some, or what. I'll
check tomorrow.


> it is just one, you might provide your PL/SQL and ColdFusion
> cfstoredproc/cfprocparam/cfprocresult tags so that we may have a chance of
> spotting something.

Yeah, I thought about that: it's usually the first thing I say when
someone's asking for help too "it's a bit bloody hard to tell what's going
on... etc".

If it was just a "why's my query / proc runnning slow on CF: it runs fine
when I run it in query analyser" I'd agree that seeing that stuff would
make sense. However monitoring the JDBC connection I can *see* that the
proc is running fine: the DB server is reporting to the JDBC driver that
it's taking 0ms to run. It's just the comms from the driver to CF (or
vice-versa) that's killing the time.

I dunno if this code will help you @ all, without seeing really a lot of
the rest of the underlying code, but... 'ere 'tis.

{code}
<cfstoredproc procedure="pkg_tree.proc_getAncestors" datasource="#sDsn#"
result="stResult">
<cfprocparam type="in" cfsqltype="CF_SQL_VARCHAR" value="#uNode#">
<!--- uNode in varchar2 --->
<cfprocparam type="in" cfsqltype="CF_SQL_VARCHAR" value="#bDetail#"> <!---
sDetail in varchar2 --->
<cfprocparam type="in" cfsqltype="CF_SQL_VARCHAR" value="#sFilter#">
<!--- sFilter in varchar2 --->
<cfprocparam type="in" cfsqltype="CF_SQL_VARCHAR" value="#sSort#"> <!---
sTypeSort in varchar2 --->
<cfprocparam type="in" cfsqltype="CF_SQL_VARCHAR" value="#bSelf#"><!---
sSelf in varchar2 --->
<cfprocresult name="qReturn"> <!--- qAncestors out
cResultSet --->
</cfstoredproc>
{code}

{code}
procedure proc_getAncestors(uNode in varchar2, sDetail in varchar2, sFilter
in varchar2, sTypeSort in varchar2, sSelf in varchar2, qAncestors out
cResultSet) is
type tNode is record(obt_left int, obt_right int);
rSelf tNode;

sSql varchar2(600);
sWhere varchar2(100);
sSortExpression varchar(200);
sTail varchar2(100);

sErrMsg varchar2(1024);
begin

case sSelf
when 'TRUE' then
sWhere := ' where obt_left <= :iLeft and obt_right >= :iRight';
when 'FALSE' then
sWhere := ' where obt_left < :iLeft and obt_right > :iRight';
else
raise_application_error(-20021, 'Invalid sSelf parameter value passed to
proc_getAncestors');
end case;

case sTypeSort
when 'NONE' then
sSortExpression := ' order by obt_left';
when 'SECTION' then
sSortExpression := ' order by decode(obt_type, ''SECTION'',1,
''PAGE'',2, ''FILE'',3, ''LINK'',4), obt_left';
when 'PAGE' then
sSortExpression := ' order by decode(obt_type, ''PAGE'',1,
''SECTION'',2, ''FILE'',3, ''LINK'',4), obt_left';
when 'FILE' then
sSortExpression := ' order by decode(obt_type, ''FILE'',1,
''SECTION'',2, ''PAGE'',3, ''LINK'',4), obt_left';
when 'LINK' then
sSortExpression := ' order by decode(obt_type,
''LINK'',1,''SECTION'',2, ''PAGE'',3,''FILE'',4), obt_left';
else
raise_application_error(-20022, 'Invalid sTypeSort parameter value
passed to proc_getAncestors');
end case;

if sFilter = 'ALL' then
sTail := sSortExpression;
else
sTail := ' and (1=0 ';
if instr(sFilter, 'SECTION') > 0 then
sTail := sTail || ' or obt_type = ''SECTION''';
end if;
if instr(sFilter, 'PAGE') > 0 then
sTail := sTail || ' or obt_type = ''PAGE''';
end if;
if instr(sFilter, 'FILE') > 0 then
sTail := sTail || ' or obt_type = ''FILE''';
end if;
if instr(sFilter, 'LINK') > 0 then
sTail := sTail || ' or obt_type = ''LINK''';
end if;

sTail := sTail || ') ' || sSortExpression;
end if; /* designed to fail if it's not one of ALL, SECTION, PAGE, FILE,
LINK */

case sDetail
when 'TRUE' then
/* get this node */
select obt_left, obt_right
into rSelf
from VW_OBJTREE
where obt_uuid = uNode;

/* get ancestors */
sSQl := 'select * from VW_OBJTREE' || sWhere || sTail;
open qAncestors for sSql using rSelf.obt_left, rSelf.obt_right;

when 'FALSE' then
/* get this node */
select obt_left, obt_right
into rSelf
from tbl_objtree
where obt_uuid = uNode;

sSQl := 'select * from tbl_objtree' || sWhere || sTail;
open qAncestors for sSql using rSelf.obt_left, rSelf.obt_right;
else
raise_application_error(-20023, 'Invalid sDetail parameter value passed
to proc_getAncestors');
end case;

exception
when no_data_found then /* this happens for some reason, sometimes. Yet
to work out where/why */
null;
when others then
sErrMsg := SQLERRM;
raise_application_error(-20024, 'Unexpected error: ' || sErrMsg);

end;

{code}

Cheers Phil.

--
Adam
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Mentor ,
Apr 16, 2008 Apr 16, 2008
Wow, I see nothing in your code that jumps out at me as a problem. And you are using the 3.5 drivers.... weird!

Phil
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
LEGEND ,
Apr 16, 2008 Apr 16, 2008
> Wow, I see nothing in your code that jumps out at me as a problem.

God. I at least expected you to run - screaming - from the room at the
sight of my code!


More on this.

Standard queries are doing this too, sometimes. For example we had a query
that was basically:

select obt_id, obt_left, obt_right
from tbl_objtree
where obt_left <= <cfqueryparam value="#iLeft#"
cf_sql_type="cf_sql_integer">
and obt_right >= <cfqueryparam value="#iRight#"
cf_sql_type="cf_sql_integer">

(ie: get ancestors and self from a nested-set tree)

Which was taking 0ms on the DB to fetch zero records, yet took CF 16sec
(sic) to catch up and do something about it.

One idea I had was whether perhaps CF has a "fire and forget" approach to
connections to the JDBC driver, like this:

- make a connection
- pass SQL statement
- close connection
- (time passes whilst DB does its stuff, in the mean time another SQL call
can use the connection)
- DB driver says "oi, CF, have this..."

And CF in the mean time hasn't got a connection available to use to
reconnect to the driver (this site has some DB usage problems, which is why
I'm looking at this sort of thing).

So perhaps the 16sec is the length of time the JDBC driver has to wait
until CF gets around to listening to the answer. This is all supposition
on my part. I've not been able to find out anything in the FusionReactor
docs to describe what that value might actually represent.

This seems more likely given these big time blowouts are more likely to
happen when the server is struggling under load (although, equally, they
could be the CAUSE of the load, not a symptom of it).

It's all a bit curious.

--
Adam
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Mentor ,
Apr 16, 2008 Apr 16, 2008
LATEST
Interesting, sure is starting to sound more driver-ish to me. Are your DSNs configured to maintain connections? Mine are not, and my queries and SPs are running just fine. (CF 7.0.2 and Oracle 10gR2) Could it be a threading issue? I do remember my application having a simple SP with small results taking forever to return because another SP on the same DSN was returning a large result set from another session.

Phil
Translate
Report
Community guidelines
Be kind and respectful, give credit to the original source of content, and search for duplicates before posting. Learn more
community guidelines
Resources