Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> PL/SQL Wrapper Costs

PL/SQL Wrapper Costs

From: Peter Sylvester <peters_at_mitre.org>
Date: Wed, 13 Jun 2007 19:38:19 -0400
Message-ID: <46707FEB.1030100@mitre.org>


I was asked to look at performance on someone else's system, running Oracle 10.1.0.4 under HPUX. Its actually a 2 node RAC cluster, but I don't think thats all that important here.

This is an older commercial application, written using the (older) UNIFACE client-server framework, which appears to use a lot of PL/SQL procedures that essentially run a singleton select ... into statement, specifying the PK in the where clause. All input/output is done through individual bind variables. No dynamic SQL. There is not much logic within the procedures. User response time has been an issue. We ran 10046 traces files of known problem scenarios and formatted using tkprof as well as trace analyzer.

One thing that I noticed is that the elapsed time for the procedure call is 4-5X the elapsed time of the underlying query, which does not seem right to me. Is this expected for the overhead in calling a PL/SQL procedure and marshalling arguments in and out? Not much else is happening in the procedures.

Also, I'm just curious, does anyone really write applications this way anymore?
It seems pretty inefficient to run a call for every record you need. Lots of round trips on the network etc, especially for client server.

I did not see any other obvious issues in the trace file, other than LOTS of procedure calls.
Any clues would be appreciated.

Oh, and these procedures typically get called many 1000s of times an hour. The trace file represents about 10 minutes of activity on a particular transaction in one session.

Here are some clips from the trace file:

*The procedure call:*

BEGIN "IDNT$U"."UNIFACE_IO"( :UNIFACE_IO_REQUEST, :XIDNT_ID, :XU_VERSION,
:XIDNT_XREF_ID, :XFOLDER_NBR, :XDETAINEE_ID, :XRECIDIVIST, :XPRFX_CD,
:XSFFX_CD, :XFIRST_NAME, :XMIDDLE_NAME, :XLAST_NAME, :XCOMPANY_NAME,
:XSSN,
:XDOB, :XDOD, :XBIRTH_CNTY_CD, :XBIRTH_CITY_CD, :XBIRTH_ST_CD, :XSECRET,
:XINS_BY, :XINS_PRG, :XINS_DTTM, :XUPD_BY, :XUPD_PRG, :XUPD_DTTM,
:XCITY_TEXT, :XCOUNTY_TEXT, :XDRIVERS_LIC_NO, :XSID, :XBCI, :XFBI,
:XFULL_NAME_SOUNDEX, :XROWID, :WIDNT_ID, :WU_VERSION,
:ONE_ROW_AFFECTED );
  END;

call     count       cpu    elapsed       disk      query    
current        rows

------- ------ -------- ---------- ---------- ---------- ----------
Parse        3      0.00       0.00          0          0          
0           0
Execute   1419      4.61       7.39         80       5676          
0        1419
Fetch        0      0.00       0.00          0          0          
0           0

------- ------ -------- ---------- ---------- ---------- ----------
total     1422      4.61       7.39         80       5676          
0        1419

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 448

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total 
Waited

*The select statement:*

SELECT /*+ FIRST_ROWS */ "IDNT_ID", "U_VERSION", "IDNT_XREF_ID", "FOLDER_NBR",
   "DETAINEE_ID", "RECIDIVIST", "PRFX_CD", "SFFX_CD", "FIRST_NAME",

  "MIDDLE_NAME", "LAST_NAME", "COMPANY_NAME", "SSN", "DOB", "DOD",
  "BIRTH_CNTY_CD", "BIRTH_CITY_CD", "BIRTH_ST_CD", "SECRET", "INS_BY",
  "INS_PRG", "INS_DTTM", "UPD_BY", "UPD_PRG", "UPD_DTTM", "CITY_TEXT",
  "COUNTY_TEXT", "DRIVERS_LIC_NO", "SID", "BCI", "FBI", "FULL_NAME_SOUNDEX"
FROM
 "IDNT" WHERE "IDNT_ID" = :B1
call     count       cpu    elapsed       disk      query    
current        rows

------- ------ -------- ---------- ---------- ---------- ----------
Parse        8      0.00       0.00          0          0          
0           0
Execute   1419      0.39       0.46          0          0          
0           0
Fetch     1419      0.13       0.76         80       5676          
0        1419

------- ------ -------- ---------- ---------- ---------- ----------
total     2846      0.52       1.23         80       5676          
0        1419

Misses in library cache during parse: 0
Optimizer mode: FIRST_ROWS
Parsing user id: 987 (recursive depth: 1)

Rows Row Source Operation

-------  ---------------------------------------------------
     99  TABLE ACCESS BY INDEX ROWID IDNT (cr=396 pr=63 pw=0 time=457354 us)
     99   INDEX UNIQUE SCAN IDNTP1 (cr=297 pr=29 pw=0 time=200551 
us)(object id 285949)

Elapsed times include waiting on following events:

  Event waited on                             Times   Max. Wait  Total 
Waited

thanks for any suggestions,
Peter Sylvester
MITRE Corp.

--
http://www.freelists.org/webpage/oracle-l
Received on Wed Jun 13 2007 - 18:38:19 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US