[20170426]漫长的测试时间.txt

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

--//唯一索引的情况下没有动态取样。这样问题自然消失。
--//我在想下次再给开发演示，故意不分析表看看，人为夸大不使用绑定变量的危害,^_^。不然开发真的不长记性,就是一群长不大的孩子.........