사용자 정의 함수의 실행 계획

실행 계획에서 사용자 정의 함수의 소요 시간이 제대로 표시되지 않는 경우가 있다. 관련 내용을 살펴보자.

테스트를 위해 DBMS_LOCK 패키지에 대한 실행 권한을 사용자에게 부여하고, 아래와 같이 테이블과 함수를 생성하자.

-- 1-1
GRANT EXECUTE ON DBMS_LOCK TO tuna;

-- 1-2
DROP TABLE t1 PURGE;
CREATE TABLE t1 AS SELECT 1 AS c1 FROM XMLTABLE ('1 to 10');

CREATE OR REPLACE FUNCTION fnc_sleep (i_seconds IN NUMBER) RETURN NUMBER DETERMINISTIC
IS
BEGIN
    DBMS_LOCK.SLEEP (i_seconds);
    RETURN 1;
END fnc_sleep;
/

아래에서 쿼리 2-1은 10초가 소요되었지만 실행 계획은 0.01초가 소요된 것으로 표시된다. 쿼리 2-2는 소요 시간이 제대로 표시된다. 구문(SELECT STATEMENT)을 제외한 상위 오퍼레이션이 존재하는 경우 소요 시간이 제대로 표시되는 것을 알 수 있다. 쿼리 2-2는 12초가 소요되었는데 이유는 마지막에 살펴보자. 서브 쿼리 팩토링을 사용한 경우에는 병목 구간을 오판할 수 있다. 쿼리 2-3은 2번 LOAD AS SELECT 오퍼레이션이 소요 시간이 표시되어 쓰기 작업에서 병목이 발생한 것처럼 보인다. 

-- 2-1
SELECT fnc_sleep (c1) AS c1 FROM t1;

경   과: 00:00:10.01

--------------------------------------------------------
| Id  | Operation         | Name | A-Rows |   A-Time   |
--------------------------------------------------------
|   0 | SELECT STATEMENT  |      |     10 |00:00:00.01 |
|   1 |  TABLE ACCESS FULL| T1   |     10 |00:00:00.01 |
--------------------------------------------------------

-- 2-2
SELECT * FROM (SELECT /*+ NO_MERGE */ fnc_sleep (c1) AS c1 FROM t1);

경   과: 00:00:12.01

---------------------------------------------------------
| Id  | Operation          | Name | A-Rows |   A-Time   |
---------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     10 |00:00:11.01 |
|   1 |  VIEW              |      |     10 |00:00:11.01 | -- !
|   2 |   TABLE ACCESS FULL| T1   |     10 |00:00:00.01 |
---------------------------------------------------------

-- 2-3
WITH w1 AS (SELECT /*+ MATERIALIZE */ fnc_sleep (c1) AS c1 FROM t1)
SELECT * FROM w1;

경   과: 00:00:10.01

---------------------------------------------------------------------------------------
| Id  | Operation                  | Name                       | A-Rows |   A-Time   |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT           |                            |     10 |00:00:10.01 |
|   1 |  TEMP TABLE TRANSFORMATION |                            |     10 |00:00:10.01 |
|   2 |   LOAD AS SELECT           |                            |      0 |00:00:10.01 | -- !
|   3 |    TABLE ACCESS FULL       | T1                         |     10 |00:00:00.01 |
|   4 |   VIEW                     |                            |     10 |00:00:00.01 |
|   5 |    TABLE ACCESS FULL       | SYS_TEMP_0FD9D69DE_ADF921B |     10 |00:00:00.01 |
---------------------------------------------------------------------------------------

아래는 쿼리 2-2의 트레이스 프로파일 내용이다.(ora11gr2_ora_5724_udf.trc) PL/SQL lock timer 이벤트가 12회 발생한 것을 확인할 수 있다.^[각주:1] 짐작가는 이유가 몇가지 있긴하지만 확실치 않다.

-- 3
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.01      11.01          1          4          0          10
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01      11.02          1          4          0          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        10         10         10  VIEW  (cr=4 pr=1 pw=0 time=2 us starts=0 cost=2 size=4251 card=327)
        10         10         10   TABLE ACCESS FULL T1 (cr=4 pr=1 pw=0 time=2 us starts=0 cost=2 size=0 card=327)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        1        0.01          0.01
  db file sequential read                         1        0.00          0.00
  PL/SQL lock timer                              12        1.01         12.00 -- !
  SQL*Net message from client                     2        0.00          0.00

1. 11.2 버전에서 테스트한 내용이다. 12.1 이후 버전부터 11회만 수행된다. [본문으로]