[20241004]为什么这么慢.txt

来源:这里教程网 时间:2026-03-03 20:41:13 作者:

[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.

相关推荐