[20200326]为什么选择这个索引.txt
--//昨天例行检查遇到执行缓慢的阿问题，首先写了2篇说明我遇到的情况。链接如下：
http://blog.itpub.net/267265/viewspace-2682613/=>[20200326]绑定变量抓取与NULL值.txt
http://blog.itpub.net/267265/viewspace-2682615/=>[20200326]dbms_monitor跟踪与SQL语句分析.txt
1.环境：
SYS@ZZZZ/dbcn> @ 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@ZZZZ/dbcn> @ tpt/sqlid b5nnkbvnzh7dg ''
Show SQL text, child cursors and execution stats for SQLID b5nnkbvnzh7dg child nvl('','%')
HASH_VALUE PLAN_HASH_VALUE CH# SQL_TEXT
------------ --------------- ---- ------------------------------------------------------------------------------------------------------------------------------------------------------
3925351855 1911168271 0 select * from xxxxxx_yyy.emr_bl_bl01 where bllb = :"SYS_B_0" and mblb = :"SYS_B_1" and jzhm = :"SYS_B_2" and WCSJ < to_date(:"SYS_B_3", :"SYS_B_4")
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED ROWS_PER_FETCH CPU_SEC CPU_SEC_EXEC ELA_SEC ELA_SEC_EXEC LIOS LIOS_EXEC PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ------------ ------------ ------------ ------------ ------------ -------------- -------------- ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ---------------
0 000000063A9A7368 00000001491AE400 1911168271 19451 1 19451 19450 1059 .05444730077 83028.197755 4.2685824767 83343.522597 4.2847937174 2860971145 147086.06987 70164 0 1
--//平均每次执行需要4秒。实际上有问题的语句执行要8秒。
--//查看执行计划如下：
Plan hash value: 1911168271
------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID| EMR_BL_BL01 | 1 | 141 | 2 (0)| 00:00:01 | | | |
|* 2 | INDEX RANGE SCAN | I_EMR_BL_BL01_WCSJ | 1 | | 2 (0)| 00:00:01 | 1025K| 1025K| |
------------------------------------------------------------------------------------------------------------------------------
SYS@ZZZZ/dbcn> @ bind_cap b5nnkbvnzh7dg ''
C200
---------------------------------------------------------------------------------------------------------------------------------------------------
select * from xxxxxx_yyy.emr_bl_bl01 where bllb = :"SYS_B_0" and mblb = :"SYS_B_1" and jzhm = :"SYS_B_2" and WCSJ < to_date(:"SYS_B_3", :"SYS_B_4")
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- -------- -------- ---------- ------------------- --------------- ---------------------
b5nnkbvnzh7dg 0 YES :SYS_B_0 1 22 2020-03-25 11:45:25 NUMBER 294
YES :SYS_B_1 2 22 2020-03-25 11:45:25 NUMBER 2000201
YES :SYS_B_2 3 32 2020-03-25 11:45:25 VARCHAR2(32) 571387
YES :SYS_B_3 4 32 2020-03-25 11:45:25 VARCHAR2(32) 2020/3/13 23:34:31
YES :SYS_B_4 5 32 2020-03-25 11:45:25 VARCHAR2(32) yyyy-mm-dd hh24:mi:ss
--//很明显选择错误索引,应该选择jzhm索引。而选择日期字段WCSJ这样几乎扫描整个索引在回表，这样逻辑读异常高。
--//我第1个猜测可能查询日期有误，比如输入的是'0020/03/ ...'之类的日期，正好重新分析，导致oracle认为这个日期范围的值很少
--//，导致选择错误的索引。我也没有多想重新分析表，可是问题依旧。我利用我写的脚本带入以上参数，是很好的选择jzhm索引的。
--//再次查看抓取的绑定变量值：
SYS@ZZZZ/dbcn> @ bind_cap b5nnkbvnzh7dg ''
C200
---------------------------------------------------------------------------------------------------------------------------------------------------
select * from xxxxxx_yyy.emr_bl_bl01 where bllb = :"SYS_B_0" and mblb = :"SYS_B_1" and jzhm = :"SYS_B_2" and WCSJ < to_date(:"SYS_B_3", :"SYS_B_4")
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- --------- -------- ---------- ------------------- --------------- ----------------------
b5nnkbvnzh7dg 0 YES :SYS_B_0 1 22 2020-03-25 12:28:21 NUMBER 294
YES :SYS_B_1 2 22 2020-03-25 12:28:21 NUMBER 2000201
YES :SYS_B_2 3 32 2020-03-25 12:28:21 VARCHAR2(32) 565759
YES :SYS_B_3 4 32 2020-03-25 12:28:21 VARCHAR2(32) NULL
YES :SYS_B_4 5 32 2020-03-25 12:28:21 VARCHAR2(32) yyyy-mm-dd hh24:mi:ss
--//恩!! :SYS_B_3 ='NULL',什么回事.我想当然认为开发:"SYS_B_3"初始值是NULL字符串，实际上NULL值，参考链接里面
--//http://blog.itpub.net/267265/viewspace-2682613/=>[20200326]绑定变量抓取与NULL值.txt
--//而且很明显我带入'NULL'字符串，结果报错，我自己也没注意，但是执行计划确实选择好的执行计划。
--//这样我开始考虑跟踪会话执行的sql语句获取绑定变量值。
3.跟踪会话执行的sql语句：
--//通过select * from V$OPEN_CURSOR where sql_id='b5nnkbvnzh7dg'确定会话sid。
exec dbms_monitor.session_trace_enable(session_id => 4221,serial_num => 1769 , waits => true , binds => true);
--//等40秒，执行如下：
exec dbms_monitor.session_trace_disable(session_id => 4221,serial_num => 1769);
--//结果遇到奇葩的事情，我跟踪执行计划变好，取消跟踪执行计划变坏。
--//参考连接：http://blog.itpub.net/267265/viewspace-2682615/=>[20200326]dbms_monitor跟踪与SQL语句分析.txt
--//实际上当我跟踪时语句开始时都要重分析，而第一次:"SYS_B_3"是非NULL的。这样正好选择好的执行计划，取消跟踪执行计划变坏。
--//当然通过抓取绑定变量值知道带入值确实有是NULL的情况：
BINDS #140345468516232:
Bind#0
oacdty=02 mxl=22(03) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=12f5168128 bln=22 avl=03 flg=09
value=294
Bind#1
oacdty=02 mxl=22(05) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=00 csi=00 siz=24 off=0
kxsbbbfp=25d56eb28 bln=22 avl=05 flg=09
value=2000201
Bind#2
oacdty=01 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0100 frm=01 csi=852 siz=32 off=0
kxsbbbfp=5f41627f8 bln=32 avl=06 flg=09
value="565759"
Bind#3
oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0300 frm=01 csi=852 siz=32 off=0
kxsbbbfp=00000000 bln=32 avl=00 flg=09
--//abl=00,长度是0.没有值。
Bind#4
oacdty=01 mxl=32(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=10 fl2=0300 frm=01 csi=852 siz=32 off=0
kxsbbbfp=12ff9f3a90 bln=32 avl=21 flg=09
value="yyyy-mm-dd hh24:mi:ss"
4.我生成一个脚本验证这个问题：
$ cat b5nnkbvnzh7dg.sql6
variable SYS_B_0 NUMBER
variable SYS_B_1 NUMBER
variable SYS_B_2 VARCHAR2(32)
variable SYS_B_3 VARCHAR2(32)
variable SYS_B_4 VARCHAR2(32)
begin
:SYS_B_0 := 294;
:SYS_B_1 := 2000201;
:SYS_B_2 := '560128';
:SYS_B_3 := NULL;
--//:SYS_B_3 := 'NULL';
--//:SYS_B_3 := '2020-03-27 10:00:00';
:SYS_B_4 := 'yyyy-mm-dd hh24:mi:ss';
end;
/
set termout off
set sqlblanklines on
alter session set current_schema=xxxxxx_yyy;
--//alter session set statistics_level=all;
Select * from xxxxxx_yyy.emr_bl_bl01 where bllb = :"SYS_B_0" and mblb = :"SYS_B_1" and jzhm = :"SYS_B_2" and WCSJ < to_date(:"SYS_B_3", :"SYS_B_4");
set termout on
set sqlblanklines off
@dpc '' ''
rollback;
--//每次使用不同的:SYS_B_3,都要修改sql语句，我一般习惯把select逐步换成SELECT。每次更改1个字符，主要目的是每次都要硬分析。
--//使用 :SYS_B_3 := NULL;
SYS@ZZZZ/dbcn> @ b5nnkbvnzh7dg.sql6
PL/SQL procedure successfully completed.
Plan hash value: 1911168271
------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID| EMR_BL_BL01 | 1 | 150 | 2 (0)| 00:00:01 | | | |
|* 2 | INDEX RANGE SCAN | I_EMR_BL_BL01_WCSJ | 1 | | 2 (0)| 00:00:01 | 1025K| 1025K| |
------------------------------------------------------------------------------------------------------------------------------
--//带入NULL使用错误索引。
--//使用 :SYS_B_3 := 'NULL';
Plan hash value: 3458316953
----------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | E-Rows |E-Bytes| Cost (%CPU)| E-Time | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 5 (100)| | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID| EMR_BL_BL01 | 1 | 150 | 5 (0)| 00:00:01 | | | |
|* 2 | INDEX RANGE SCAN | I_EMR_BL_BL01_JZHM_BLLB_MBLB | 2 | | 3 (0)| 00:00:01 | 1025K| 1025K| |
----------------------------------------------------------------------------------------------------------------------------------------
--//带入'NULL'字符串使用索引正确。实际上如果你注解set termout off，就会发现如下错误。
*
ERROR at line 1:
ORA-01841: (full) year must be between -4713 and +9999, and not be 0
--//顺便再现问题：
--//首先使用 :SYS_B_3 := NULL，生成坏执行计划，然后换成:SYS_B_3 := '2020-03-27 10:00:00';这样问题再现：
Plan hash value: 1911168271
-------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | OMem | 1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 2 (100)| | 0 |00:00:00.01 | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID| EMR_BL_BL01 | 1 | 1 | 150 | 2 (0)| 00:00:01 | 0 |00:00:00.01 | | | |
|* 2 | INDEX RANGE SCAN | I_EMR_BL_BL01_WCSJ | 1 | 1 | | 2 (0)| 00:00:01 | 0 |00:00:00.01 | 1025K| 1025K| |
-------------------------------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1911168271
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 2 (100)| | 3 |00:01:06.62 | 8436K| 36785 | | | |
|* 1 | TABLE ACCESS BY INDEX ROWID| EMR_BL_BL01 | 1 | 1 | 150 | 2 (0)| 00:00:01 | 3 |00:01:06.62 | 8436K| 36785 | | | |
|* 2 | INDEX RANGE SCAN | I_EMR_BL_BL01_WCSJ | 1 | 1 | | 2 (0)| 00:00:01 | 8795K|00:00:16.87 | 38954 | 36785 | 1025K| 1025K| |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
5.看看awr报表：
--//结束时间当天的18:00之前的统计：
SYS@ZZZZ/dbcn> @ tpt/ash/ash_wait_chains username||':'||event2 "sql_id='b5nnkbvnzh7dg'" trunc(sysdate) trunc(sysdate)+1
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- ----------------------------------------------
100% 47589 .6 -> xxxxxx_yyy:ON CPU
0% 25 0 -> xxxxxx_yyy:gc current block 2-way
0% 17 0 -> xxxxxx_yyy:cell single block physical read
0% 5 0 -> xxxxxx_yyy:gc cr block 2-way
0% 1 0 -> xxxxxx_yyy:gc cr request
--//看看执行这条语句花的时间是47589/3600 = 13.22小时，这样的团队失望，只能说明我们服务器超级强劲，真正的先进工作者^_^。
--//今天再统计昨天的情况，注意使用dash_wait_chains脚本，访问的视图不一样，统计误差有点大。
SYS@ZZZZ/dbcn> @ tpt/ash/dash_wait_chains username||':'||event2 "sql_id='b5nnkbvnzh7dg'" trunc(sysdate-1) trunc(sysdate)
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- ---------------------------------------------
100% 56450 .7 -> xxxxxx_yyy:ON CPU
0% 30 0 -> xxxxxx_yyy:gc current block 2-way
0% 10 0 -> xxxxxx_yyy:cell single block physical read
--//今天的统计：
SYS@ZZZZ/dbcn> @ tpt/ash/ash_wait_chains username||':'||event2 "sql_id='b5nnkbvnzh7dg'" trunc(sysdate) trunc(sysdate)+1
-- Display ASH Wait Chain Signatures script v0.2 BETA by Tanel Poder ( http://blog.tanelpoder.com )
%This SECONDS AAS WAIT_CHAIN
------ ---------- ---------- --------------------------------
98% 44 0 -> xxxxxx_yyy:ON CPU
2% 1 0 -> xxxxxx_yyy:gc cr block 2-way
--//到现在11点仅仅使用45秒。
6.补充如何更正：
--//最佳的方式叫开发修改代码，规避带入NULL这个错误。我看开发的工作效率往往遥遥无期....
--//我最后使用sql profile稳定执行计划，这样比较保险。我现在基本按照第三方运维的方式解决这类问题。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-2682641/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [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
