一次有意思的错选执行计划问题定位(涉及SYS_OP_C2)

2021-12-12 00:21:31

这两天和广分的兄弟看了一个问题，比较有意思，过程也比较曲折。。。


问题现象：

1. 11g的库，话说有一个应用程序新上线，应用中使用了绑定变量的方式执行一条简单的SQL，例如select a from b where c = :x，c列是该表复合主键的前导列，表定义是varchar2类型，从spotlight监控看这条SQL的执行计划是全表扫描，一次执行要1个小时，这张表是运行很久的引用分区表，数据量是亿级，测试的时候正常，但很显然测试的数据量可能和生产非常不一致，导致没察觉。

2. 在sqlplus中手工执行SQL，变量使用字面值，例如select a from b where c = 'abc'，执行的非常快，查看执行计划，是用的索引范围扫描。


初步怀疑：

1. 对如此数据量的一张表，理应使用索引，但应用程序未使用索引，用的全表扫描，手工执行SQL时却可以用到索引，那么问题就在于为什么对于应用程序，Oracle选择了全表扫描的执行计划，而不是索引？


开始时的几种猜测：

1. 是否该表上线时有大量的数据变更，对执行计划产生影响，且未到达夜维统计信息收集的时间，造成因统计信息不准导致错误执行计划的可能？

> 经询问，确认上线时未有大量数据的变更，且上线后手工收集过统计信息。这种猜测不对。


2. 是否因为使用不同的查询条件会有不同的执行计划，由于绑定变量窥探的影响，导致采用了错误的执行计划？进一步解释猜测，例如第一次执行应用程序时，使用的条件值对应的执行计划是全表扫描，由于使用绑定变量窥探的作用，又由于应用使用了绑定变量，接下来的每次执行都会采用全表扫描，除非shared_pool被清空或对该表有DDL操作，才会重新硬解析，有可能采用另外的执行计划，这是绑定变量窥探的副作用。

> 因为他用的是引用分区，符合条件的记录在主表如果是存储于多个分区中，是否Oracle认为全表扫描效率高，如果存储于很少的分区，Oracle认为索引扫描效率高？

证明上述猜测的依据，就是无论哪种方式执行，应用程序或sqlplus，执行计划都是全表扫描，但实际是sqlplus执行SQL时并没有采用全表扫描，用的是索引范围扫描。这种猜测不对。


3. 是不是索引设置为了invisible？

> invisible是11g的新特性，允许设置索引为invisible，效果是DML操作仍会维护索引，但优化器会忽略索引的存在，除非设置参数optimizer_use_invisible_indexes，否则即使使用该索引字段，也不会使用索引。

但和问题2相同，使用sqlplus时会使用索引扫描，不可能应用程序执行时会临时设置该参数，因为这参数是系统级的，不是session级的，需要重启数据库生效，这不是应用程序能做的，而且也没有任何理由需要由应用程序来做这个操作。这种猜测不对。


究竟为什么应用程序运行时，这个SQL使用了全表扫描，但sqlplus执行SQL时却用的索引范围扫描呢？

越来越邪乎了。。。

但哲学观点证明，因果关联，肯定有某种因素让Oracle对不同场景使用了不同的执行计划，就像@dbsnake所说的，90%的Oracle问题都是SQL的书写不正确导致的，前两天有幸听了RWP中国巡讲，Tom同样提到了这点，不是Oracle做错了，而是你可能给Oracle的某些错误信息，让其出现了这种错误。


如何进一步证明？

首先跑了一个10046，第一次反馈没看出什么问题。

接着跑一个sqlplus下执行SQL的10053，发现优化器选择的就是索引范围扫描，其成本值最低，而全表扫描的成本值如下：

无论如何，是不会选择全表扫描的啊？

其实开始的时候并没有第一时间反应过来，一条SQL语句，Oracle计算的成本中索引范围扫描最优，但应用程序运行时没有用，而是用的全表扫描，排除上面几种猜测后，剩下的可能不多了。其实问题已经缩小到为什么应用程序执行的SQL索引失效了？

经过进一步排查，发现应用程序中对查询条件变量使用了OracleDbType.NVarchar2的定义，但实际字段类型是VARCHAR2，即where VARCHAR2 = NVARCHAR2，那么是否因为这种类型不匹配，造成做了隐式转换，导致索引失效？可能用过NVARCHAR2的朋友就已经发现问题了，由于以前基本没用过这种类型，所以只是怀疑，需要验证。


实验：

1. 定义了一张测试表，定义NVARCHAR2类型的变量，模拟应用程序。

SQL> create table t_n as select * from dba_objects;

Table created.

SQL> create index idx_t_n on t_n (object_name);

Index created.

SQL> var x nvarchar2(128);
SQL> exec :x := 'ABC';

PL/SQL procedure successfully completed.

2. 首先使用explain plan for查看执行计划

SQL> explain plan for select count(*) from t_n where object_name = :x;

Explained.

SQL> select * from table(dbms_xplan.display());

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 3062759669

-----------------------------------------------------------------------------
| Id  | Operation	  | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |	    |	  1 |	 66 |	  3   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE   |	    |	  1 |	 66 |		 |	    |
|*  2 |   INDEX RANGE SCAN| IDX_T_N |	722 | 47652 |	  3   (0)| 00:00:01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
---------------------------------------------------

   2 - access("OBJECT_NAME"=:X)

Note
-----
   - dynamic sampling used for this statement (level=2)

18 rows selected.
发现是用的索引范围扫描啊，没有任何问题？？？


3. explain plan for方式得到的执行计划有可能是不准的，@dbsnake的书中有详细介绍，那么看看display_cursor方式得到的执行计划有不同

SQL> select count(*) from t_n where object_name = :x;

  COUNT(*)
----------
	 1

SQL> select sql_text,sql_id,version_count from v$sqlarea where sql_text like 'select count(*) from t_n where object_name%';

SQL_TEXT
--------------------------------------------------------------------------------
SQL_ID	      VERSION_COUNT
------------- -------------
select count(*) from t_n where object_name = :x
630ztwp0w2b6f		  1

SQL> select * from table(dbms_xplan.display_cursor('630ztwp0w2b6f',0,'advanced'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID	630ztwp0w2b6f, child number 0
-------------------------------------
select count(*) from t_n where object_name = :x

Plan hash value: 4075463224

---------------------------------------------------------------------------
| Id  | Operation	   | Name | Rows  | Bytes | Cost (%CPU)| Time	  |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |	  |	  |	  |   290 (100)|	  |
|   1 |  SORT AGGREGATE    |	  |	1 |    66 |	       |	  |

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
|*  2 |   TABLE ACCESS FULL| T_N  |    12 |   792 |   290   (1)| 00:00:04 |
---------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SEL$1
   2 - SEL$1 / T_N@SEL$1

Outline Data
-------------

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('11.2.0.1')
      DB_VERSION('11.2.0.1')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      FULL(@"SEL$1" "T_N"@"SEL$1")
      END_OUTLINE_DATA
  */

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

   1 - :X (NVARCHAR2(30), CSID=2000): 'ABC'

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(SYS_OP_C2C("OBJECT_NAME")=:X)


PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Column Projection Information (identified by operation id):
-----------------------------------------------------------

   1 - (#keys=0) COUNT(*)[22]

Note
-----
   - dynamic sampling used for this statement (level=2)


53 rows selected.
看到不同了。。。

注意filter中显示SYS_OP_C2C("OBJECT_NAME")=:X，说明Oracle对左值使用了一个叫SYS_OP_C2C的函数，我们都知道这个常识，如果对索引字段使用了函数，那么是不会采用这个索引作为执行计划的，肯定是全表扫描。

看来问题是找到关键了，但还没完，这个SYS_OP_C2C是什么，为什么对VARCHAR2 = NVARCHAR2这种情况会调用这个函数？


首先搜到了MOS有篇文章SYS_OP_C2C Causing Full Table/Index Scans (文档 ID 732666.1)，简明扼要地说明了这个问题：

1) You are executing a query using bind variables.

2) The binding occurs via an application (eg. .NET, J2EE ) using a "string" variable to bind.

3) The query is incorrectly performing a full table/index scan instead of an unique/range index scan.  

4) When looking at advanced explain plan, sqltxplain or 10053 trace, you notice that the "Predicate Information" shows is doing a "filter(SYS_OP_C2C)".

e.g select * from table(dbms_xplan.display_cursor(&sql_id,null,'ADVANCED'));

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(SYS_OP_C2C("COL1")=:B1)            <=== filter operation occurring

CAUSE

The bind variable "string" is using a different datatype to the column that is being queried.  
This means that an implicit conversion of the data is required to execute the query.  SYS_OP_C2C is the implicit function which is used to convert the column between nchar and char.

SOLUTION

  1. Create a function based index on the column.

e.g create index <index_name> on <table_name> (SYS_OP_C2C(<column>));

OR
  2. Ensure that your bind "string" datatype and column datatype are the same.
      A java example where this can occurs is when defaultNChar=TRUE.  This will cause strings to bind as NVARCHAR2 causing the predicate that are subset datatypes to be converted to NVARCHAR2.
      e.g.    -Doracle.jdbc.defaultNChar=true
                <connection-property name="defaultNChar">true</connection-property>

说明的很是详细了，如果应用程序(例如.NET，Java)中使用了“string”的绑定变量，查询语句就会使用全表扫描/索引全扫描，不会使用到唯一索引扫描/索引范围扫描。使用advanced选项的explain plan或10053等方式才能发现这个问题。

原因就是“string”的绑定变量是使用了另外一种和查询列定义不同的数据类型。Oracle需要使用SYS_OP_C2C函数在NCHAR和CHAR类型之间做隐式转换。

解决方法：

1. 创建函数索引。

2. 确保应用程序中使用的“string”类型和列字段类型一致。


另外，杨长老对这个问题也有过说明(http://blog.itpub.net/4227/viewspace-531728/)。


后话是，开发同事之前没用过Oracle，写程序时不知怎的就用了NVARCHAR2的定义，且测试和生产环境不一致，才导致了这个在上线后才出现的问题。


总结：

1. 一个很小的字段定义，有可能造成意想不到的后果，说明了解Oracle一些基本原理的重要性，这里不仅指提到的字段类型。

2. 分析一个问题，要有正确的思路，要能抓到问题本质，像这个问题，就是不同方式执行同一条SQL，会有不同的执行计划，那么为什么Oracle选择了错误的执行计划？是有原因的，不是Oracle自己选择错了，更多情况是我们给他的信息错了，影响了其选择执行计划的准确性。如果能排除一些参数影响，定位到什么原因导致索引失效，进而查看列字段定义和应用程序中的字段类型定义，这个问题就可能更快的找到原因。这点还有待加强。

3. 要有分析的方法，这里10046、10053，包括display_cursor，都是可能找到问题的重要手段，一是要知道什么场景下使用这些工具，二是知道如何使用这些工具，像explain plan for得到的执行计划有可能是不准的，尤其在有绑定变量的情况，上述就论证了这点，关键看是否真正执行了这条SQL语句；还有就像使用display_cursor，前提是执行过这条SQL，并且执行计划仍在缓存中，通过v$sqlarea可以找到对应的SQLID，这都是基础。

4. 要细心，对于上述问题，可能从10046中就可以看到谓词条件带有隐式转换的线索，进而可以找到问题的真正原因，即使之前不知道SYS_OC_C2C，不知道NVARCHAR2和VARCHAR2之间的区别，也可以让我们有正确的认识。

5. 要能模拟出问题，像这里使用var x nvarchar2的方式，就是模拟了应用程序使用绑定变量的逻辑。

6. 自己需要提高的地方还很多，宽度深度都如此，加油。

上一篇：业内大佬怒喷Window 10 Cloud：最大的流氓软件！


下一篇：AndroidStudio 插件 之 Findbugs 安装与简单使用教程