昨日，同事发来一则微信反馈前一天晚应用SQL查询缓慢，原本10ms内能完成的查询SQL在一时间段内：19号22：10到22：45突然执行效率下降到10分钟，然而在22：45后自动恢复正常，想分析一下根因。数据库为一套2节点RAC，Linux -x86 数据库版本为11.2.0.4。

有了明确的时间段，登录到数据库内看看到底这个期间产生了什么性能问题？

数据库DB_TIME、活动会话数与应用反馈的时间基本吻合，从22点10分开始，数据库中的Active_Session数量开始飙升，并且数据库活动会话基本都被Library Cache Lock与Cursor Pin S wait on X等待事件所阻塞。

从ASH中看，活动会话最早被节点1的4327会话所阻塞，并且等待的是LIBRARY CACHE LOCK，随后，开始出现sql尝试软解析，遭遇Cursor pin s wait on x，且被节点1的2060会话所阻塞

我们看一下4237与2060在故障期间在干什么？

但是2060会话在systemstate dump的trace文件中找到阻塞者，同样被4327会话阻塞

分析结论： 此时间段确实为oracle autotask作业的时间窗口，但是job会话并不会长时间持有Library Cache Lock，这个会话当时在等待db file scattered read，数据库当时物理读非常高并且io链路上没有明显异常，异常点1：此JOB作业长时间持有LIBRARY CACHE LOCK不释放且JOB涉及的SQL造成物理读很高，异常点2：内存lock与Mutex争用又会导致cpu Idle低，从而进一步导致io无法调度完成，造成会话JOB工作效率下降，从而没有及时的释放LIBRARY CACHE LOCK的可能性会加大，这些都是非常不正常的行为，所以我决定disable sql tunning advisor功能，规避此问题再次发生。

春节前夕，一套核心交易系统出现短时间夯死的状况出现（后台数据库版本信息：Oracle 11.2.0.4 RAC 2节点，Linux X86服务器），活动会话数又飙升至近300+

如上图所示，数据库从1月19日 09:34分左右开始，活动会话逐渐攀升，数据库在当时存在大量等待事件log file switch (checkpoint not complete)，排查了硬件IO链路、应用事务量均正常，还是要在数据库软件层面进行分析。

    可以看到当时数据库活动会话概览，这些在等待log file switch (checkpoint incomplete)的会话均被节点2的1369会话所阻塞。

那么2节点的1369会话这时在干些什么？从ASH中看到，1369会话（LGWR）正在读取控制文件，等待事件为control file sequential read,但是这个动作是很快的动作，理论上不应该造成长时间的阻塞。

当时的DIAG进程做的HANGANALYZE中我们可以看到如下的Chain关系，开始试图找寻是否是Bug引起，因为种种客观现象实在是有悖常理，无法从原理上解释

从Oracle Mos上找寻相关Bug描述，果然有一个刚刚发布不久的Bug：

但是这个Bug并未标注影响版本范围，但是和本次故障现象基本一致，遗憾的是并没有相关的Workrond并且此Bug只能在12.2版本中有相关Patch进行修复。

为了规避此问题的再次爆发，我们在数据库中设置了一个Job进行规避，调度时间按照redo 所有group#均变为ACTIVE且准备进行覆盖的时间周期，本系统为5分钟。

declare
jobno number;
begin dbms_job.submit(
jobno,
'begin
 execute immediate ''alter system checkpoint'';
end;',
sysdate,
'sysdate + 5/1440');
commit;
end;
/

每5分钟进行强制全量检查点，避免数据库再次产生log file switch (checkpoint not complete)的现象，从而导致产生更大数据库夯死风险。

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

alter table TRAVELSKYDBA drop constraint FK_TRAVELSKYDBA;

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

继续分析，发现了一个更加奇怪的现象：

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

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

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

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

大量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资源从而等待，

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

我们看到，该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文件.

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

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

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

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

上周四，应用部门中负责数据库维护的同事发来求助邮件，所属业务后台数据库出现严重性能异常，希望帮忙协助一下排查一下数据库问题，应用部门监控到了具体的异常时间点,如下图所示：

图中涉及到了两类数据库关键性能指标，1.DB_TIME，2.Active Session数据，从同事中邮件中反馈得知，24日的 16:00开始 数据库DB_TIME开始飙升，但是图中的ACTIVE_SESSION显示的异常事件点为14：00-15：00左右。两类指标异常的时间点并不吻合。具体数据库发生了什么？ 登录到数据库后，查看了具体的信息：

ASH信息：

从ASH中看到，从13：57分开始，数据库中陆续出现log file sync等待事件，与同事提供的监控数据基本吻合。

read more »

近期做数据库优化时，发现数据库AWR报告TOP 10等待事件中出现了一个enq:US-CONTENTION等待事件,性能瓶颈时AWR信息如下：

虽然该等待事件并不是引起数据库性能瓶颈的主要矛盾，主要矛盾分析请见《普通Index改造为Hash Partition后对涉及索引列的SQL查询影响有多大？》，那么什么enq: US – contention 等待事件？

read more »

Cursor Pin S Wait on X

一.什么Cursor Pin S Wait on X：

官方解释：

Mutexes were introduced in Oracle 10.2. A session waits for “cursor: pin S wait on X” when it wants a mutex in S (share) mode on a specific cursor but some other session holds that same mutex in X (exclusive) mode. Hence the current session has to wait for the X mode holder to release the mutex.Mutexes are local to the current instance in RAC environments.

Versions 10.2.0.1 - 11.2.0.2
Parameter    Description
P1             idn
P2            value
P3      where (where|sleeps in 10.2)

• A session waits for “cursor: pin S wait on X” when it wants a mutex in S (share) mode on a specific cursor but some other session holds that same mutex in X (exclusive) mode.
Hence the current session has to wait for the X mode holder to release the mutex.
• Occurs when hard parse time for a cursor is too long for the session holding the X mutex and at the same time another session is trying to execute the cursor.
• For SQL with long parse times.
• For SQL with high version counts.
• Frequent hard parses

一个process为一个与pin相关的共享操作（such as executing a cursor）请求一个mutex时,该mutex不能被立即获取，因为该mutex正在被其他session以排他模式持有。
例如，大量并发执行的SQL+SQL 硬解析：举一个简单的例子，一个会话（SESSION_A）正在解析（硬解析）某一个sql语句（SQL_A），当另一个会话（SESSION_B）同时执行这条sql语句（SQL_A）时（执行前需要对该语句进行软解析），SESSION_B就会等待cursor:pin S wait on X 事件。(硬解析+执行次数多) 该等待事件的P1参数idn，实际上就是sql语句的hash_value，也就是说通过该等待事件的P1参数即可定位等待的实际对象。

二.模拟场景：

read more »

之前公司一个运维的数据库每日凌晨3点左右均会HUNG住，使得应用无法正常处理业务作业，只能通过 kill session 进行释放。数据库的版本为 11.2.0.3，平台为 Linux x86-64 平台，数据量为2T 左右。 下面我们将对这一现象进行详细分析。

如上所示，故障期间数据库的等待事件主要为 cursor: mutex X。平均等待事件为 719s，
占了总 DB time 的 34%

什么是cursor: mutex X 等待事件： 等待的会话尝试独占（ EXCL）方式持有 cursor 的 mutex，而当前 cursor 已经被其他进程以共享（ SHRD）或独占方式持有，因此当前会话必须等待持有的 mutex 的进程释放，直到尝试持有 CURSOR 的 Ref count 等于 0，才能获取到游标。

read more »

本周三凌晨1点左右，公司某核心业务交易严重超时，触发了中间件层面的应急操作，因该业务系统过于重要，所以业务的IT全链路部门均开始隐患的排查工作，消除隐患，避免故障的二次发生。

该业务后台数据库  Linux X-86 Oracle 11.2.0.4 RAC 2节点架构

根据Cloud Control显示及历史信息查看，该数据库每日凌晨1点左右，均会产生一个激增的尖峰，等待Wait Class为 Concurrency。

关注一下ASH报告信息：

read more »