数据库性能问题导致应用单次SQL效率10ms变为10s

昨日,同事发来一则微信反馈前一天晚应用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等待事件所阻塞。

故障时间段内Top Event百分比

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

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

4327这个会话为oracle auto_task的sql auto tunning advisor job,并且他持有了Library Cache Lock Handle “0x1f9bc9bb98″导致了会话3877想以Mode=3(X)独占模式持有Library Cache Lock不成功,被阻塞。
2060为正常的应用会话,并且同样等待LIBRARY CACHE LOCK,没有阻塞者,这是一个奇怪的现象

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

从相同时间段的systemstate dump trace文件中看到,2060会话在等待library cache lock,申请的同样是0x1f9bc9bb98的Library Cache Lock Handle (Mode=2(s) 共享模式),虽然没有Dump出2060的阻塞者,但是从申请的Handle上可以推断,都是被4327会话sql auto tunning advisor job阻塞。

分析结论: 此时间段确实为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功能,规避此问题再次发生。

一则Bug导致数据库All Database Sessions Hang

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

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

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

20200127-2

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

20200127-3

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

20200127-4

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

Bug 29635990 – All Database Sessions Hang Due To Checkpoint Incomplete (Doc ID
29635990.8)
20200127-5

但是这个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)的现象,从而导致产生更大数据库夯死风险。

删除空子表约束导致主表事务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

应用报错“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 。

又见Log File Sync~

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

log_file_sync_1024-1

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

ASH信息:

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

1026-2

 

继续阅读

enq: US – contention 等待事件

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

US-1

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

继续阅读

Library Cache中Latch与Mutex Event(5)—Cursor Pin S Wait on X

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参数即可定位等待的实际对象。

二.模拟场景:

curs-1

继续阅读

一个生产数据库HANG案例

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

od-1

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

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

OD-2

继续阅读

核心系统业务交易超时,enq:SQ contention: 这个锅我不背。

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

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

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

SQ-1

关注一下ASH报告信息:

SQ-2

 

继续阅读

Find_Blocker.sql–查询数据库中阻塞关系

昨日在线上分享案例时,一个朋友询问了一个问题,等待Cursor Pin s wait on X的会话是否可以Kill掉。当数据库发生严重的等待时,我一般常用的一个脚本如下:

with blocked as
  ( SELECT  *
  FROM 
    ( SELECT  instance, sid, sess_serial#, blocker_instance, blocker_sid, blocker_sess_serial#, WAIT_EVENT_TEXT, level lv, num_waiters, blocker_chain_id
    FROM v$wait_chains connect by PRIOR sid = blocker_sid
        AND PRIOR sess_serial# = blocker_sess_serial#
        AND PRIOR INSTANCE = BLOCKER_INSTANCE START
    WITH blocker_is_valid = 'FALSE')
    WHERE num_waiters > 0
        OR blocker_sid is NOT null) SELECT  s.username, b.instance, b.ses, b.sess_serial#, b.wait_event_text
  FROM 
  ( SELECT  instance, lpad(' ', 2 * (lv - 1)) || b.sid ses, b.sess_serial#, WAIT_EVENT_TEXT, b.blocker_instance, b.blocker_sid, b.blocker_sess_serial#
  FROM blocked b) b, gv$session s
WHERE s.sid=b.ses
    AND s.serial#=b.sess_serial#;
 继续阅读