[20170426]漫长的测试时间.txt
--//昨天浏览一个blog,链接nimishgarg.blogspot.com/2015/11/plsql-tuning-bind-variables-and-execute.html
--//里面提到主要是绑定变量的问题,让我感到奇怪的是对方的测试时间:Elapsed: 00:27:15.55(在不使用绑定变量的情况下).
--//这个时间也太长了,我以前也做过了类似测试执行2万次sql语句大约10秒上下,这样对于他建立的测试例子最多在1分钟之内.
--//换1个想法，我们生产系统每秒的执行语句可以达到3000条(当然混合绑定与非绑定)，这样100000/3000=33.3秒，最多1分钟。
--//于是我决定重复测试看看.
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 table test_bind as select level col from dual connect by level <= 2e4;
create index test_indx on test_bind(col);
--//注建立2万行记录(作者1e6条记录),担心测试时间太长.
--//建立测试脚本:
$ cat b1.sql
set timing on
alter system flush shared_pool;
declare
a number;
begin
for i in 1 .. 2e4 loop
execute immediate 'select col from test_bind where col = ' || i into a;
end loop;
end;
/
set timing off
$ cat b2.sql
set timing on
alter system flush shared_pool;
declare
a number;
begin
for i in 1 .. 2e4 loop
execute immediate 'select col from test_bind where col = :i ' into a using i;
end loop;
end;
/
set timing off
--//注，我采用for 循环，实际上与他采用的算法相差不大。
2.测试:
SCOTT@book> @ b1.sql
System altered.
Elapsed: 00:00:00.14
PL/SQL procedure successfully completed.
Elapsed: 00:00:45.36
--//45*5=225秒,不知道作者如何27分钟。但是还是与我想像存在差距，我记得我以前测试1万条这样sql语句4秒上下，也就是我的测试应该在10秒完成，
--//而现在45秒，还是有点长。
SCOTT@book> @ b2.sql
System altered.
Elapsed: 00:00:00.14
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.59
--//而使用绑定变量不到1秒(放大5倍，5秒),对方也是5秒，基本一致。
3.再仔细看看,发现对方建立的索引不是唯一.难道是问题出在这里吗?
drop index test_indx;
create unique index test_indx on test_bind(col);
--//继续重复测试:
SCOTT@book> @ b1
System altered.
Elapsed: 00:00:00.12
PL/SQL procedure successfully completed.
Elapsed: 00:00:10.19
--//10秒。
4.问题似乎到这里可以定位问题在于索引的建立方式,再仔细想感觉不对,表仅仅一个字段,也就是生成的执行计划根本不会访问表,
虽然唯一索引与非唯一索引的差别是逻辑读相差1个,这样也就是相差2万个逻辑读,这些逻辑读目前的硬件1秒之内就可以访问完成,
何况我的测试是单用户测试.不存在latch争用问题.看看执行计划：
drop index test_indx;
create index test_indx on test_bind(col);
SCOTT@book> alter session set statistics_level =all ;
Session altered.
SCOTT@book> select col from test_bind where col=100;
COL
----------
100
SCOTT@book> @&r/dpc '' '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID bm4df1k084wcw, child number 0
-------------------------------------
select col from test_bind where col=100
Plan hash value: 4214624029
------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers |
------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 1 (100)| | 1 |00:00:00.01 | 3 |
|* 1 | INDEX RANGE SCAN| TEST_INDX | 1 | 1 | 13 | 1 (0)| 00:00:01 | 1 |00:00:00.01 | 3 |
------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / TEST_BIND@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("COL"=100)
Note
-----
- dynamic sampling used for this statement (level=2)
--//仔细看执行计划就明白了,问题出在作者没有分析表.在执行过程中存在动态取样.
--//退出在登陆，避免statistics_level =all 影响。
SCOTT@book> show parameter sampling
NAME TYPE VALUE
-------------------------- -------- ------
optimizer_dynamic_sampling integer 2
SCOTT@book> alter session set optimizer_dynamic_sampling=0;
Session altered.
SCOTT@book> @ b1
System altered.
Elapsed: 00:00:00.16
PL/SQL procedure successfully completed.
Elapsed: 00:00:10.13
--//可以发现关闭动态取样，现在恢复到10秒。
--//重新分析表再测试:
execute sys.dbms_stats.gather_table_stats ( OwnName => nvl('',user),TabName => 'test_bind',Estimate_Percent => NULL,Method_Opt => 'FOR ALL COLUMNS SIZE 1 ',Cascade => True ,No_Invalidate => false);
SCOTT@book> show parameter sampling
NAME TYPE VALUE
-------------------------- -------- -----
optimizer_dynamic_sampling integer 2
SCOTT@book> @b1
System altered.
Elapsed: 00:00:00.16
PL/SQL procedure successfully completed.
Elapsed: 00:00:10.06
--//可以发现如果没有动态分析，执行都是在10秒完成，换一句话如果执行对方的测试，在99999次循环的情况下，最多1分钟完成任务。
SCOTT@book> execute sys.dbms_stats.delete_table_stats (ownname=> user ,tabname=> 'test_bind',cascade_columns=> true,cascade_indexes=> true,cascade_parts=>true,no_invalidate=> false)
PL/SQL procedure successfully completed.
--//附上存在动态取样的perf top输出:
# perf top -k /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
PerfTop: 1219 irqs/sec kernel:16.1% exact: 0.0% [1000Hz cycles], (all, 24 CPUs)
---------------------------------------------------------------------------------------------------------
samples pcnt function DSO
_______ _____ ____________________________ ____________________________________________________
2723.00 21.3% evadcd /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
2259.00 17.6% qesaFastAggNonDistSS /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
2144.00 16.7% lnxsum /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
764.00 6.0% kdstf00001010000km /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
669.00 5.2% kaf4reasrp0km /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
--//分析表之后的perf top输出:
# perf top -k /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
PerfTop: 1057 irqs/sec kernel:15.9% exact: 0.0% [1000Hz cycles], (all, 24 CPUs)
---------------------------------------------------------------------------------------------------------
samples pcnt function DSO
_______ _____ ____________________________ ____________________________________________________
243.00 4.3% kghalf /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
241.00 4.2% qksbgGetVal /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
209.00 3.7% __intel_new_memset /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
169.00 3.0% qksbgGetAltered /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
119.00 2.1% kghfnd /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
113.00 2.0% kghalo /u01/app/oracle/product/11.2.0.4/dbhome_1/bin/oracle
--//可以发现动态取样大量调用evadcd，lnxsum内部函数。
5.你也许要问为什么建立唯一索引后问题消失呢?
--//实际上建立唯一索引后,执行计划不在动态取样,这样消耗缺少了动态取样部分,问题也随之消失.
SCOTT@book> execute sys.dbms_stats.delete_table_stats (ownname=> user ,tabname=> 'test_bind',cascade_columns=> true,cascade_indexes=> true,cascade_parts=>true,no_invalidate=> false)
PL/SQL procedure successfully completed.
SCOTT@book> drop index test_indx;
Index dropped.
SCOTT@book> create unique index test_indx on test_bind(col);
Index created.
SCOTT@book> alter session set statistics_level =all ;
Session altered.
SCOTT@book> select col from test_bind where col=100;
COL
----------
100
SCOTT@book> @ &r/dpc '' ''
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID bm4df1k084wcw, child number 0
-------------------------------------
select col from test_bind where col=100
Plan hash value: 1159737204
----------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads |
----------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 1 (100)| | 1 |00:00:00.01 | 2 | 4 |
|* 1 | INDEX UNIQUE SCAN| TEST_INDX | 1 | 1 | 13 | 1 (0)| 00:00:01 | 1 |00:00:00.01 | 2 | 4 |
----------------------------------------------------------------------------------------------------------------------------------
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
1 - SEL$1 / TEST_BIND@SEL$1
Predicate Information (identified by operation id):
---------------------------------------------------
1 - access("COL"=100)
23 rows selected.
--//唯一索引的情况下没有动态取样。这样问题自然消失。
--//我在想下次再给开发演示，故意不分析表看看，人为夸大不使用绑定变量的危害,^_^。不然开发真的不长记性,就是一群长不大的孩子.........