删除空子表约束导致主表事务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)还要大,这明显是不正常的现象。

继续阅读

应用报错“Io 异常: Connection reset”异常案例

前几日,一套核心业务数据库待投产环境进行投产前测试时应用出现大量“Io 异常: Connection reset”报错,应用无法连接数据库。要来数据库相关信息后,登陆数据库检查状态发现数据库正处于大量’Library Cache Lock与Library Cache Mutex :X等待中,如下图ASH所示:

20191227-1

20191228-5

20191228-6

大量ddl_lock type为79,已经知晓了这种现象的根因,随手做了一个数据库systemstate dump进行验证:

oradebug setmypid
oradebug dump systemstate 266;
oradebug tracefile_name;

探寻 dump Trace文件,我们看到会话正在等待Library Cache Lock,做system dump 的意义在于,要找到持有Library Cache Handle Lock的会话为什么会持有锁,为什么不及时释放锁从而导致后续活动会话get不到Lock资源从而等待,

20191228-1

dump trace文件中已经明确显示了该handle address,继续搜寻后发现证实了我的猜测,

20191228-2我们看到,该Hanlde Lock既有RequestMode=X,同时又存在LockMode=X ,不兼容从而发生的阻塞等待是正常现象,但是发现了该Library Cache Lock 的Namespace=ACCOUNT_STATUS(79),证实了我的猜测,该阻塞等待是因为数据库账户密码错误导致触发Oracle 延迟登录特性,从而产生大量Library Cache Lock。但是为何Io 异常: Connection reset呢?猜测是因为数据库活动会话大量积压,应用服务器连接数被撑满。

既然找到并且证实了根因,针对此问题下一步该如何操作?针对数据库账户密码错误,我们可以执行:

alter system set events '1017 trace name errorstack forever,level 3';

该errorstack会生成trace文件,在trace文件中确认,waitint for library cahce lock中的machine,也就是密码错误触发延迟登录长时间持有Library Cache Lock的应用服务器。

设置完成后,只要利用错误密码登录数据库抛出ORA-01017,则会在数据库Alert中产生一个Trace文件.

20181228-3

20191228-4

随后将报错应用服务器发送至应用方,检查配置的数据库账户密码是否正确。

最后, 为消除之后隐患,在数据库中执行

ALTER SYSTEM SET EVENTS '28401 TRACE NAME CONTEXT FOREVER, LEVEL 1' :

从而使得,今后会话在因密码登录失败后,直接返回报错,不会长时间持有LIBRARY CACHE LOCK 。

alter table drop column(default value not null )导致ORA-12899

近日,同事的测试库中出现一则奇怪的现象邀请我共同探讨,一张数据表在删除一个含有DEFAULT值的非空列时报错,Error Code为ORA-12899,报错详情如下:

20191215-1

12899, 00000, "value too large for column %s (actual: %s, maximum: %s)"
// *Cause: An attempt was made to insert or update a column with a value
// which is too wide for the width of the destination column.
// The name of the column is given, along with the actual width
// of the value, and the maximum allowed width of the column.
// Note that widths are reported in characters if character length
// semantics are in effect for the column, otherwise widths are
// reported in bytes.
// *Action: Examine the SQL statement for correctness. Check source
// and destination column data types.
// Either make the destination column wider, or use a subset
// of the source column (i.e. use substring).

专业的同事,在同样觉得蹊跷的之后,再一次执行此语句并且抓取了相关10046 Trace文件,分析Trace文件后,发现有一条递归update语句导致此错误,导致drop column失败,进入死循环。

2019115-2

继续阅读

针对SCHEMA Rename需求

近日,某测试数据库用户存在更换schema名称的需求,同事准备将数据进行导入导出的同时进行remap schema的工作,其实,从ora11g(11.2.0.2)版本开始,Oracle提供在不动数据的情况下,将schema rename的功能,但是代价是需要将数据库启动restrict模式下,实验如下:

20191208-111

rename之前需要将_enable_rename_user隐含参数改为TRUE(默认为FALSE),此参数意义为enable RENAME-clause using ALTER USER statement。

将数据库启动到restrict模式后,可以利用alter user rename命令进行更改schema name,本案例中为schema独占测试数据库,若生产库将数据库中一般存在多个schema共享一套数据库,启动到 restrict模式会造成应用连接无法连接数据库的情况发生,因本案例为测试系统,生产系统慎用此方式。

20191208-222

Oracle 12c column add default value功能增强

前几日晚,某核心应用负责人准备进行上线操作前打来一个确认电话,咨询了一个Oracle 11g 表添加default值的问题,询问是否有何影响,听完他的描述后,简单跟他描述完原理后,建议他取消此上线操作,否则会造成核心应用严重的性能问题,但是此问题再Oracle 12c新特性中已得到很大改进,对性能的影响已经降到最低。

11g情况下,可以看到,增加一个带有default值的并且没有添加非空约束的列,需要分钟级别(与表数据量有直接关系),完成时间会随着数据量的增加而耗时变长。

20191208-11

会话2,我们在执行alter table时会造成读写阻塞,等待library cache lock

SID=916会话被阻塞

20191208-12

SID=346会话被阻塞:

20191208-14

所以在此期间内产生的应用事务,查询均会被阻塞,如果TABLE量级比较大,会造成更严重的性能问题,因为11g在添加DEFAULT值且没有非空约束时,在更新数据字典的同时仍要更新表中全部已有记录值,我们从segment大小与10046 event trace文件中可以得到论证。

继续阅读

应用端频繁报出java.sql.SQLException: pingDatabase failed, status=-1案例

近日,某航司B2C网站应用人员发来求助排查邮件,告知JBOSS连接数据库经常报出java.sql.SQLException: pingDatabase failed, status=-1的错误,并且经过确认,数据库正处于正常状态下,应用人员提供了相对具体报错时间点,希望尽快帮忙排查一下数据库端有无异常。

20191201-2

登录数据库查看alert与监听日志后发现,数据中确实偶发出现如下链接报错,

20191201-1

继续阅读