某电信业务平台p570数据库瞬间访问慢故障分析(News).doc

某电信业务平台p570数据库瞬间访问慢故障分析目 录1、故障现象12、故障的直接原因分析13、磁盘IO等待时间较长的原因分析24、锁的形成机制分析55、结论71、故障现象6月14日14:55，节点XX.XX.XX.XX连接的前台有不到2分钟的时间访问数据库速度很慢。其中表AAA的写入数据的频度如下：时间段写入的记录数2012/6/14 14:503802012/6/14 14:513362012/6/14 14:523572012/6/14 14:533902012/6/14 14:543542012/6/14 14:551772012/6/14 14:562292012/6/14 14:573332012/6/14 14:583852012/6/14 14:593402012/6/14 15:00383在14:55时，写入的数据明显降低。2、故障的直接原因分析比较6月14日，14:53-59的每分钟的ASH报告，发现：1、在14:55:00-14:56:00、14:56:00-14:57:00，存在TOP DB Files，而在其他时段，并不存在。TOP DBfiles表示访问这个数据文件存在较长等待。在55:00-56:00时段，出现等待的事件是： gc current grant 2-way。此事件说明是：当时在内存里找不到数据块，需要到磁盘上去找。（The message-oriented wait event statistics indicate that no block was received because it was not cached in any instance. Instead a global grant was given, enabling the requesting instance to read the block from disk or modify it.） 2、在56:00-57:00，事件更演变成： gc buffer busy acquire这是一个面向竞争的事件。这个事件表明library cache pin已经发生了。事实上果然如此。（The contention-oriented wait event statistics indicate that a block was received which was pinned by a session on another node,was deferred because a change had not yet been flushed to disk or because of high concurrency, and therefore could not be shipped immediately.）这个事件通常是指另一个节点的会话加锁了数据块。加锁的原因是下列因素之一：1） 还没有刷新到磁盘2） 高度并发3） 本地的两个会话在争抢。从上面的分析看到，这次某电信业务瞬间访问慢的直接原因就是磁盘IO等待时间较长。3、磁盘IO等待时间较长的原因分析14:55:00-14:56:00等待的数据文件如下。File ID% ActivityEvent% EventFile NameTablespace1181.15gc current grant 2-way1.15/dev/rlv_index43ICD某电信业务_MAIN_IDX1461.15gc current grant 2-way1.15/dev/rlv_index56ICD某电信业务_LOG_IDX1511.15gc current grant 2-way1.15/dev/rlv_index61ICD某电信业务_LOG_IDX1分钟ASH报告中，top db file如下：File ID% ActivityEvent% EventFile NameTablespace1181.15gc current grant 2-way1.15/dev/rlv_index43ICD某电信业务_MAIN_IDX1461.15gc current grant 2-way1.15/dev/rlv_index56ICD某电信业务_LOG_IDX1511.15gc current grant 2-way1.15/dev/rlv_index61ICD某电信业务_LOG_IDX从上表中可以看出，在14：55-14：56，比较忙的表空间是ICD某电信业务_MAIN_IDX和ICD某电信业务_LOG_IDX。有2个top object在这两个表空间上。Top DB ObjectsWith respect to Application, Cluster, User I/O and buffer busy waits only. Object ID% ActivityEvent% EventObject Name (Type)Tablespace2204752.30gc current grant 2-way2.30DLP某电信业务_DE03.IX_CALLINLOAD_LASTDATE (INDEX)ICD某电信业务_LOG_IDX1753281.15gc current grant 2-way1.15DLP某电信业务_DE03.IDX_TRANSBILL_CALLER (INDEX)ICD某电信业务_MAIN_IDX从上表可以看出，在这两个忙的表空间上最忙的对象是这两个索引。这两个索引的属主是dlp某电信业务_de03。这个用户dlp某电信业务_de03是通过JDBC访问数据库的。Sid, Serial#% ActivityEvent% EventUserProgram# Samples ActiveXIDs1485,249182.30CPU + Wait for CPU1.15DLP某电信业务_DE03JDBC Thin Client1/6 17%0library cache pin1.151/6 17%0674,117581.15CPU + Wait for CPU1.15ISEADMINJDBC Thin Client1/6 17%0688,338511.15library cache pin1.15ISEADMINJDBC Thin Client1/6 17%0827,366351.15library cache lock1.15DLP某电信业务_DE03aplogicSB-IVR-2 (TNS V1-V3)1/6 17%0872,543481.15library cache pin1.15ISEADMINJDBC Thin Client1/6 17%0在这1分钟内，执行的top sql如下：SQL IDPlanhashSampled # of Executions% ActivityEvent% EventTop Row Source% RwSrcSQL Text75jt5pz26jg892528.74library cache pin28.74* Row Source Not Available *28.74BEGIN P_QUE_UNITNOTE(:1, :2, :.1339dkff7ss3g3462735131016.09library cache lock16.09* Row Source Not Available *16.09SELECT TEXTCONTENT FROM T_SCE_.9r9dkcc8ccsns89.20library cache pin9.20* Row Source Not Available *9.20BEGIN P_DZ_GETUSERINFOEX(:1, :.f7vcvknr79snk371631394389.20library cache pin9.20UNION-ALL9.20SELECT UnitID | | IncTyp.g3kbsub2vsg3144.60library cache pin4.60* Row Source Not Available *4.60BEGIN p_dz_msa_msp_writebackre.正是这个用户dlp某电信业务_de03，执行了以上的top sql，并访问前面指出的两个索引，导致IO wait长。数据库的alert.log 也没有任何出错信息。ASH报告也没有指出数据库本身的任何问题。4、锁的形成机制分析在14：55-15：00的5分钟ash报告中，top sql如下：SQL IDPlanhashSampled # of Executions% ActivityEvent% EventTop Row Source% RwSrcSQL Text75jt5pz26jg894289.00library cache pin8.99* Row Source Not Available *8.99BEGIN P_QUE_UNITNOTE(:1, :2, :.950r156yzwjg13741150534778.18row cache lock5.30* Row Source Not Available *5.30INSERT INTO t_Online06 (Serial.enq: US - contention2.37* Row Source Not Available *2.377wgkmhbq6m0sb2217.77library cache pin6.04* Row Source Not Available *6.04begin P_GetUserInfo (:1, :2, .2217.77library cache lock1.73* Row Source Not Available *1.73begin P_GetUserInfo (:1, :2, .fvxfddnzfqq9y3783955680697.33row cache lock4.94UPDATE4.94UPDATE T_STAFFCALLCOUNT T SET .enq: US - contention2.33UPDATE2.28gbqqjrafd356p515.79row cache lock3.55* Row Source Not Available *3.55INSERT INTO DEBUG_MSG VALUES (.515.79enq: US - contention