本文共 8154 字，大约阅读时间需要 27 分钟。
[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 Productioncreate 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 ---------- 100SCOTT@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 2SCOTT@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 2SCOTT@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/oraclePerfTop: 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 ---------- 100SCOTT@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.--//唯一索引的情况下没有动态取样。这样问题自然消失。
--//我在想下次再给开发演示，故意不分析表看看，人为夸大不使用绑定变量的危害,^_^。不然开发真的不长记性,就是一群长不大的孩子.........转载地址：http://onjio.baihongyu.com/