Re: PL/SQL Wrapper Costs

  • From: "Vlad Sadilovskiy" <vlovsky@xxxxxxxxx>
  • To: peters@xxxxxxxxx
  • Date: Wed, 13 Jun 2007 22:58:32 -0400

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@xxxxxxxxx> 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.


Other related posts: