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_ROWSParsing 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" = :B1call 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.
