[20210926]并行执行计划疑问.txt
--//问题来源于前几天看awr报表遇到的奇怪问题.
$ cat sqlh.sql
column BEGIN_INTERVAL_TIME format a24
column END_INTERVAL_TIME format a24
prompt @ sqlh sql_id [snap_id]
SELECT s.SNAP_ID
,s.instance_number
,s.PLAN_HASH_VALUE
,x.BEGIN_INTERVAL_TIME
,x.END_INTERVAL_TIME
,ELAPSED_TIME_DELTA
,CPU_TIME_DELTA
,EXECUTIONS_DELTA
,EXECUTIONS_TOTAL
,ROWS_PROCESSED_DELTA
,BUFFER_GETS_DELTA
,s.LOADED_VERSIONS
FROM DBA_HIST_SQLSTAT s, DBA_HIST_SNAPSHOT x
WHERE s.sql_id = '&&1'
AND s.snap_id = x.snap_id
AND s.instance_number = x.instance_number
AND s.snap_id >= nvl('&&2',0)
ORDER BY 1,2;
--//sql_id = 7ksrtc8rzpawc
SELECT a.object_name, c.sid,
CASE TO_CHAR(b.locked_mode)
WHEN '0' THEN 'NONE'
WHEN '1' THEN 'NULL'
WHEN '2' THEN 'ROW-S (RS)'
WHEN '3' THEN 'ROW-X (RX)'
WHEN '4' THEN 'SHARE (S)'
WHEN '5' THEN 'S/ROW-X (SRX)'
WHEN '6' THEN 'Exclusive (X)'
ELSE TO_CHAR(b.locked_mode)
END locked_mode, c.SERIAL#, b.process, c.program, c.SQL_ADDRESS
FROM all_objects a, sys.gv_$locked_object b, sys.GV_$SESSION C
WHERE a.object_id = b.object_id
AND b.process = c.process
ORDER BY a.object_name
$ rlsql -s -l <<< "@ sqlh 7ksrtc8rzpawc 60360" | awk '$10>=0 || $10='0'{ print $0}'
SNAP_ID INSTANCE_NUMBER PLAN_HASH_VALUE BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA BUFFER_GETS_DELTA LOADED_VERSIONS
60360 1 4164392588 2021-09-16 15:00:20.273 2021-09-16 16:00:27.666 17267146 16734456 12 9896 0 2846404 22
60360 1 3030673966 2021-09-16 15:00:20.273 2021-09-16 16:00:27.666 2497060 2323646 0 0 0 252 20
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
60361 1 3030673966 2021-09-16 16:00:27.666 2021-09-16 17:00:35.402 1244472 1042842 0 0 0 103 24
60361 1 4164392588 2021-09-16 16:00:27.666 2021-09-16 17:00:35.402 17467751 16113550 11 9907 0 2935098 25
60362 1 4164392588 2021-09-16 17:00:35.402 2021-09-16 18:00:42.710 17397997 16587478 12 9919 0 3610294 37
60362 1 3030673966 2021-09-16 17:00:35.402 2021-09-16 18:00:42.710 2771635 2699588 0 0 0 268 35
....
--//有点奇怪的是EXECUTIONS_DELTA=0,为什么ELAPSED_TIME_DELTA>0的情况出现.自己测试看看.
1.环境:
SYS@127.0.0.1:XXXX/yyyy> @ 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
2.测试:
SYS@127.0.0.1:XXXX/yyyy> select /*+ aaa1234 */ count(*) from gv_$session;
COUNT(*)
----------
9129
SYS@127.0.0.1:XXXX/yyyy> @ hash
HASH_VALUE SQL_ID CHILD_NUMBER HASH_HEX
---------- ------------- ------------ ---------
3330167945 47jvwgv37wp49 0 c67e5489
SYS@127.0.0.1:XXXX/yyyy> @ tpt/sql_id 47jvwgv37wp49 %
Show SQL text, child cursors and execution stats for SQLID 47jvwgv37wp49 child %
HASH_VALUE CH# SQL_TEXT
---------- ---- -----------------------------------------------
3330167945 0 select /*+ aaa1234 */ count(*) from gv_$session
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED CPU_MS ELA_MS LIOS PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------------
0 0000001305051800 0000001301B45EB0 1117094054 2 1 1 1 1 26.995 31.968 2 0 0 0
--//你可以发现执行1次.切换到另外的实例查看发现:
SYS@127.0.0.1:ZZZZ/dbcn> @ tpt/sql_id 47jvwgv37wp49 %
Show SQL text, child cursors and execution stats for SQLID 47jvwgv37wp49 child %
HASH_VALUE CH# SQL_TEXT
---------- ---- -----------------------------------------------
3330167945 0 select /*+ aaa1234 */ count(*) from gv_$session
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED CPU_MS ELA_MS LIOS PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------------
0 000000132CBFA450 00000000B93ED610 1117094054 1 1 0 0 0 6.999 6.531 2 0 0 0
--//可以发现执行次数0,而实际上CPU_MS,ELA_MS有值.这样查询sqlh.sql语句出现EXECUTIONS_DELTA=0,ELAPSED_TIME_DELTA>0的情况就不奇怪了.
3.继续:
SYS@127.0.0.1:XXXX/yyyy> select /*+ rule aaa1234 */ count(*) from gv$session;
COUNT(*)
----------
9138
SYS@127.0.0.1:XXXX/yyyy> @ hash
HASH_VALUE SQL_ID CHILD_NUMBER HASH_HEX
---------- ------------- ------------ ---------
3793980144 f2psczrj272rh 0 e2238af0
SYS@127.0.0.1:XXXX/yyyy> select /*+ rule aaa1234 */ count(*) from gv$session;
COUNT(*)
----------
9127
SYS@127.0.0.1:XXXX/yyyy> @ dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID f2psczrj272rh, child number 0
-------------------------------------
select /*+ rule aaa1234 */ count(*) from gv$session
Plan hash value: 3390655029
-------------------------------------------------------------------------------------------------------
| Id | Operation | Name | TQ |IN-OUT| PQ Distrib | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | | | | |
| 1 | SORT AGGREGATE | | | | | | | |
| 2 | PX COORDINATOR | | | | | | | |
| 3 | PX SEND QC (RANDOM) | :TQ10000 | Q1,00 | P->S | QC (RAND) | | | |
| 4 | VIEW | GV$SESSION | Q1,00 | PCWP | | | | |
| 5 | MERGE JOIN | | Q1,00 | PCWP | | | | |
| 6 | SORT JOIN | | Q1,00 | PCWP | | 372K| 372K| 330K (0)|
| 7 | MERGE JOIN | | Q1,00 | PCWP | | | | |
| 8 | SORT JOIN | | Q1,00 | PCWP | | 232K| 232K| 206K (0)|
| 9 | FIXED TABLE FULL| X$KSLWT | Q1,00 | PCWP | | | | |
|* 10 | SORT JOIN | | Q1,00 | PCWP | | 31744 | 31744 |28672 (0)|
| 11 | FIXED TABLE FULL| X$KSLED | Q1,00 | PCWP | | | | |
|* 12 | SORT JOIN | | Q1,00 | PCWP | | 267K| 267K| 237K (0)|
|* 13 | FIXED TABLE FULL | X$KSUSE | Q1,00 | PCWP | | | | |
-------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1
2 - SEL$2 / GV$SESSION@SEL$1
5 - SEL$2
9 - SEL$2 / W@SEL$2
11 - SEL$2 / E@SEL$2
13 - SEL$2 / S@SEL$2
Predicate Information (identified by operation id):
---------------------------------------------------
10 - access("W"."KSLWTEVT"="E"."INDX")
filter("W"."KSLWTEVT"="E"."INDX")
12 - access("S"."INDX"="W"."KSLWTSID")
filter("S"."INDX"="W"."KSLWTSID")
13 - filter((BITAND("S"."KSUSEFLG",1)<>0 AND BITAND("S"."KSSPAFLG",1)<>0))
Note
-----
- rule based optimizer used (consider using cbo)
- statement not queuable: gv$ statement
- Warning: basic plan statistics not available. These are only collected when:
* hint 'gather_plan_statistics' is used for the statement or
* parameter 'statistics_level' is set to 'ALL', at session or system level
SYS@127.0.0.1:XXXX/yyyy> @ tpt/sql_id f2psczrj272rh %
Show SQL text, child cursors and execution stats for SQLID f2psczrj272rh child %
HASH_VALUE CH# SQL_TEXT
---------- ---- ---------------------------------------------------
3793980144 0 select /*+ rule aaa1234 */ count(*) from gv$session
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED CPU_MS ELA_MS LIOS PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------------
0 00000001B57EFBE0 00000001B57F0648 3390655029 4 1 2 2 2 62.991 177.895 0 0 8 0
--//在另外的实例查询,实际上即使提示rule也是并行查询.
SYS@127.0.0.1:ZZZZ/dbcn> @ tpt/sql_id f2psczrj272rh %
Show SQL text, child cursors and execution stats for SQLID f2psczrj272rh child %
HASH_VALUE CH# SQL_TEXT
---------- ---- ---------------------------------------------------
3793980144 0 select /*+ rule aaa1234 */ count(*) from gv$session
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED CPU_MS ELA_MS LIOS PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------------
0 000000133C691C78 000000133C691B08 3390655029 2 1 0 0 0 14.998 15.475 0 0 8 0
--//从以上测试可以发现该语句出现EXECUTIONS_DELTA=0,ELAPSED_TIME_DELTA>0的情况就是正常的,