大量OPTIMIZER_MISMATCH引起的游标高版本,cursor:mutex s等待

data_data

这阵子时常出现cpu高负载，业务连不上。综合awr,发现系统负载过高，大量的parse，及cursor:mutex s 等待。
查询游标版本过高，定位为大量OPTIMIZER_MISMATCH=Y。
select * from (select count(*),sql_id from v$sql_shared_cursor where OPTIMIZER_MISMATCH='Y' group by sql_id order by 1 desc )where rownum<10;


  COUNT(*) SQL_ID
---------- ---------------------------------------
623 2nzyqa2j992dm         
556 d9jq7rbwg51ju            
43 18naypzfmabd6
30 8xgd2r1h0kr34
27 2q93zsrvbdw48
24 7ng34ruy5awxq
23 83taa7kaw59c1
22 5n1fs4m2n2y0r
22 gx4mv66pvj3xz


这些sql都是并发严重的业务主要sql，极其影响系统性能。

数据库版本：11.2.0.1
patch:12419378
请教，优化器模式引起的高版本是为何，一共就几种优化器模式而已啊？
可能的bug:
Bug 12976376  High VERSION_COUNT for SQL with binds, including recursive dictionary SQL - superseded但涉及版本没有包括11.2.0.1。
请大神帮忙，谢谢。

Maclean Liu(刘相兵

给出这个SQL  2nzyqa2j992dm          的文本

以及


select * from v$sql_optimizer_env where sql_id='2nzyqa2j992dm';

data_data

Maclean Liu(刘相兵 发表于 2014-9-28 10:30
给出这个SQL  2nzyqa2j992dm          的文本

以及

刘大，高版本之前我做了个操作之后目前是降下来了。这还是开发人员的坑，之后我发现应该是短链接和concurrent，引发的Bug 10351178  High version counts caused by auto tuned PGA memory 。之后修改连接方式，算是规避了这个问题。

data_data

Maclean Liu(刘相兵 发表于 2014-9-28 10:30
给出这个SQL  2nzyqa2j992dm          的文本

以及

补充
另外，这条sql文本：
insert into ag_login values(:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:9 ,:10 ,sysdate,:11 ,:12 ,:13 )
一个绑定变量的insert操作。

虽然解决了高版本的问题。但还存在高软解析，基本上parse=execution。
SQL> select parse_calls,executions from v$sqlarea where sql_id in ('d9jq7rbwg51ju','2nzyqa2j992dm');

PARSE_CALLS EXECUTIONS
----------- ----------
     693800        693804
     249032        249032
检查了session_cached_cursors=50,opens_cursors=300,默认值。
awr:
Parses:         14.6         1.8                  
Hard parses:         0.0         0.0
每秒10多个软解析。
--进一步查看执行的会话,截取近期执行部分，应该是11.2.0.1的bug，会话状态一直是inactive.
SQL> select sid||','||serial# id,last_call_et,logon_time,status,machine from v$session where sql_id in('d9jq7rbwg51ju','2nzyqa2j992dm') or prev_sql_id in('d9jq7rbwg51ju','2nzyqa2j992dm') order by 2,1,3,4;
ID         LAST_CALL_ET LOGON_TIME         STATUS         MACHINE
-------------------- ------------ ------------------------- ------------------------ --------------------
1,19 0 01-10月-2014 14:54:29 INACTIVE F-8-3
1428,134 0 03-10月-2014 16:43:43 INACTIVE F-8-3

--同时查看v$open_cursor游标的缓存，1，1428两个会话有缓存游标。
SQL> select SID,COUNT(*) from v$open_cursor where sql_id in ('d9jq7rbwg51ju','2nzyqa2j992dm') and cursor_type in('SESSION CURSOR CACHED','OPEN') GROUP BY SID order by sid;
       SID COUNT(*)
---------- ----------
        1         2
       192         1
       289         1
       477         2
       952         1
      1046         2
      1332         2
      1428         2
      1713         1
      1808         1
-----------------------------------------------------
我的诊断手段有限，请刘大帮忙支招。感谢！

Maclean Liu(刘相兵

对于短链接 而言 session_cached_cursors 的缓存游标是没有意义的，所以有软解析高很正常。

data_data

Maclean Liu(刘相兵 发表于 2014-10-3 18:26
对于短链接 而言 session_cached_cursors 的缓存游标是没有意义的，所以有软解析高很正常。 ...

是的。但问题是已经修改为长连接了，还是一执行一解析。测试中用sqlplus执行sql多次，会话保持连接，从另一会话中查询此sql的解析数也是一执行一解析。我想不出还有什么情况会这样，会不会是该版本的某个bug。版本为11.2.0.1.6

Maclean Liu(刘相兵

data_data 发表于 2014-10-3 22:27
是的。但问题是已经修改为长连接了，还是一执行一解析。测试中用sqlplus执行sql多次，会话保持连接，从另 ...

给出 支持你说法现象的AWR

data_data

没网络暂时给不了awr，慢些上传。现在正常情况下这个库负载是很低的。疑惑的是在长链接之下，几个参数设置正常之下，没有用到软软解析。

data_data

Maclean Liu(刘相兵 发表于 2014-10-3 22:39
给出 支持你说法现象的AWR

刘大，麻烦分析一下。截图是长链接模式运行一段时间后的sql解析。

Maclean Liu(刘相兵

        Snap Id        Snap Time        Sessions        Cursors/Session
Begin Snap:        234        26-9月 -14 17:00:11        322        4.7
End Snap:        235        26-9月 -14 18:00:15        339        4.7


总的session数目在330左右

Logons:        6.7        1.4                  

logon达到了 每秒6.7次，也就是 一分钟360次 ，我不认为这个 可以称为 长连接。

data_data

Maclean Liu(刘相兵 发表于 2014-10-12 20:46
Snap Id        Snap Time        Sessions        Cursors/Session
Begin Snap:        234        26-9月 -14 17:00:11        322        4.7
End Snap ...

你好!
可能某些应用仍然还是短链接的模式，但针对之前两条高版本的insert语句：d9jq7rbwg51ju，2nzyqa2j992dm，还是有采取长链接的或者至少有部分是采取长链接的，但针对share pool中两条sql的解析和执行数仍然是不正常的。论证如下：
SQL> select sid||','||serial# id,last_call_et,logon_time,status，sql_id,machine from v$session where sql_id in('d9jq7rbwg51ju','2nzyqa2j992dm') or prev_sql_id in('d9jq7rbwg51ju','2nzyqa2j992dm') order by 2,1,3,4;

ID                              LAST_CALL_ET LOGON_TIME                      STATUS                       SQL_ID                                       MACHINE
------------------------------ ------------ ------------------------- ------------------------ --------------------------------------- ------------------------------
1333,1452                                 0 11-10月-2014 11:57:04     INACTIVE                 d9jq7rbwg51ju                           jdbcclient
1239,44478                               49 11-10月-2014 11:57:04     INACTIVE                 d9jq7rbwg51ju                           jdbcclient
862,27                                88998 11-10月-2014 11:57:09     INACTIVE                 d9jq7rbwg51ju                           jdbcclient
1050,11266                            88999 11-10月-2014 11:57:09     INACTIVE                 d9jq7rbwg51ju                           jdbcclient
1523,5311                             88999 11-10月-2014 11:57:04     INACTIVE                 d9jq7rbwg51ju                           jdbcclient

LAST_CALL_ET列和logon_time列 说明10月11号建立的会话1239,44478和1333,1452，在0秒和49秒钟前是有执行sql_id=‘d9jq7rbwg51ju’的insert语句的
隔2分钟后再次执行

ID                               LAST_CALL_ET LOGON_TIME                      STATUS                       SQL_ID                                       MACHINE
------------------------------ ------------ ------------------------- ------------------------ --------------------------------------- ------------------------------
1239,44478                               1 11-10月-2014 11:57:04     INACTIVE                 2nzyqa2j992dm                           jdbcclient
1333,1452                                16 11-10月-2014 11:57:04     INACTIVE                 d9jq7rbwg51ju                           jdbcclient

仍然是1239,44478和1333,1452 这两个会话，1秒和66秒钟前分别执行了2nzyqa2j992dm和d9jq7rbwg51ju。
加上之前一段时间的观察，一般会有2个会话在保持较长时间的连接的基础上执行2nzyqa2j992dm和d9jq7rbwg51ju。

接下来查询这两条sql的解析数和执行数：

SQL> select sql_id,executions,parse_calls,version_count from v$sqlarea where sql_id in('d9jq7rbwg51ju','2nzyqa2j992dm');

SQL_ID                                        EXECUTIONS PARSE_CALLS VERSION_COUNT
--------------------------------------- ---------- ----------- -------------
d9jq7rbwg51ju                                   2612674     2612559                  12
2nzyqa2j992dm                                    854376        854372                  13


从结果上来看，至少这两条sql基本上是没有用上软软解析的（实例是长链接之后重启过的）。再次确认有关初始化参数：

SQL> show parameter session_cached_cursors

NAME                                     TYPE                               VALUE
------------------------------------ --------------------------------- ------------------------------
session_cached_cursors                     integer                               50


SQL> show parameter open_cursors

NAME                                     TYPE                               VALUE
------------------------------------ --------------------------------- ------------------------------
open_cursors                             integer                               300


不知道我这样的论证方式有没有问题。麻烦分析一下问题。谢谢刘大~

Maclean Liu(刘相兵

session_cached_cursors 也是过小的  

data_data

Maclean Liu(刘相兵 发表于 2014-10-13 13:10
session_cached_cursors 也是过小的

嗯。但解析数和执行数的比例还是太不可靠，基本可以认为是没有利用到会话pga中的open/cached游标。真是搞不懂是为什么……数据库版本是11.2.0.1.6

ALLSTARS_ORACLE

“但解析数和执行数的比例还是太不可靠”

这样说的依据是什么？

data_data

ALLSTARS_ORACLE 发表于 2014-10-13 20:08
“但解析数和执行数的比例还是太不可靠”

这样说的依据是什么？

绝大多数sql的执行数=解析数（软解析为主），如
SQL_ID                                        EXECUTIONS PARSE_CALLS VERSION_COUNT
--------------------------------------- ---------- ----------- -------------
d9jq7rbwg51ju                                   2612674     2612559                  12
2nzyqa2j992dm                                    854376        854372                  13

ALLSTARS_ORACLE

为什么不该是如此呢？

大量短链接+ 默认的session_cached_cursor，每秒还有7次左右的硬解析

我认为这些综合因素的话 对应这个软解析数目并无不妥啊

data_data

ALLSTARS_ORACLE 发表于 2014-10-13 22:42
为什么不该是如此呢？

大量短链接+ 默认的session_cached_cursor，每秒还有7次左右的硬解析

可能你没有看完全贴吧。
以前确实是大量短链接，现状是部分连接做了优化，例如后面我列举的2个sql，已经是长链接。但仍然有这么高的解析数。另外，我做了个测试，sqlplus中，在同一个会话中多次执行同一条sql,这一条sql的解析数依旧是等于执行数的。
这就是我目前疑惑的问题：为什么没有用到软软解析，及时我的会话pga有缓存游标的前提下。

data_data

咋没了消息…………实在不行就只能先升级了。

Maclean Liu(刘相兵

我始终认为在 这样大面积的短链接和并不合适的session_cached_cursor下 这点软解析是正常的，如果你觉得不正常 请给出同等配置下合理值的演示。

data_data

Maclean Liu(刘相兵 发表于 2014-10-14 23:04
我始终认为在 这样大面积的短链接和并不合适的session_cached_cursor下 这点软解析是正常的，如果你觉得不 ...

感谢！我会先设置更大的session_cached_curcors，并让开发人员优化连接模式，看看是否有效。到时会给出一个结果。感谢刘大的时间~

dla001

用连接池了？

data_data

dla001 发表于 2014-10-15 11:25
用连接池了？

想必是的。

dla001

data_data 发表于 2014-10-15 14:36
想必是的。

连接池的类似maxStatements 这种参数开了没？ 这个是C3P0的，其它的连接池也有自己的相应的参数。

data_data

dla001 发表于 2014-10-15 15:52
连接池的类似maxStatements 这种参数开了没？ 这个是C3P0的，其它的连接池也有自己的相应的参数。 ...

应用方面的细节我不清楚，这个能调节的东西并不是重点。问题是后面所说的：

列举的2个sql，已经是长链接。但仍然有这么高的解析数。另外，我做了个测试，sqlplus中，在同一个会话中多次执行同一条sql,这一条sql的解析数依旧是等于执行数的。
这就是我目前疑惑的问题：为什么没有用到软软解析，及时我的会话pga有缓存游标的前提下。