[20241004]为什么这么慢.txt
--//家里无聊，做的一些测试，一些现象我无法解析。
1.环境：
SCOTT@book01p> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.建立测试环境：
--//GRANT EXECUTE ON SYS.DBMS_LOCK TO SCOTT;
CREATE OR REPLACE FUNCTION SCOTT.sleep (seconds IN NUMBER)
RETURN NUMBER
AS
BEGIN
sys.DBMS_LOCK.sleep (seconds);
RETURN seconds;
END;
/
SCOTT@book01p> create table tx as select level a from dual connect by level<=3 ;
Table created.
SCOTT@book01p> create table ty as select level a from dual connect by level<=3 ;
Table created.
--//分析略。
3.测试：
SCOTT@book01p> set timing on
SCOTT@book01p> SELECT sleep(a) val FROM tx;
VAL
----------
1
2
3
Elapsed: 00:00:06.03
--//3+2+1=6秒没有问题.
--//测试前大家先猜测看执行如下需要多少秒？12秒？15秒？
SCOTT@book01p> @ sl all
alter session set statistics_level = all;
Session altered.
with t1 as ( SELECT /*+ inline */ sleep(a) val FROM tx),t2 as ( SELECT /*+ inline */ sleep(a) val FROM ty)
select * from t1 ,t2 WHERE t1.val = t2.val;
with t1 as ( SELECT sleep(a) val FROM tx),t2 as ( SELECT sleep(a) val FROM ty) select * from t1 ,t2 WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:24.28
--//噢，猜测不到需要24秒。看看执行计划：
SCOTT@book01p> @ dpc '' projection ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 641xs1dhjk53y, child number 0
-------------------------------------
with t1 as ( SELECT sleep(a) val FROM tx),t2 as ( SELECT sleep(a) val
FROM ty) select * from t1 ,t2 WHERE t1.val = t2.val
Plan hash value: 1879928712
------------------------------------------------------------------------------------------------------------------------------------------------
| 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 | | | 6 (100)| | 3 |00:00:12.10 | 5 | | | |
|* 1 | HASH JOIN | | 1 | 1 | 6 | 6 (0)| 00:00:01 | 3 |00:00:12.10 | 5 | 2078K| 2078K| 963K (0)|
| 2 | TABLE ACCESS FULL| TX | 1 | 3 | 9 | 3 (0)| 00:00:01 | 3 |00:00:00.01 | 2 | | | |
| 3 | TABLE ACCESS FULL| TY | 1 | 3 | 9 | 3 (0)| 00:00:01 | 3 |00:00:00.01 | 3 | | | |
------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$18780C30
2 - SEL$18780C30 / "TX"@"SEL$1"
3 - SEL$18780C30 / "TY"@"SEL$2"
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("SLEEP"("A")="SLEEP"("A"))
Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - (#keys=1) "A"[NUMBER,22], "A"[NUMBER,22]
2 - "A"[NUMBER,22]
3 - "A"[NUMBER,22]
35 rows selected.
--//A-Time 显示也是12.10，而实际的执行需要24秒。
--//注意看一个细节id=2,id=3.结合Column Projection Information (identified by operation id):部分：
--//仅仅取字段A，而不是sleep(A),id=2,3的a-time很小。
--//真正做HASH JOIN的是id=1，在这里调用函数sleep。消耗6+6秒。
--//在id=0时，select输出，再次调用sleep函数，导致再需要6+6秒这样总共24秒。
--//做1个10046跟踪就很清楚了。
$ grep "lock time" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3832.trc
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 1008297 duration=0 p2=0 p3=0 obj#=24401 tim=3977086831
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 2019544 duration=0 p2=0 p3=0 obj#=24401 tim=3979106823
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 3000002 duration=0 p2=0 p3=0 obj#=24401 tim=3982107136
--//第1次扫描表tx，形成hash table。需要6秒
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 1018749 duration=0 p2=0 p3=0 obj#=24401 tim=3983126232
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 999545 duration=0 p2=0 p3=0 obj#=24401 tim=3984126149
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 1003211 duration=0 p2=0 p3=0 obj#=24401 tim=3985129576
--//第2次扫描表ty，先取出a=1，每条记录都调用sleep 3次作为比较。
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 2006211 duration=0 p2=0 p3=0 obj#=24401 tim=3987135920
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 2000298 duration=0 p2=0 p3=0 obj#=24401 tim=3989136349
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 2002598 duration=0 p2=0 p3=0 obj#=24401 tim=3991139069
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 3012665 duration=0 p2=0 p3=0 obj#=24401 tim=3994153622
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 3006930 duration=0 p2=0 p3=0 obj#=24401 tim=3997160698
WAIT #140437728019360: nam='PL/SQL lock timer' ela= 3001133 duration=0 p2=0 p3=0 obj#=24401 tim=4000161986
--//一个很简单验证如果输出不包括val(执行函数部分)，就可以减少执行时间。
SCOTT@book01p> with t1 as ( SELECT sleep(a) val,a FROM tx),t2 as ( SELECT sleep(a) val,a FROM ty) select t1.a,t2.a from t1 ,t2 WHERE t1.val = t2.val;
VAL VAL
---------- ----------
3 3
2 2
1 1
Elapsed: 00:00:12.11
--//使用MATERIALIZE提示就可以减少函数调用。
with t1 as ( SELECT /*+ MATERIALIZE */ sleep(a) val FROM tx),t2 as ( SELECT /*+ MATERIALIZE */ sleep(a) val FROM ty)
select * from t1 ,t2 WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:12.04
SCOTT@book01p> @ dpc '' projection ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 2081zkrcxfn69, child number 0
-------------------------------------
with t1 as ( SELECT /*+ MATERIALIZE */ sleep(a) val FROM tx),t2 as (
SELECT /*+ MATERIALIZE */ sleep(a) val FROM ty) select * from t1 ,t2
WHERE t1.val = t2.val
Plan hash value: 2067585427
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 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 | | | 10 (100)| | 3 |00:00:12.04 | 6 | | | |
| 1 | TEMP TABLE TRANSFORMATION | | 1 | | | | | 3 |00:00:12.04 | 6 | | | |
| 2 | LOAD AS SELECT (CURSOR DURATION MEMORY)| SYS_TEMP_0FD9D6615_63B4FD | 1 | | | | | 0 |00:00:06.03 | 3 | 1024 | 1024 | |
| 3 | TABLE ACCESS FULL | TX | 1 | 3 | 9 | 3 (0)| 00:00:01 | 3 |00:00:00.01 | 2 | | | |
| 4 | LOAD AS SELECT (CURSOR DURATION MEMORY)| SYS_TEMP_0FD9D6616_63B4FD | 1 | | | | | 0 |00:00:06.01 | 2 | 1024 | 1024 | |
| 5 | TABLE ACCESS FULL | TY | 1 | 3 | 9 | 3 (0)| 00:00:01 | 3 |00:00:00.01 | 2 | | | |
|* 6 | HASH JOIN | | 1 | 1 | 26 | 4 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | 2546K| 2546K| 1063K (0)|
| 7 | VIEW | | 1 | 3 | 39 | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | | | |
| 8 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6615_63B4FD | 1 | 3 | 9 | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | | | |
| 9 | VIEW | | 1 | 3 | 39 | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | | | |
| 10 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6616_63B4FD | 1 | 3 | 9 | 2 (0)| 00:00:01 | 3 |00:00:00.01 | 0 | | | |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$3
2 - SEL$1
3 - SEL$1 / "TX"@"SEL$1"
4 - SEL$2
5 - SEL$2 / "TY"@"SEL$2"
7 - SEL$D67CB2D2 / "T1"@"SEL$3"
8 - SEL$D67CB2D2 / "T1"@"SEL$D67CB2D2"
9 - SEL$EC770CBA / "T2"@"SEL$3"
10 - SEL$EC770CBA / "T1"@"SEL$EC770CBA"
Predicate Information (identified by operation id):
---------------------------------------------------
6 - access("T1"."VAL"="T2"."VAL")
Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - "T1"."VAL"[NUMBER,22], "T2"."VAL"[NUMBER,22]
2 - SYSDEF[4], SYSDEF[0], SYSDEF[1], SYSDEF[120], SYSDEF[0]
3 - "A"[NUMBER,22]
4 - SYSDEF[4], SYSDEF[0], SYSDEF[1], SYSDEF[120], SYSDEF[0]
5 - "A"[NUMBER,22]
6 - (#keys=1) "T1"."VAL"[NUMBER,22], "T2"."VAL"[NUMBER,22]
7 - (rowset=256) "T1"."VAL"[NUMBER,22]
8 - (rowset=256) "C0"[NUMBER,22]
9 - "T2"."VAL"[NUMBER,22]
10 - "C0"[NUMBER,22]
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 2
---------------------------------------------------------------------------
2 - SEL$1
- MATERIALIZE
4 - SEL$2
- MATERIALIZE
66 rows selected.
--//如果写成如下呢？注意sleep(rownum)。
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1,
( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t2
WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:13.11
--//为什么这样写，执行需要13秒呢？
SCOTT@book01p> @ dpc '' projection ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID ddyh0dg3w38a5, child number 0
-------------------------------------
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <=
3) t1, ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY
LEVEL <= 3) t2 WHERE t1.val = t2.val
Plan hash value: 155859586
---------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | OMem | 1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 4 (100)| | 3 |00:00:12.10 | | | |
|* 1 | HASH JOIN | | 1 | 1 | 26 | 4 (0)| 00:00:01 | 3 |00:00:12.10 | 2546K| 2546K| 966K (0)|
| 2 | VIEW | | 1 | 1 | 13 | 2 (0)| 00:00:01 | 3 |00:00:06.08 | | | |
| 3 | COUNT | | 1 | | | | | 3 |00:00:00.01 | | | |
| 4 | CONNECT BY WITHOUT FILTERING| | 1 | | | | | 3 |00:00:00.01 | 2048 | 2048 | 2048 (0)|
| 5 | FAST DUAL | | 1 | 1 | | 2 (0)| 00:00:01 | 1 |00:00:00.01 | | | |
| 6 | VIEW | | 1 | 1 | 13 | 2 (0)| 00:00:01 | 3 |00:00:06.02 | | | |
| 7 | COUNT | | 1 | | | | | 3 |00:00:00.01 | | | |
| 8 | CONNECT BY WITHOUT FILTERING| | 1 | | | | | 3 |00:00:00.01 | 2048 | 2048 | 2048 (0)|
| 9 | FAST DUAL | | 1 | 1 | | 2 (0)| 00:00:01 | 1 |00:00:00.01 | | | |
---------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$2 / "T1"@"SEL$1"
3 - SEL$2
5 - SEL$2 / "DUAL"@"SEL$2"
6 - SEL$3 / "T2"@"SEL$1"
7 - SEL$3
9 - SEL$3 / "DUAL"@"SEL$3"
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("T1"."VAL"="T2"."VAL")
Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - (#keys=1) "T1"."VAL"[NUMBER,22], "T2"."VAL"[NUMBER,22]
2 - "T1"."VAL"[NUMBER,22]
3 - ROWNUM[8]
4 - LEVEL[4]
6 - "T2"."VAL"[NUMBER,22]
7 - ROWNUM[8]
8 - LEVEL[4]
50 rows selected.
--//仔细看执行计划显示形成view，然后做hash join。按照道理怎么会多1秒呢？
--//如果在toad下执行就会发现显示的是12秒，为什么呢？这与sqlplus的fetch有关，缺省ROWPREFETCH=1，
--//一般fetch的数量是1，arraysize，arraysize，...剩下部分小于arraysize。
--//这个参数仅仅12c以上的sqlplus版本可以修改。
SCOTT@book01p> set rowprefetch 2
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1,
( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t2
WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:14.13
SCOTT@book01p> set rowprefetch 3
SCOTT@book01p> /
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:15.09
SCOTT@book01p> set rowprefetch 4
SCOTT@book01p> /
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:12.06
--//画一个表格：
rowprefetch 执行时间
----------------------
1 13
2 14
3 15
4 12
----------------------
--//set rowprefetch 2 做一个10046跟踪，结果如下：
$ grep "lock time" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3832_0001.trc
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 1003922 duration=0 p2=0 p3=0 obj#=24401 tim=4599768595
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2005582 duration=0 p2=0 p3=0 obj#=24401 tim=4601774372
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 3005814 duration=0 p2=0 p3=0 obj#=24401 tim=4604780368
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 1013875 duration=0 p2=0 p3=0 obj#=24401 tim=4605794487
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2100977 duration=0 p2=0 p3=0 obj#=24401 tim=4607895631
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2006217 duration=0 p2=0 p3=0 obj#=24401 tim=4609902047
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 3019542 duration=0 p2=0 p3=0 obj#=24401 tim=4612923536
--//跟踪内容如下：
*** 2024-10-04T16:25:21.864147+08:00 (BOOK01P(3))
WAIT #140437728019360: nam='SQL*Net message from client' ela= 1098883 driver id=1413697536 #bytes=1 p3=0 obj#=24401 tim=4598763528
CLOSE #140437728019360:c=9,e=9,dep=0,type=1,tim=4598763661
=====================
PARSING IN CURSOR #140437727524480 len=178 dep=0 uid=109 oct=3 lid=109 tim=4598763876 hv=109321450 ad='702ce860' sqlid='0u8agsn38877a'
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1,
( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t2
WHERE t1.val = t2.val
END OF STMT
PARSE #140437727524480:c=165,e=164,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=155859586,tim=4598763874
EXEC #140437727524480:c=77,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=155859586,tim=4598764061
WAIT #140437727524480: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=24401 tim=4598764141
*** 2024-10-04T16:25:22.869210+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 1003922 duration=0 p2=0 p3=0 obj#=24401 tim=4599768595
*** 2024-10-04T16:25:24.875003+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2005582 duration=0 p2=0 p3=0 obj#=24401 tim=4601774372
*** 2024-10-04T16:25:27.880989+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 3005814 duration=0 p2=0 p3=0 obj#=24401 tim=4604780368
*** 2024-10-04T16:25:28.895107+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 1013875 duration=0 p2=0 p3=0 obj#=24401 tim=4605794487
*** 2024-10-04T16:25:30.996254+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2100977 duration=0 p2=0 p3=0 obj#=24401 tim=4607895631
FETCH #140437727524480:c=1653,e=9131571,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=1,plh=155859586,tim=4607895763
--//r=2.
*** 2024-10-04T16:25:33.002666+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 2006217 duration=0 p2=0 p3=0 obj#=24401 tim=4609902047
WAIT #140437727524480: nam='SQL*Net message from client' ela= 1585 driver id=1413697536 #bytes=1 p3=0 obj#=24401 tim=4609903841
--//无法解析为什么重新执行sleep(2).视乎总是fetch的数量到达arraysize时重新读取最后1条。
*** 2024-10-04T16:25:36.024159+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='PL/SQL lock timer' ela= 3019542 duration=0 p2=0 p3=0 obj#=24401 tim=4612923536
WAIT #140437727524480: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=24401 tim=4612923661
FETCH #140437727524480:c=435,e=3019843,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=155859586,tim=4612923753
--//r=1.
STAT #140437727524480 id=1 cnt=3 pid=0 pos=1 obj=0 op='HASH JOIN (cr=0 pr=0 pw=0 str=1 time=12151372 us cost=4 size=26 card=1)'
STAT #140437727524480 id=2 cnt=3 pid=1 pos=1 obj=0 op='VIEW (cr=0 pr=0 pw=0 str=1 time=6015966 us cost=2 size=13 card=1)'
STAT #140437727524480 id=3 cnt=3 pid=2 pos=1 obj=0 op='COUNT (cr=0 pr=0 pw=0 str=1 time=67 us)'
STAT #140437727524480 id=4 cnt=3 pid=3 pos=1 obj=0 op='CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 str=1 time=60 us)'
STAT #140437727524480 id=5 cnt=1 pid=4 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 str=1 time=2 us cost=2 size=0 card=1)'
STAT #140437727524480 id=6 cnt=3 pid=1 pos=2 obj=0 op='VIEW (cr=0 pr=0 pw=0 str=1 time=6134942 us cost=2 size=13 card=1)'
STAT #140437727524480 id=7 cnt=3 pid=6 pos=1 obj=0 op='COUNT (cr=0 pr=0 pw=0 str=1 time=54 us)'
STAT #140437727524480 id=8 cnt=3 pid=7 pos=1 obj=0 op='CONNECT BY WITHOUT FILTERING (cr=0 pr=0 pw=0 str=1 time=46 us)'
STAT #140437727524480 id=9 cnt=1 pid=8 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 str=1 time=1 us cost=2 size=0 card=1)'
*** 2024-10-04T16:25:41.639727+08:00 (BOOK01P(3))
WAIT #140437727524480: nam='SQL*Net message from client' ela= 5614581 driver id=1413697536 #bytes=1 p3=0 obj#=24401 tim=4618539112
CLOSE #140437727524480:c=46,e=45,dep=0,type=0,tim=4618539290
PARSE #140437730665600:c=8,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=4618539361
EXEC #140437730665600:c=381,e=381,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=4618539770
SCOTT@book01p> set arraysize 2
SCOTT@book01p> set rowprefetch 1
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1,
( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t2
WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:16.07
$ grep "lock time" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3832_0002.trc
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 1007989 duration=0 p2=0 p3=0 obj#=-1 tim=5365884132
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 2007088 duration=0 p2=0 p3=0 obj#=-1 tim=5367891438
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 3004928 duration=0 p2=0 p3=0 obj#=-1 tim=5370896531
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 1028788 duration=0 p2=0 p3=0 obj#=-1 tim=5371925572
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 1001489 duration=0 p2=0 p3=0 obj#=-1 tim=5372927420
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 2000780 duration=0 p2=0 p3=0 obj#=-1 tim=5374930090
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 3007603 duration=0 p2=0 p3=0 obj#=-1 tim=5377937946
WAIT #140437725180264: nam='PL/SQL lock timer' ela= 3002644 duration=0 p2=0 p3=0 obj#=-1 tim=5380940882
SCOTT@book01p> set arraysize 2
SCOTT@book01p> set rowprefetch 1
SELECT * FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 6) t1,
( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 6) t2
WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2 --//停一下
3 3
4 4 --//停一下
5 5
6 6
6 rows selected.
Elapsed: 00:00:51.51
$ grep "lock time" /u01/app/oracle/diag/rdbms/book/book/trace/book_ora_3832_0003.trc
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 1003361 duration=0 p2=0 p3=0 obj#=-1 tim=5751379853
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 2004139 duration=0 p2=0 p3=0 obj#=-1 tim=5753384201
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 3012769 duration=0 p2=0 p3=0 obj#=-1 tim=5756397136
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 4003654 duration=0 p2=0 p3=0 obj#=-1 tim=5760400923
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 5011354 duration=0 p2=0 p3=0 obj#=-1 tim=5765412478
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 6012046 duration=0 p2=0 p3=0 obj#=-1 tim=5771424705
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 1025651 duration=0 p2=0 p3=0 obj#=-1 tim=5772450679
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 1006917 duration=0 p2=0 p3=0 obj#=-1 tim=5773458196
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 2006345 duration=0 p2=0 p3=0 obj#=-1 tim=5775466558
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 3002809 duration=0 p2=0 p3=0 obj#=-1 tim=5778469546
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 3002833 duration=0 p2=0 p3=0 obj#=-1 tim=5781472619
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 4011207 duration=0 p2=0 p3=0 obj#=-1 tim=5785484372
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 5000575 duration=0 p2=0 p3=0 obj#=-1 tim=5790485205
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 5372975 duration=0 p2=0 p3=0 obj#=-1 tim=5795858417
WAIT #140437729984976: nam='PL/SQL lock timer' ela= 6012395 duration=0 p2=0 p3=0 obj#=-1 tim=5801871454
--//那位能给出更好的解析。
--//我测试许多例子，只要第2个表含有sleep(ROWNUM)就会出现这样的情况。
--//补充1个例子：
SELECT
/*+
LEADING(@"SEL$8976F1A6" "TX"@"SEL$3" "T1"@"SEL$1" )
USE_HASH(@"SEL$8976F1A6" "T1"@"SEL$1" ) */
* FROM ( SELECT sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1,
( SELECT sleep(a) val FROM tx) t2
WHERE t1.val = t2.val;
VAL VAL
---------- ----------
1 1
2 2
3 3
Elapsed: 00:00:19.17
SCOTT@book01p> @ dpc '' projection,outline ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID 03nruuwk92tnk, child number 0
-------------------------------------
SELECT /*+ LEADING(@"SEL$8976F1A6" "TX"@"SEL$3" "T1"@"SEL$1" )
USE_HASH(@"SEL$8976F1A6" "T1"@"SEL$1" ) */ * FROM ( SELECT
sleep(ROWNUM) val FROM dual CONNECT BY LEVEL <= 3) t1, (
SELECT sleep(a) val FROM tx) t2 WHERE t1.val = t2.val
Plan hash value: 4252884107
-------------------------------------------------------------------------------------------------------------------------------------------------------------
| 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 | | | 5 (100)| | 3 |00:00:12.05 | 3 | | | |
|* 1 | HASH JOIN | | 1 | 1 | 16 | 5 (0)| 00:00:01 | 3 |00:00:12.05 | 3 | 2078K| 2078K| 945K (0)|
| 2 | TABLE ACCESS FULL | TX | 1 | 3 | 9 | 3 (0)| 00:00:01 | 3 |00:00:00.01 | 3 | | | |
| 3 | VIEW | | 1 | 1 | 13 | 2 (0)| 00:00:01 | 3 |00:00:06.02 | 0 | | | |
| 4 | COUNT | | 1 | | | | | 3 |00:00:00.01 | 0 | | | |
| 5 | CONNECT BY WITHOUT FILTERING| | 1 | | | | | 3 |00:00:00.01 | 0 | 2048 | 2048 | 2048 (0)|
| 6 | FAST DUAL | | 1 | 1 | | 2 (0)| 00:00:01 | 1 |00:00:00.01 | 0 | | | |
-------------------------------------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$8976F1A6
2 - SEL$8976F1A6 / "TX"@"SEL$3"
3 - SEL$2 / "T1"@"SEL$1"
4 - SEL$2
6 - SEL$2 / "DUAL"@"SEL$2"
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('21.1.0')
DB_VERSION('21.1.0')
ALL_ROWS
OUTLINE_LEAF(@"SEL$2")
OUTLINE_LEAF(@"SEL$8976F1A6")
MERGE(@"SEL$3" >"SEL$1")
OUTLINE(@"SEL$1")
OUTLINE(@"SEL$3")
FULL(@"SEL$8976F1A6" "TX"@"SEL$3")
NO_ACCESS(@"SEL$8976F1A6" "T1"@"SEL$1")
LEADING(@"SEL$8976F1A6" "TX"@"SEL$3" "T1"@"SEL$1")
USE_HASH(@"SEL$8976F1A6" "T1"@"SEL$1")
NO_CONNECT_BY_FILTERING(@"SEL$2")
CONNECT_BY_COMBINE_SW(@"SEL$2")
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("T1"."VAL"="SLEEP"("A"))
Column Projection Information (identified by operation id):
-----------------------------------------------------------
1 - (#keys=1) "T1"."VAL"[NUMBER,22], "A"[NUMBER,22]
2 - "A"[NUMBER,22]
3 - "T1"."VAL"[NUMBER,22]
4 - ROWNUM[8]
5 - LEVEL[4]
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 2
---------------------------------------------------------------------------
1 - SEL$8976F1A6
- LEADING(@"SEL$8976F1A6" "TX"@"SEL$3" "T1"@"SEL$1" )
1 - SEL$8976F1A6 / "T1"@"SEL$1"
- USE_HASH(@"SEL$8976F1A6" "T1"@"SEL$1" )
77 rows selected.
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3035704/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
