ACCESS[20170909]为何是12秒.txt

[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
#ACCESS,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版本等未来再测试吧….

相关文章