[20180205]为什么是3秒.txt
http://blog.itpub.net/267265/viewspace-2138042/
1.环境：
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
CREATE OR REPLACE FUNCTION SCOTT.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@book> show array
arraysize 200
SCOTT@book> set timing on
SCOTT@book> select empno, ename, deptno, get_dept(deptno) 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.
Elapsed: 00:00:04.01
--//4秒,相关测试与array设置有关,.而在PLSQLDev下执行实际是3秒为什么呢?
2.做一个跟踪分析:
--//定位PLSQLDev的sid,serial#,执行如下:
begin sys.dbms_monitor.session_trace_enable(144,5,true,true); end;
--//在PLSQLDev执行如下:
select empno, ename, deptno, get_dept(deptno) c20 from emp ;
begin sys.dbms_monitor.session_trace_disable(144,5); end;
--//使用tkprof检查发现:
SQL ID: 6uxfy61c9nz30 Plan Hash: 3956160932
select empno, ename, deptno, get_dept(deptno) c20
from
emp
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 1 0.00 3.00 0 6 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3 0.00 3.00 0 6 0 14
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 83
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
14 14 14 TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=81 us cost=3 size=182 card=14)
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
SQL*Net message from client 2 0.01 0.01
PL/SQL lock timer 3 1.00 3.00
********************************************************************************
--//确实是3秒.为什么与sqlplus不同呢?
=====================
PARSING IN CURSOR #140040481766096 len=60 dep=0 uid=83 oct=3 lid=83 tim=1517792961409130 hv=1486519392 ad='7b4604d8' sqlid='6uxfy61c9nz30'
select empno, ename, deptno, get_dept(deptno) c20 from emp
END OF STMT
PARSE #140040481766096:c=4999,e=4713,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3956160932,tim=1517792961409128
EXEC #140040481766096:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3956160932,tim=1517792961409280
WAIT #140040481766096: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=87106 tim=1517792961409355
WAIT #140040481766096: nam='SQL*Net message from client' ela= 498 driver id=1413697536 #bytes=1 p3=0 obj#=87106 tim=1517792961409914
*** 2018-02-05 09:09:22.410
WAIT #140040481766096: nam='PL/SQL lock timer' ela= 1000648 duration=0 p2=0 p3=0 obj#=87106 tim=1517792962410780
=====================
PARSING IN CURSOR #140040476722760 len=42 dep=1 uid=83 oct=3 lid=83 tim=1517792962410932 hv=328320763 ad='7c641d10' sqlid='56r5sd49t3jrv'
SELECT DNAME FROM DEPT WHERE DEPTNO = :B1
END OF STMT
BINDS #140040476722760:
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=7f5db6e02298 bln=22 avl=02 flg=05
value=20
EXEC #140040476722760:c=0,e=175,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2852011669,tim=1517792962411069
FETCH #140040476722760:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792962411153
~~~~
CLOSE #140040476722760:c=0,e=3,dep=1,type=3,tim=1517792962411211
WAIT #140040481766096: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=87106 tim=1517792962411248
*** 2018-02-05 09:09:23.411
WAIT #140040481766096: nam='PL/SQL lock timer' ela= 1000498 duration=0 p2=0 p3=0 obj#=87106 tim=1517792963411794
BINDS #140040476722760:
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=7f5db6e02298 bln=22 avl=02 flg=05
value=30
EXEC #140040476722760:c=0,e=117,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2852011669,tim=1517792963412031
FETCH #140040476722760:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792963412102
~~~~~~~~
CLOSE #140040476722760:c=0,e=3,dep=1,type=3,tim=1517792963412158
*** 2018-02-05 09:09:24.412
WAIT #140040481766096: nam='PL/SQL lock timer' ela= 1000547 duration=0 p2=0 p3=0 obj#=87106 tim=1517792964412768
BINDS #140040476722760:
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=7f5db6e02298 bln=22 avl=02 flg=05
value=10
EXEC #140040476722760:c=0,e=118,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2852011669,tim=1517792964412986
FETCH #140040476722760:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792964413055
~~~~~~~~~
CLOSE #140040476722760:c=0,e=2,dep=1,type=3,tim=1517792964413110
FETCH #140040481766096:c=2000,e=3003217,p=0,cr=12,cu=0,mis=0,r=14,dep=0,og=1,plh=3956160932,tim=1517792964413175
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
STAT #140040481766096 id=1 cnt=14 pid=0 pos=1 obj=87108 op='TABLE ACCESS FULL EMP (cr=6 pr=0 pw=0 time=81 us cost=3 size=182 card=14)'
WAIT #140040481766096: nam='SQL*Net message from client' ela= 12882 driver id=1413697536 #bytes=1 p3=0 obj#=87106 tim=1517792964426185
=====================
FETCH #140040476722760:c=0,e=29,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792962411153
FETCH #140040476722760:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792963412102
FETCH #140040476722760:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=2852011669,tim=1517792964413055
FETCH #140040481766096:c=2000,e=3003217,p=0,cr=12,cu=0,mis=0,r=14,dep=0,og=1,plh=3956160932,tim=1517792964413175
--//可以发现PLSQLDev与sqlplus执行方式不一样.注意看下划线内容,可以发现fetch r=14,也就是一次取出全部结果(估计也受限array或
--//者某些参数).
--//而#140040481766096对应的sql语句是select empno, ename, deptno, get_dept(deptno) c20 from emp.
--//而#140040476722760对应的sql语句是SELECT DNAME FROM DEPT WHERE DEPTNO = :B1,仅仅r=1执行3次.
--//我在toad写也做了相同的测试也发现一样的问题,toad也是3秒,看来一些开发工具与sqlplus下执行sql存在小量的区别.
--//即使我在toad写成脚本
set timing on
set linesize 200
column c20 format a20
select empno, ename, deptno, get_dept(deptno) c20 from emp;
--//选择execute as script,执行时间也是3秒.
