[20170909]為什麼是12秒.txt--//在開發程式時我一般會強調開發儘量不要寫一些自定義函數，往往可能導致CPU忙。--//例子很像這樣:CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE) RETURN dept. ...
[20170909]為什麼是12秒.txt
--//在開發程式時我一般會強調開發儘量不要寫一些自定義函數，往往可能導致CPU忙。
--//例子很像這樣:
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
--//這樣定義實際上非常不好,如果執行如下,相當於每行都會調用函數get_dept,形成不必要的遞歸.
--//本來應該使用表連接解決的,使用函數,有點像標量子查詢.
--//當時我建議他好好看一下我寫的blog,鏈接如下:
--// http://blog.itpub.net/267265/viewspace-2138042/ => [20170426]為什麼是4秒.txt
--// 結果對方發現在12c for windows下,測試結果與我的測試不符,我重新測試看看.
1.環境:
SCOTT@test01p> @ ver1
PORT_STRING VERSION BANNER CON_ID
------------------------------ -------------- -------------------------------------------------------------------------------- ----------
IBMPC/WIN_NT64-9.1.0 12.1.0.1.0 Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production 0
2.建立函數:
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
set timing on
set autot traceonly;
SCOTT@test01p> select empno, ename, deptno, get_dept(deptno) c20 from emp;
14 rows selected.
Elapsed: 00:00:14.02
--//執行多次穩定遞歸的數量.需要14秒完成.
Execution Plan
----------------------------------------------------------
Plan hash value: 3956160932
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 14 | 182 | 3 (0)| 00:00:01 |
| 1 | TABLE ACCESS FULL| EMP | 14 | 182 | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------
Statistics
----------------------------------------------------------
14 recursive calls
0 db block gets
36 consistent gets
0 physical reads
0 redo size
1130 bytes sent via SQL*Net to client
544 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
14 rows processed
--//可以發現遞歸執行14次(如果不是,執行多次最後會穩定在14次)
--//換成標量子查詢:
SCOTT@test01p> select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
14 rows selected.
Elapsed: 00:00:12.04
Execution Plan
----------------------------------------------------------
Plan hash value: 1340320406
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 14 | 182 | 9 (0)| 00:00:01 |
| 1 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 |
| 2 | TABLE ACCESS FULL| EMP | 14 | 182 | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------
Statistics
----------------------------------------------------------
12 recursive calls
0 db block gets
32 consistent gets
0 physical reads
0 redo size
1130 bytes sent via SQL*Net to client
544 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
14 rows processed
--//執行時間是12秒,遞歸12次.與我在11g下測試不同,11g下測試3秒.
set autot off
alter session set statistics_level=all;
SCOTT@test01p> show array
arraysize 200
SCOTT@test01p> select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
...
SCOTT@test01p> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID apagxtf1p2puy, child number 1
-------------------------------------
select empno, ename, deptno, (select get_dept(deptno) from dual )c20
from emp
Plan hash value: 1340320406
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 9 (100)| | 14 |00:00:00.01 | 8 |
| 1 | FAST DUAL | | 12 | 1 | | 2 (0)| 00:00:01 | 12 |00:00:00.01 | 0 |
| 2 | TABLE ACCESS FULL| EMP | 1 | 14 | 182 | 3 (0)| 00:00:01 | 14 |00:00:00.01 | 8 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$2 / DUAL@SEL$2
2 - SEL$1 / EMP@SEL$1
21 rows selected.
--//從執行計劃也可以發現fast dual執行了12次.為什麼?不好理解?要麼3次,要麼14次?什麼也不應該12次.
3.分析:
--//使用10046跟蹤看看
@ 10046on 12
select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
@ 10046off
--//檢查跟蹤文件.
*** 2017-09-09 21:20:16.366
WAIT #181607424: nam='PL/SQL lock timer' ela= 999265 duration=0 p2=0 p3=0 obj#=665 tim=5412716150
=====================
PARSING IN CURSOR #181597968 len=42 dep=1 uid=109 oct=3 lid=109 tim=5412716418 hv=328320763 ad='7ff13e15ba0' sqlid='56r5sd49t3jrv'
SELECT DNAME FROM DEPT WHERE DEPTNO = :B1
END OF STMT
BINDS #181597968:
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=212a7fb0 bln=22 avl=02 flg=05
value=20
EXEC #181597968:c=0,e=8900,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2852011669,tim=5412725274
FETCH #181597968:c=0,e=28,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=5412725381
STAT #181597968 id=1 cnt=1 pid=0 pos=1 obj=92285 op='TABLE ACCESS BY INDEX ROWID DEPT (cr=2 pr=0 pw=0 time=30 us cost=1 size=13 card=1)'
STAT #181597968 id=2 cnt=1 pid=1 pos=1 obj=92286 op='INDEX UNIQUE SCAN PK_DEPT (cr=1 pr=0 pw=0 time=19 us cost=0 size=0 card=1)'
CLOSE #181597968:c=0,e=3,dep=1,type=3,tim=5412735882
FETCH #181607424:c=0,e=1019217,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=1,plh=1340320406,tim=5412735943
WAIT #181607424: nam='SQL*Net message from client' ela= 1165 driver id=1413697536 #bytes=1 p3=0 obj#=665 tim=5412737203
...
d:\tools\rlwrap>grep "BINDS #181597968:" D:\app\oracle\diag\rdbms\test\test\trace\test_ora_6436.trc |wc
12 24 216
--//確實12次.
d:\tools\rlwrap> grep -A5 "BINDS #181597968:" D:\app\oracle\diag\rdbms\test\test\trace\test_ora_6436.trc | grep "^ value="
value=20
value=30
value=20
value=30
value=10
value=20
value=10
value=30
value=20
value=30
value=20
value=10
SCOTT@test01p> select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
EMPNO ENAME DEPTNO C20
---------- ---------- ---------- --------------------
7369 SMITH 20 RESEARCH
7499 ALLEN 30 SALES
7521 WARD 30 SALES
7566 JONES 20 RESEARCH
7654 MARTIN 30 SALES
7698 BLAKE 30 SALES
7782 CLARK 10 ACCOUNTING
7788 SCOTT 20 RESEARCH
7839 KING 10 ACCOUNTING
7844 TURNER 30 SALES
7876 ADAMS 20 RESEARCH
7900 JAMES 30 SALES
7902 FORD 20 RESEARCH
7934 MILLER 10 ACCOUNTING
14 rows selected.
--//對比你可以發現,如果鄰近的值一樣,函數調用僅僅1次.
SCOTT@test01p> select * from (select empno, ename, deptno, lag(deptno,1) over(order by rownum) next from emp) where deptno=next;
EMPNO ENAME DEPTNO NEXT
---------- ---------- ---------- ----------
7521 WARD 30 30
7698 BLAKE 30 30
--//這樣減少2次調用,說明12c與11g在標量子查詢上處理與原來不同.不知道是什麼回事,上班再仔細對比看看(與11g).
--//或者是OS版本的問題....
--//一個簡單的驗證,建立一個按照deptno排序的表.
create table empx as select * from emp order by deptno;
SCOTT@test01p> select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from empx;
EMPNO ENAME DEPTNO C20
---------- ---------- ---------- --------------------
7782 CLARK 10 ACCOUNTING
...
7654 MARTIN 30 SALES
14 rows selected.
Elapsed: 00:00:03.03
--//現在3秒...如果這樣執行:
select t.* ,(select get_dept(t.deptno) from dual ) c20 from ( select empno, ename, deptno from emp order by deptno) t;
...
Elapsed: 00:00:12.00
--//竟然也是12秒.不過看執行計劃馬上明白:
SCOTT@test01p> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 248fpg2995yz8, child number 0
-------------------------------------
select t.* ,(select get_dept(t.deptno) from dual ) c20 from ( select
empno, ename, deptno from emp order by deptno) t
Plan hash value: 3996307794
------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 9 (100)| | 14 |00:00:12.00 | 31 | | | |
| 1 | FAST DUAL | | 12 | 1 | | 2 (0)| 00:00:01 | 12 |00:00:00.01 | 0 | | | |
| 2 | SORT ORDER BY | | 1 | 14 | 182 | 9 (0)| 00:00:01 | 14 |00:00:12.00 | 31 | 2048 | 2048 | 2048 (0)|
| 3 | TABLE ACCESS FULL| EMP | 1 | 14 | 182 | 3 (0)| 00:00:01 | 14 |00:00:00.01 | 7 | | | |
------------------------------------------------------------------------------------------------------------------------------------------------
--//可以發現 SORT ORDER BY 消耗12秒.也就是在排序前就進行遞歸調用函數了.
--//對比前面的執行計劃,再次發現奇怪問題,看不出前面的執行計劃12秒消耗在那裡?
--//使用提示MATERIALIZE改寫如下:
SCOTT@test01p> with t as ( select /*+MATERIALIZE */ empno, ename, deptno from emp order by deptno) select t.*,(select get_dept(t.deptno) from dual ) c20 from t;
EMPNO ENAME DEPTNO C20
---------- ---------- ---------- --------------------
7782 CLARK 10 ACCOUNTING
7839 KING 10 ACCOUNTING
..
7654 MARTIN 30 SALES
14 rows selected.
Elapsed: 00:00:03.02
SCOTT@test01p> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID fwvgq6403j0nx, child number 0
-------------------------------------
with t as ( select /*+MATERIALIZE */ empno, ename, deptno from emp
order by deptno) select t.*,(select get_dept(t.deptno) from dual ) c20
from t
Plan hash value: 2014637640
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads | Writes | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 11 (100)| | 14 |00:00:00.01 | 21 | 1 | 1 | | | |
| 1 | FAST DUAL | | 3 | 1 | | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | 0 | 0 | | | |
| 2 | TEMP TABLE TRANSFORMATION | | 1 | | | | | 14 |00:00:00.01 | 21 | 1 | 1 | | | |
| 3 | LOAD AS SELECT | | 1 | | | | | 0 |00:00:00.01 | 11 | 0 | 1 | 1036K| 1036K| |
| 4 | SORT ORDER BY | | 1 | 14 | 182 | 3 (0)| 00:00:01 | 14 |00:00:00.01 | 7 | 0 | 0 | 2048 | 2048 | 2048 (0)|
| 5 | TABLE ACCESS FULL | EMP | 1 | 14 | 182 | 3 (0)| 00:00:01 | 14 |00:00:00.01 | 7 | 0 | 0 | | | |
| 6 | VIEW | | 1 | 14 | 322 | 2 (0)| 00:00:01 | 14 |00:00:00.01 | 7 | 1 | 0 | | | |
| 7 | TABLE ACCESS FULL | SYS_TEMP_0FD9D660E_18A8CC5 | 1 | 14 | 182 | 2 (0)| 00:00:01 | 14 |00:00:00.01 | 7 | 1 | 0 | | | |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
4.繼續測試使用 DETERMINISTIC Functions:
--//一般如果在在某個函數定義索引，需要DETERMINISTIC,表示返回結果固定。其實即使不固定，也可以這樣定義。
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
DETERMINISTIC
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
SCOTT@test01p> select empno, ename, deptno, get_dept(deptno) c20 from emp;
...
14 rows selected.
Elapsed: 00:00:14.01
--//奇怪! 又回到14秒,而在11g下這樣的測試是4秒(註意設置array=200的情況,如果太小,時間會變化).
5.最後補充測試RESULT CACHE的情況:
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
RESULT_CACHE
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
SCOTT@test01p> select empno, ename, deptno, get_dept(deptno) c20 from emp;
14 rows selected.
Elapsed: 00:00:03.13
SCOTT@test01p> select empno, ename, deptno, get_dept(deptno) c20 from emp;
14 rows selected.
Elapsed: 00:00:00.00
--//第1次執行3秒,第2次執行0秒.修改如下結果一樣.
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
RESULT_CACHE
DETERMINISTIC
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
總結:
--//不知道是否是OS版本的問題,有機會安裝12c在linux下重覆測試看看.
--//看來測試環境該轉向12c了....那位有12c for linux的版本測試看看...
--//補充測試11g的情況:
SCOTT@book> @ &r/ver1
PORT_STRING VERSION BANNER
------------------------------ -------------- --------------------------------------------------------------------------------
x86_64/Linux 2.4.xx 11.2.0.4.0 Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
SYS@book> GRANT EXECUTE ON SYS.dbms_lock TO SCOTT;
Grant succeeded.
CREATE OR REPLACE FUNCTION get_dept (p_deptno dept.deptno%TYPE)
RETURN dept.dname%TYPE
IS
l_dname dept.dname%TYPE;
BEGIN
DBMS_LOCK.sleep (1);
SELECT dname
INTO l_dname
FROM dept
WHERE deptno = p_deptno;
RETURN l_dname;
END;
/
set timing on
set autot traceonly;
select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
SCOTT@book> select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
14 rows selected.
Elapsed: 00:00:03.01
Execution Plan
----------------------------------------------------------
Plan hash value: 1340320406
--------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 14 | 182 | 3 (0)| 00:00:01 |
| 1 | FAST DUAL | | 1 | | 2 (0)| 00:00:01 |
| 2 | TABLE ACCESS FULL| EMP | 14 | 182 | 3 (0)| 00:00:01 |
--------------------------------------------------------------------------
Statistics
----------------------------------------------------------
3 recursive calls
0 db block gets
13 consistent gets
0 physical reads
0 redo size
1114 bytes sent via SQL*Net to client
520 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
14 rows processed
--//執行多次,基本穩定在3個遞歸調用.
set autot off
alter session set statistics_level=all;
select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp;
SCOTT@book> @ &r/dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID apagxtf1p2puy, child number 1
-------------------------------------
select empno, ename, deptno, (select get_dept(deptno) from dual )c20 from emp
Plan hash value: 1340320406
--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
--------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 3 (100)| | 14 |00:00:00.01 | 7 |
| 1 | FAST DUAL | | 3 | 1 | | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 |
| 2 | TABLE ACCESS FULL| EMP | 1 | 14 | 182 | 3 (0)| 00:00:01 | 14 |00:00:00.01 | 7 |
--------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$2 / DUAL@SEL$2
2 - SEL$1 / EMP@SEL$1
21 rows selected.
--//Id=2.starts=3次,也驗證函數調用3次.
--//不知道為什麼,也許12.2.0.N版本跟11g一樣,沒有這個oracle版本等以後再測試吧....
