大量OPTIMIZER_MISMATCH引起的游标高版本,cursor:mutex s等待
这阵子时常出现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。
请大神帮忙，谢谢。 给出这个SQL 2nzyqa2j992dm 的文本
以及
select * from v$sql_optimizer_env where sql_id='2nzyqa2j992dm'; Maclean Liu(刘相兵 发表于 2014-9-28 10:30 static/image/common/back.gif
给出这个SQL 2nzyqa2j992dm 的文本
以及
刘大，高版本之前我做了个操作之后目前是降下来了。这还是开发人员的坑，之后我发现应该是短链接和concurrent，引发的Bug 10351178 High version counts caused by auto tuned PGA memory 。之后修改连接方式，算是规避了这个问题。 Maclean Liu(刘相兵 发表于 2014-9-28 10:30 static/image/common/back.gif
给出这个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
-----------------------------------------------------
我的诊断手段有限，请刘大帮忙支招。感谢！
对于短链接 而言 session_cached_cursors 的缓存游标是没有意义的，所以有软解析高很正常。 Maclean Liu(刘相兵 发表于 2014-10-3 18:26 static/image/common/back.gif
对于短链接 而言 session_cached_cursors 的缓存游标是没有意义的，所以有软解析高很正常。 ...
是的。但问题是已经修改为长连接了，还是一执行一解析。测试中用sqlplus执行sql多次，会话保持连接，从另一会话中查询此sql的解析数也是一执行一解析。我想不出还有什么情况会这样，会不会是该版本的某个bug。版本为11.2.0.1.6 data_data 发表于 2014-10-3 22:27 static/image/common/back.gif
是的。但问题是已经修改为长连接了，还是一执行一解析。测试中用sqlplus执行sql多次，会话保持连接，从另 ...
给出 支持你说法现象的AWR 没网络暂时给不了awr，慢些上传。现在正常情况下这个库负载是很低的。疑惑的是在长链接之下，几个参数设置正常之下，没有用到软软解析。 本帖最后由 data_data 于 2014-10-12 12:33 编辑
Maclean Liu(刘相兵 发表于 2014-10-3 22:39 static/image/common/back.gif
给出 支持你说法现象的AWR
刘大，麻烦分析一下。截图是长链接模式运行一段时间后的sql解析。 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次 ，我不认为这个 可以称为 长连接。 Maclean Liu(刘相兵 发表于 2014-10-12 20:46 static/image/common/back.gif
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
不知道我这样的论证方式有没有问题。麻烦分析一下问题。谢谢刘大~
session_cached_cursors 也是过小的 Maclean Liu(刘相兵 发表于 2014-10-13 13:10 static/image/common/back.gif
session_cached_cursors 也是过小的
嗯。但解析数和执行数的比例还是太不可靠，基本可以认为是没有利用到会话pga中的open/cached游标。真是搞不懂是为什么……数据库版本是11.2.0.1.6 “但解析数和执行数的比例还是太不可靠”
这样说的依据是什么？
ALLSTARS_ORACLE 发表于 2014-10-13 20:08 static/image/common/back.gif
“但解析数和执行数的比例还是太不可靠”
这样说的依据是什么？
绝大多数sql的执行数=解析数（软解析为主），如
SQL_ID EXECUTIONS PARSE_CALLS VERSION_COUNT
--------------------------------------- ---------- ----------- -------------
d9jq7rbwg51ju 2612674 2612559 12
2nzyqa2j992dm 854376 854372 13 为什么不该是如此呢？
大量短链接+ 默认的session_cached_cursor，每秒还有7次左右的硬解析
我认为这些综合因素的话 对应这个软解析数目并无不妥啊 ALLSTARS_ORACLE 发表于 2014-10-13 22:42 static/image/common/back.gif
为什么不该是如此呢？
大量短链接+ 默认的session_cached_cursor，每秒还有7次左右的硬解析
可能你没有看完全贴吧。
以前确实是大量短链接，现状是部分连接做了优化，例如后面我列举的2个sql，已经是长链接。但仍然有这么高的解析数。另外，我做了个测试，sqlplus中，在同一个会话中多次执行同一条sql,这一条sql的解析数依旧是等于执行数的。
这就是我目前疑惑的问题：为什么没有用到软软解析，及时我的会话pga有缓存游标的前提下。 咋没了消息…………实在不行就只能先升级了。 我始终认为在 这样大面积的短链接和并不合适的session_cached_cursor下 这点软解析是正常的，如果你觉得不正常 请给出同等配置下合理值的演示。 Maclean Liu(刘相兵 发表于 2014-10-14 23:04 static/image/common/back.gif
我始终认为在 这样大面积的短链接和并不合适的session_cached_cursor下 这点软解析是正常的，如果你觉得不 ...
感谢！我会先设置更大的session_cached_curcors，并让开发人员优化连接模式，看看是否有效。到时会给出一个结果。感谢刘大的时间~ 用连接池了？ dla001 发表于 2014-10-15 11:25 static/image/common/back.gif
用连接池了？
想必是的。 data_data 发表于 2014-10-15 14:36 static/image/common/back.gif
想必是的。
连接池的类似maxStatements 这种参数开了没？ 这个是C3P0的，其它的连接池也有自己的相应的参数。 dla001 发表于 2014-10-15 15:52 static/image/common/back.gif
连接池的类似maxStatements 这种参数开了没？ 这个是C3P0的，其它的连接池也有自己的相应的参数。 ...
应用方面的细节我不清楚，这个能调节的东西并不是重点。问题是后面所说的：
列举的2个sql，已经是长链接。但仍然有这么高的解析数。另外，我做了个测试，sqlplus中，在同一个会话中多次执行同一条sql,这一条sql的解析数依旧是等于执行数的。
这就是我目前疑惑的问题：为什么没有用到软软解析，及时我的会话pga有缓存游标的前提下。
页:
[1]