Monthly Archives: 1月 2020

删除空子表约束导致主表事务row cache lock/Library cache lock/Cursor pin s wait on x

春节前夕,公司一套核心核心再核心的数据库出现严重性能问题(版本信息:11.2.0.4),数据库活动会话飙升到300+,幸好当时处置得当,人员判断与应急迅速,及时kill了相关blocker session从而使得影响没有扩大。20200114-1从应用负责人员获悉,此时间段应用人员正在执行上线操作,具体操作为删除一张num rows=0的空表的外键约束。

alter table TRAVELSKYDBA drop constraint FK_TRAVELSKYDBA;

ASH中活动会话基本都在等待Library Cache Lock,Cursor Pin s Wait On X,Row Cache Lock上,阻塞情况如下:

20200123-11

继续分析,发现了一个更加奇怪的现象:

20200123-13

SESSION_ID=1827的会话为应用上线alter table删除外键约束的语句会话,SESSION_ID=73,2119,4000均为对删除外键的主表的正常业务DML语句(INSERT,DELETE,UPDATE),从ASH中看到1827会话正在等待正常业务事务(SESSION_ID=73)的LIBRARY CACHE LOCK,但是SESSION_ID=73在等 ROW CACHE LOCK,被ALTER TABLE (SESSION_ID=1827)阻塞,行成了死锁,并且ROW CACHE LOCK 的P1=8(dc_object与grants,dc_object),随后的正常事务的DML SQL想去软解析时遭遇Cursor Pin S wait on X。

从数据库DIAG进程自动dump的system state dump与Hanganalyze trace中确认,这些应用的SQL因为Rolling Invalidate Window Exceeded触发了硬解析,alter table 子表 drop constraints时,这项操作是需要申请主表DML游标Object Handle的Library Cache Lock的,主表涉及SQL在硬解析,ALTER TABLE求LIBRARY CACHE LOCK而不得被阻塞,但是主表DML硬解析申请ROW CACHE LOCK,理论上非常快速内存操作为何长时间不释放?产生死锁?并且Oracle并没有处理这个死锁

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
 Oracle session identified by:
 {
 instance: 1 (#######)
 os id: 111552
 process id: 161, oracle@###-rac
 session id: 73
 session serial #: 181
 }
 is waiting for 'row cache lock' with wait info:
 {
 p1: 'cache id'=0x8
 p2: 'mode'=0x0
 p3: 'request'=0x3
 time in wait: 0.612302 sec
 heur. time in wait: 2 min 23 sec
 timeout after: 2.387698 sec
 wait id: 24235
 blocking: 286 sessions
 wait history:
 * time between current wait and wait #1: 0.000034 sec
 1. event: 'row cache lock'
 time waited: 3.000963 sec
 wait id: 24234 p1: 'cache id'=0x8
 p2: 'mode'=0x0
 p3: 'request'=0x3
 * time between wait #1 and #2: 0.000039 sec
 2. event: 'row cache lock'
 time waited: 3.000978 sec
 wait id: 24233 p1: 'cache id'=0x8
 p2: 'mode'=0x0
 p3: 'request'=0x3
 * time between wait #2 and #3: 0.000064 sec
 3. event: 'row cache lock'
 time waited: 3.000913 sec
 wait id: 24232 p1: 'cache id'=0x8
 p2: 'mode'=0x0
 p3: 'request'=0x3
 }
 and is blocked by
 => Oracle session identified by:
 {
 instance: 1 (*******)
 os id: 92902
 process id: 112, oracle@*****-rac
 session id: 1827
 session serial #: 19367
 }
 which is waiting for 'library cache lock' with wait info:
 {
 p1: 'handle address'=0xfeec0a948
 p2: 'lock address'=0xfe24600b8
 p3: '100*mode+namespace'=0x15dba00010003
 time in wait: 2 min 23 sec
 timeout after: 12 min 36 sec
 wait id: 1540
 blocking: 286 sessions
 wait history:
 * time between current wait and wait #1: 0.000150 sec
 1. event: 'gc current block 2-way'
 time waited: 0.000285 sec
 wait id: 1539 p1: ''=0x1
 p2: ''=0x131f3
 p3: ''=0x1
 * time between wait #1 and #2: 0.000131 sec
 2. event: 'gc current block 2-way'
 time waited: 0.000374 sec
 wait id: 1538 p1: ''=0x1
 p2: ''=0x131de
 p3: ''=0x1
 * time between wait #2 and #3: 0.002456 sec
 3. event: 'gc cr block 2-way'
 time waited: 0.000405 sec
 wait id: 1537 p1: ''=0x1
 p2: ''=0x131f3
 p3: ''=0x1
 }
 and is blocked by the session at the start of the chain.

Chain 1 Signature: 'library cache lock'<='row cache lock' (cycle)
Chain 1 Signature Hash: 0x52a8007d
----------------------------------------------------------------
并且 p3: '100*mode+namespace'=0x15dba00010003 --003 LOCK MODE=X

SQL> select to_number('15dba','xxxxxxx') from dual;
TO_NUMBER('15DBA','XXXXXXX')
---------------------------
 89530  --主表对象OBJECT_ID

20200123-16

SESSION_ID=73在sql net message from client中居然阻塞了1827的 alter table?

分析到这里,越来越感觉是Bug导致,从Mos上寻找相关案例发现一篇“现象相似”的文章,可惜版本无法对应上,不能确定是因为此Bug导致,虽然最后没有定位具体的Bug Number,但是此问题要告诫警示大家,不要再事务繁忙期间进行alter table DDL操作,虽然是一张空表,但是和其对象的相关OBJECT也存在受到牵连的可能性,从而产生跟大的影响。

20200123-17

参数一致却导致ORA-01105: mount is incompatible with mounts by other instances

昨日,RAC数据库2节点因私网心跳超时导致CRS重启,异常的是,数据库实例并没有如愿启动,而是在CRS自动带起数据库实例时,NOMOUNT到MOUNT过程中抛出了如下报错:

ORA-01105: mount is incompatible with mounts by other instances 
ORA-19808: recovery destination parameter mismatch

此错误为RAC数据库各实例同一参数生效值存在differ的情况,但是针对本次案例,经过分析与测试,此问题定性为软件Bug,故障现象还原模拟如下:

20200121-1

与生产系统现象一致,3节点RAC中,db_recovery_file_dest 参数为空,db_recovery_file_dest_size为300gb,

20200123-1

我们在节点2上设置db_recovery_file_dest参数,设置为+DG_DATA

20200123-2

我完全还原生产环境中故障的现象,生产环境中,在时间节点1时,集群2节点设置了db_recovery_file_dest参数,并且该参数在1个月后左右,人为将节点1上这个参数设置成了空,并且两次参数范围生效均为scope=both sid=’*’

故障现象出现,节点2宕机,并且无法启动抛出了预期的错误,生成create pfile from memory与create pfile from spfile后进行对比,但是这个参数各个节点均为格式一致的空,理论上不存在参数不一致且冲突的设置。

20200123-3

是否这个参数的设置方式不规范导致了此问题的发生,询问了Oracle业界大神ACED杨廷琨老师,杨老师建议用reset方式再次进行测试,但是测试结果一致,只用alter system reset方式进行参数的重置,仍然会导致此问题的发生。

严谨的杨老师继续给予我第二个测试内容,

(1)是否只是设置为空会引发这个问题,如果修改为其他目录是不是在任意一个节点都可以?

(2)另外,如果置空需要在当时set的节点运行,那么如果当前崩溃尝试启动的恰好是这个节点呢?其他节点的reset都无法使当前节点的实例启动吗?

测试点(1)是否只是设置为空会引发这个问题,如果修改为其他目录是不是在任意一个节点都可以?

20200123-4

这时,模拟2节点宕机并重启后,没有发生ORA-01105与ORA-19808的错误,说明本节点设置值A,另外节点设置非空值B是OK的

测试点(2)如果置空需要在当时set的节点运行,那么如果当前崩溃尝试启动的恰好是这个节点呢?其他节点的reset都无法使当前节点的实例启动吗?

2020012305

20200123-6测试结论:因为这个参数设置导致的“冲突”,从而引发了实例重启的故障,但是,通过上述对生产环境的模拟发现,这个参数各个节点实际上内存生效值与实例SPFILE中的参数数值并不存在差异(包括格式),显然,这是Oracle软件的Bug行为,

1.节点set value,节点set null必须在同一节点上运行,如果不同,则会影响set value 节点重启,解决方案为在set null节点再次执行set null命令,其他节点设置其他VALUE是无影响的(只要别设置为空)

2.如果set null节点已宕机的情况下,之后set value节点也无法启动了,需要其他存活节点上再次执行set null命令后,set value,set null的异常节点均可成功启动

3.如果set null节点存活,则必须在set null节点 再次执行set null命令,若在其他存活节点上执行set null命令,set value节点同样无法启动。

 

RAC节点2遭遇连续驱逐

公司一套核心业务数据库RAC集群数据库2节点实例分别在2019年 11月13日,2020年1月2日,2020年1月11日发生3次被集群驱逐的情况发生,并且故障时,三次重启CRS均夯住,只能通过重启服务器的方式应急解决。

1.集群日志(2019.11.13)

20190112-1112.集群日志(2020.01.02)

20200112-2

3.集群日志(2020.01.11)

20200112-3

通过以上日志得知,三次实例驱逐均是因为集群间私网心跳超时导致,但是依照RAC网络心跳集群的驱逐的原则,2节点被驱逐不见得根因就是出在2节点上,该环境为2节点RAC,因心跳超时导致集群分为2个子集群,保留最小节点号的子集群会留下,所以1节点会有很大几率被保留,2节点会被驱逐。

分析Oswatcher中netstat采集的网络信息:

节点1,故障期间包重组失败统计:

20200112-04

节点1,物理丢包统计:

20200112-07

节点2,故障期间包重组失败统计:

20200112-05

节点2,物理丢包统计:

20200112-06

可以看到,节点1故障期间没有发生物理丢包与包重组失败,然而节点2则物理丢包与包重组失败都存在(数值一值在累计增加),所以基本推定节点2数据库服务器私网网卡存在异常现象。当讨论这个故障期间,有同事提出可以修改linux操作系统内核参数,避免大量包重组失败的问题:

net.ipv4.ipfrag_high_thresh = 16M     --default 4M
net.ipv4.ipfrag_low_thresh = 15M      --default 3M

这种方式是可行的,当无法排查定位出硬件设备问题时,可以尝试利用此方式来继续观察,但是上述现象除了包重组失败还存在物理丢包现象,也就是说很多Packet没有到包重组那步就已经出现ERROR于DROP的现象,物理丢包仍然会导致RAC集群心跳超时从而继续驱逐节点。

通过上述分析后,我们决定不修改内核参数,决定进行本日第二次的私网网卡切换操作,继续观察,硬件同事将eth14切换到eth08后,丢包现象消失,问题暂时解决,继续观察。

Cursor 触发了OPTIMIZER_MISMATCH=Y的Bug?

近日,一个数据服务器CPU基本每日触发报警,Idle已经接近于0,并且存在一定的周期性规律,CPU Idle如下图所示:

20200105-11

定位到具体进程后,发现CPU TIME主要被两个SQL因为创建合适的索引导致大量全表扫描耗尽。经过简单优化后,SQL效率提升,但却发现了一个奇怪的问题:

优化前:

20200105-12

优化后:

20200105-13

使得游标立即失效后,此SQL会立即进行硬解析,但是却硬解析了2个Child Cursor:

20200105-14

20200105-15可以看到,两个Cursor确认是因为客户端NLS_SORT与NLS_COMP参数不一致,导致了Cursor 2无法利用上索引,从而选择了全表扫描的执行计划。但是从V$SQL_SHARED_CURSOR中发现了异常现象,LANGUAGE_MISMATCH很好理解(因为NLS_SORT与NLS_COMP参数不一),但是OPTIMIZER_MISMATCH为何也是’Y’?

20200105-16

利用alter system set events ‘trace[rdbms.SQL_Optimizer.*][sql_id]’ ;查看Trace文件与查询v$sql_optimizer_env确认游标优化器参数时,并没有发现异常现象:

20200105-17

20200105-18如果优化器参数不一,那么cursor执行计划中的Outline Data CBO参数部分会有所区别,但是上图中两个Cursor 执行计划中显示的CBO参数是一致的。虽然Oracle Support中并未发现相关Bug记录,但是猜测很有可能是触发了Bug导致。

Oracle AWR裸数据提取-Tablespace io指标发现的Bug

近日,梳理并确认Oracle数据库历史数据收集SQL有效性与正确性是发现了一个异常的现象,利用如下SQL采集数据库tablespace io相关统计信息时发现,AWR中1-bk Rds/s指标数据却与SQL裸数据提取的Writes数据完全一致。

AWR报告结果

20200105-1

SQL裸数据提取结果:

20200105-2

可以看到,AWR数据中的1-bk Rds/s与Writes数据完全一致,但是1-bk Rds/s的含义应该是每秒发生的读取单个block的次数,然而Writes是通过dba_hist_filestatxs视图中提取PHYWRTS数据指标来实现的,这两个指标含义完全不一致,不可能这么产生如此的巧合。到底是哪里出的问题?并且1-bk Rds/s居然比Av Rds/s(RPS)还要大,这明显是不正常的现象。

read more »