Performance - Qry with PL/SQL Functions vs Qry Straight SQL

From: Alvaro Leal <alvaro.leal_at_caravelconsulting.com>
Date: Thu, 16 Jun 2005 10:57:06 -0700
Message-id: <10b53b610aeb14.10aeb1410b53b6@prod.shawcable.com>

Hi,

I've been asked to look into solving a long running DW transformation process. It turns out that the SQL executed is littered with PL/SQL functions that I've shown can be replaced with DECODEs, DECODE + CASE, or CASE statements. The results of my tests were nothing short of spectacular. A query that took two hours can be completed in less than 3 minutes. What I don't understand is why the calls to PL/SQL functions ( the bulk of the functions do not execute queries but execute on literals or process conditional statements ) can be such a bottleneck. I know there's a context switch in moving from the SQL engine into the PL/SQL engine, but aside from this, again I'm at a loss as to the exact cause of the noted overhead from the PL/SQL function calls.

Therefore, I'm looking to pinpoint the performance bottleneck as to why a query that contains PL/SQL functions runs takes almost 2,500% longer than a query restricted to SQL. The respective times of the run comparisons are 735606 Hundred Secs and 28402 Hundred Secs respectively.

To help you diagnose the problem I provide below:

1. Environment Information
2. Example of PL/SQL functions
3. Example of Query
4. Extended Trace File information
5. System statistics of the highest entries

In advance, thanks for your review.

Alvaro

ENVIRONMENT INFORMATION:

- Oracle EE 10.1.0.3.0
- OS - Linux Red Hat ES 3.0
- HW - 	HP Integrity rx5670; 4 CPUs ; Itanium 2 CPU family; CPU Speed 1.5 GHz; 
- RAM - 6GB

EXAMPLE OF PL/SQL FUNCTIONS:

• KV_GET_GEN Package FUNCTION i_m RETURN NUMBER IS BEGIN RETURN 7002; END;
• SUBPOP Package FUNCTION male BEGIN --* @step {1} Cache the Male gender Id. IF pv_maleId IS NULL THEN pv_maleId := kv_get_gen.i_m(); END IF;

      --* @step {1} Check if the given Id is part of the Male sub pop.
      IF ip_objId1 = pv_maleId THEN
         RETURN ip_value;
      ELSE
         RETURN ip_returnIfNotMember;
      END IF;
   

   EXCEPTION
...

EXAMPLE OF QUERY:
-- note the function calls are commented out, but the code below should provide -- a good example of the two flavours of QRY.

SELECT
SUM(FCT.CNT_VALUE) ALL_CNT_VALUE
,SUM(FCT.CNT_COUNT) ALL_CNT_COUNT
,SUM(FCT.CNT_SUM) ALL_CNT_SUM

-- ,SUM(subpop.ABORIGINAL(cnt_value,evABOR_OBJ_ID)) AB_CNT_VALUE
,SUM(DECODE(evABOR_OBJ_ID, 432507435, cnt_value,0)) AB_CNT_VALUE
--,SUM(subpop.ABORIGINAL_FEMALES(cnt_value,evABOR_OBJ_ID,gen_obj_id)) AB_F_CNT_VALUE
,SUM(DECODE(evABOR_OBJ_ID, 432507435, DECODE(gen_obj_id, 7000, cnt_value, 0), 0)) AB_F_CNT_VALUE
/*
many more lines of code
*/
--,SUM(subpop.BEHAVIOUR_DISABILITIES(cnt_value,SPND_OBJ_ID)) BEHDIS_CNT_VALUE
,SUM(CASE

      WHEN SPND_OBJ_ID IN ( 302776, 7134, 302780, 302786 ) THEN cnt_value\
      ELSE 0
     END) BEHDIS_CNT_VALUE

/*
many more lines of code
*/
where
--kv_get_dimflg.i_ps30 = sep30_obj_id
433522215 = sep30_obj_id
and grade.label <> 'HOME SCHOOLED STUDENT' --and kv_get_dimflg.i_NADGRD = is_adgrd_obj_id AND 433522227 = is_adgrd_obj_id

and age.stagegrp_obj_descr <> 'Under Age 5'
and age.obj_id = adec_obj_id
AND FCT.SCH_OBJ_ID = SCH.OBJ_ID
AND SCH.ALL_OBJ_ID IS NOT NULL
AND FCT.SCHYR_OBJ_ID = SCHYR.OBJ_ID
AND FCT.GRADE_OBJ_ID = GRADE.OBJ_ID

AND GRADE.EDTYP_OBJ_ID IS NOT NULL
AND FCT.STYP_OBJ_ID = STYP.OBJ_ID
AND FCT.SFACTYP_OBJ_ID = SFACTYP.OBJ_ID
AND SFACTYP.ALL_OBJ_ID IS NOT NULL

GROUP BY SCH.ALL_OBJ_ID


,NVL(SCHYR.SCLYR_OBJ_ID,SCHYR.SCLYR_PAR_ID)

,GRADE.EDTYP_OBJ_ID

,NVL(STYP.SCLTYP_OBJ_ID,STYP.STD_PAR_ID)
,SFACTYP.ALL_OBJ_ID
EXTENDED TRACE INFORMATION:

• the query restricted to just SQL call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.32 0.32 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 1 245.23 320.81 207305 207351 0 18 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3 245.56 321.13 207305 207351 0 18

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 63 (recursive depth: 2)

Rows Row Source Operation

-------  ---------------------------------------------------
     18  SORT GROUP BY (cr=207351 pr=207305 pw=0 time=320758855 us)

9369812 HASH JOIN (cr=207351 pr=207305 pw=0 time=244795585 us)   42549 TABLE ACCESS FULL DM_DIM_TIME (cr=566 pr=555 pw=0 time=90502 us) 9369812 HASH JOIN (cr=206785 pr=206750 pw=0 time=178606521 us)

   3327     TABLE ACCESS FULL DM_DIM_ORG (cr=110 pr=106 pw=0 time=50381 us)
9369812     HASH JOIN  (cr=206675 pr=206644 pw=0 time=122219268 us)
     25      TABLE ACCESS FULL DM_DM_GRADE (cr=3 pr=1 pw=0 time=45177 us)
9425947      HASH JOIN  (cr=206672 pr=206643 pw=0 time=198309021 us)
     16       TABLE ACCESS FULL DM_DIM_SCLTYP (cr=3 pr=1 pw=0 time=17844 us)
9425947       HASH JOIN  (cr=206669 pr=206642 pw=0 time=141732985 us)
     15        TABLE ACCESS FULL DM_DIM_FACTYP (cr=3 pr=1 pw=0 time=14663 us)
9425947        HASH JOIN  (cr=206666 pr=206641 pw=0 time=85160186 us)
  39559         TABLE ACCESS FULL DM_DIM_AGE (cr=829 pr=826 pw=0 time=131168 us)
9426983         TABLE ACCESS FULL FT_FTSCHLSTUD (cr=205837 pr=205815 pw=0 time=84865837 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         8        0.02          0.11
  db file scattered read                       3337        0.11         49.87
********************************************************************************

• the query containing PL/SQL function calls

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse        1      0.39       0.41          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1   6672.84    7181.72     205814     207350          0          18
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3   6673.24    7182.14     205814     207350          0          18

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 63 (recursive depth: 2)

Rows Row Source Operation

-------  ---------------------------------------------------
     18  SORT GROUP BY (cr=207350 pr=205814 pw=0 time=1083025775 us)

9369812 HASH JOIN (cr=207350 pr=205814 pw=0 time=449907717 us)   42549 TABLE ACCESS FULL DM_DIM_TIME (cr=566 pr=0 pw=0 time=85198 us) 9369812 HASH JOIN (cr=206784 pr=205814 pw=0 time=384260873 us)

   3327     TABLE ACCESS FULL DM_DIM_ORG (cr=110 pr=0 pw=0 time=6755 us)
9369812     HASH JOIN  (cr=206674 pr=205814 pw=0 time=328033093 us)
     25      TABLE ACCESS FULL DM_DM_GRADE (cr=3 pr=0 pw=0 time=128 us)
9425947      HASH JOIN  (cr=206671 pr=205814 pw=0 time=395977037 us)
     16       TABLE ACCESS FULL DM_DIM_SCLTYP (cr=3 pr=0 pw=0 time=86 us)
9425947       HASH JOIN  (cr=206668 pr=205814 pw=0 time=339418962 us)
     15        TABLE ACCESS FULL DM_DIM_FACTYP (cr=3 pr=0 pw=0 time=79 us)
9425947        HASH JOIN  (cr=206665 pr=205814 pw=0 time=282860861 us)
  39559         TABLE ACCESS FULL DM_DIM_AGE (cr=829 pr=0 pw=0 time=79229 us)
9426983         TABLE ACCESS FULL FT_FTSCHLSTUD (cr=205836 pr=205814 pw=0 time=282838908 us)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file scattered read                       3236        0.14         73.23
********************************************************************************

SYSTEM STATISTICS WITH HIGHEST DIFFERENTIAL
     

                                         A        B
                                        With     Just    Difference
ID      Statistic Descr                 PL/SQL   SQL    ( A - B )
26	STAT session pga memory	        7340032	4653056	2686976
13	STAT CPU used by this session	667426	24281	643145
22	STAT session uga memory max	12465736 11864784	600952
21	STAT session uga memory	        2601480	2093248	508232
518	LATCH row cache objects	        233115	24072	209043
597	LATCH SQL memory manager workarea list latch	160770	8277	152493
448	LATCH checkpoint queue latch	124700	8708	115992
353	LATCH enqueue hash chains	106835	6814	100021
352	LATCH enqueues	                102918	5536	97382
337	LATCH session allocation	86754	4358	82396
457	LATCH object queue header operation	492441	413988	78453
532	LATCH library cache	        163174	85447	77727
351	LATCH messages	                48096	2732	45364
678	LATCH JS queue state obj latch	43126	2190	40936
435	LATCH Memory Management Latch	35925	1830	34095
668	LATCH SWRF Alerted Metric Element list	32846	0	32846
370	LATCH channel operations parent latch	24117	1246	22871
534	LATCH library cache pin	         28483	8508	19975
531	LATCH shared pool	         27265	9369	17896
533	LATCH library cache lock	14973	4532	10441
385	LATCH active service list	10540	678	9862
470	LATCH redo allocation	         9366	603	8763
468	LATCH redo writing	         8791	654	8137
342	LATCH longop free list parent	7618	265	7353
508	LATCH undo global data	        3481	480	3001
18	STAT user I/O wait time	        7301	4617	2684
447	LATCH active checkpoint queue latch	2892	235	2657
438	LATCH mostly latch-free SCN	2614	164	2450
439	LATCH lgwr LWN SCN	        2613	164	2449
564	LATCH session timer	        2575	132	2443
462	LATCH archive process latch	2545	130	2415
537	LATCH library cache load lock	2080	2	2078

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

Received on Thu Jun 16 2005 - 14:02:20 CDT