Re: PL/SQL Wrapper Costs

Peter,

Have you stripped out other recursive queries (sys=no)? If yes could you put them back and could you please also supply tkprof summary for recursive and non-recursive cursors.

Regards,

Vlad Sadilovskiy
Oracle Database Tools
http://www.fourthelephant.com

On 6/13/07, Peter Sylvester <peters_at_mitre.org> wrote:
>
> 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
> ---------------------------------------- Waited ----------
> ------------
> SQL*Net message to client 1425 0.00
> 0.00
> SQL*Net message from client 1425 3.86
> 6.99
> latch: library cache 37 0.00
> 0.06
> latch: shared pool 12 0.00
> 0.04
>
> ********************************************************************************
>
> *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
> ---------------------------------------- Waited ----------
> ------------
> db file sequential read 80 0.02
> 0.51
> latch: library cache 10 0.00
> 0.02
> latch: shared pool 22 0.00
> 0.04
>
> ********************************************************************************
>
> thanks for any suggestions,
> Peter Sylvester
> MITRE Corp.
>
>

--
http://www.freelists.org/webpage/oracle-l