溫馨提示×

溫馨提示×

您好，登錄后才能下訂單哦！

密碼登錄×
登錄注冊×
其他方式登錄
點擊 登錄注冊 即表示同意《億速云用戶服務(wù)條款》

技術(shù)人生系列 · 我和數(shù)據(jù)中心的故事——第一期

發(fā)布時間：2020-08-10 05:29:09 來源：ITPUB博客 閱讀：249 作者：記錄每一次錯誤 欄目：關(guān)系型數(shù)據(jù)庫

小y這個名字，是筆者臨時想的一個筆名，其實沒有什么特殊的含義，就暫且用他來代表我們這些為各個數(shù)據(jù)中心奉獻自己青春的一群默默無聞的IT人吧！


小y今天要和大家分享的是一個疑難雜癥的分析過程。如果大家有耐心讀完這個案例，一定會或多或少有些收獲，也就沒浪費小y的一片苦心。


具體來說是一個應(yīng)用間歇性局部掛起案例的分析過程，報告中將對 Oracle 數(shù)據(jù)庫穩(wěn)定運行的共性風(fēng)險和隱患作出提醒。


1
問題描述

據(jù)客戶反映，應(yīng)用會間歇性出現(xiàn)異常，包括 insert 單條記錄在內(nèi)的操作長時間無法完成，按照客戶的說法，數(shù)據(jù)庫內(nèi)可能有“死鎖”現(xiàn)象，希望能夠找到問題發(fā)生的根因，提出解決方案，以避免問題再次發(fā)生。

2015 年 12 月 23 日，問題再次發(fā)生，客戶再次聯(lián)系到小 y， 小 y 通過遠程方式進行了信息收集和故障診斷，最終定位了問題的根本原因。

環(huán)境介紹：

操作系統(tǒng) > > > > > > >

INSERT INTO TABLE_NAME(COL1,COL2,COL3,COL4,COL5,COL6,COL7)VALUES(:1,:2,:3,:4,:5,:6,:7)


> > > > > > > >

SQL> oradebug setmypid

Statement processed.

SQL> oradebug hanganalyze 3

Hang Analysis in /oracle/admin/xxdb/udump/xxdb_ora_14136.trc

SQL>

SQL> oradebug dump systemstate 266

Statement processed.

SQL> oradebug tracefile_name

/oracle/admin/xxdb/udump/xxdb_ora_14136.trc


> > > > > > > > > > > >

PROCESS 19:

----------------------------------------

SO: c00000003949b948, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00

(process) Oracle pid=19, calls cur/top: c0000000397209b0/c0000000397209b0, flag: (0) -

int error: 0, call error: 0, sess error: 0, txn error 0

(post info) last post received: 0 0 121

last post received-location: kcbzww

last process to post me: c000000039496148 1 22

last post sent: 0 0 121

last post sent-location: kcbzww

last process posted by me: c000000039496148 1 22

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: c000000039529928

O/S info: user: oracle, term: UNKNOWN, ospid: 11880

OSD pid info: Unix process pid: 11880, image: oracle@ap-machine-

*** 2015-12-22 10:34:53.431

Short stack dump:

ksdxfstk()+48<-ksdxcb()+1200<-sspuser()+368<-<kernel><-_ pw_wait()+48<-pw_wait() +128<-sskgpwwait()+384<-skgpwwait()+208<-ksliwat()+1728<-kslwaitns_timed()+112<-kskthbwt()+400<-kslwait()+640<-ktugur()+4416<-ktuchg()+1280<-ktbchg2()+704<-kdiins0()+267536<-kdiinsp()+320<-kauxsin()+2960<-insidx()+1744<-insrow()+1440<-insdrv()+960<-inscovexe()+1408<-insExecStmtExecIniEngine()+176<-insexe()+1040<-opiexe()+13776<-kpoal8()+3808<-opiodr()+2144<-ttcpip()+1680<-opitsk()+2368<-opiino()+1664<-opiodr()+2144<-opidrv()+1248<-sou2o()+240<-opimai_real()+496<-main()+240<-main_opd_entry()+80

----------------------------------------

SO: c0000000396d80d8, type: 4, owner: c00000003949b948, flag: INIT/-/-/0x00

(session) sid: 315 trans: c0000000355b2a28, creator: c00000003949b948, flag: (100041) USR/- BSY/-/-/-/-/-

DID: 0001-0013-00000027, short-term DID: 0000-0000-00000000

txn branch: 0000000000000000

oct: 2, prv: 0, sql: c0000000384bad50, psql: c0000000384bad50, user: 33/XXDB

service name: xxdb

O/S info: user: , term: , ospid: 1234, machine: rvwapp2-1

program:

waiting for 'db file sequential read' wait_time=0, seconds since wait started=0

file#=c, block#=2f359, blocks=1

blocking sess=0x0000000000000000 seq=42271

Dumping Session Wait History

for 'undo segment extension' count=1 wait_time=2 min 45 sec

segment#=6, =0, =0

for 'buffer busy waits' count=1 wait_time=0.000009 sec

file#=2, block#=59, class#=1b

for 'SQL*Net message from client' count=1 wait_time=0.000087 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message to client' count=1 wait_time=0.000001 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message from client' count=1 wait_time=0.000086 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message to client' count=1 wait_time=0.000001 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message from client' count=1 wait_time=0.000086 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message to client' count=1 wait_time=0.000001 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message from client' count=1 wait_time=0.000087 sec

driver id=28444553, #bytes=1, =0

for 'SQL*Net message to client' count=1 wait_time=0.000001 sec

driver id=28444553, #bytes=1, =0

Sampled Session History of session 315 serial 4544

---------------------------------------------------

The sampled session history is constructed by sampling

the target session every 1 second. The sampling process

captures at each sample if the session is in a non-idle wait,

an idle wait, or not in a wait. If the session is in a

non-idle wait then one interval is shown for all the samples

the session was in the same non-idle wait. If the

session is in an idle wait or not in a wait for

consecutive samples then one interval is shown for all

the consecutive samples. Though we display these consecutive

samples in a single interval the session may NOT be continuously

idle or not in a wait (the sampling process does not know).

The history is displayed in reverse chronological order.

sample interval: 1 sec, max history 120 sec

---------------------------------------------------

[120 samples, 10:32:52 - 10:34:53]

waited for 'undo segment extension', seq_num: 42270

p1: 'segment#'=0x6

p2: ''=0x0

p3: ''=0x0

time_waited: >= 120 sec (still in wait)

---------------------------------------------------

Sampled Session History Summary:

longest_non_idle_wait: 'undo segment extension'

[120 samples, 10:32:52 - 10:34:53]

time_waited: >= 120 sec (still in wait)

可以看到：

進程在被 ORADEBUG 間接喚醒后，不再等待 undo segment extension, 而是做 ”

PROCESS 8:

----------------------------------------

SO: c000000039496148, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00

(process) Oracle pid=8, calls cur/top: c00000003971e868/c00000003971e868, flag: (16) SYSTEM

int error: 0, call error: 0, sess error: 0, txn error 0

(post info) last post received: 0 0 121

last post received-location: kcbzww

last process to post me: c0000000394a0948 211 0

last post sent: 0 0 24

last post sent-location: ksasnd

last process posted by me: c000000039495148 1 6

(latch info) wait_event=0 bits=0

Process Group: DEFAULT, pseudo proc: c000000039529928

O/S info: user: oracle, term: UNKNOWN, ospid: 10072

OSD pid info: Unix process pid: 10072, image: oracle@ap-machine- (SMON)

Short stack dump:

ksdxfstk()+48<-ksdxcb()+1200<-sspuser()+368<-<kernel><-_pw_wait()+48<-pw_wait()+352<-sskgpwwait()+384<-skgpwwait()+208<-ksliwat()+1728<-kslwaitns_timed()+112<-kskthbwt()+400<-kslwait()+640<-ktmmon()+1168<-ktmSmonMain()+64<-ksbrdp()+2368<-opirip()+1184<-opidrv()+1184<-sou2o()+240<-opimai_real()+336<-main()+240<-main_opd_entry()+80

----------------------------------------

----------------------------------------

SO: c0000000396ead68, type: 4, owner: c000000039496148, flag: INIT/-/-/0x00

(session) sid: 329 trans: 0000000000000000, creator: c000000039496148, flag: (100051) USR/- BSY/-/-/-/-/-

DID: 0001-0008-00000002, short-term DID: 0000-0000-00000000

txn branch: 0000000000000000

oct: 0, prv: 0, sql: 0000000000000000, psql: 0000000000000000, user: 0/SYS

service name: SYS$BACKGROUND

waiting for 'smon timer' wait_time=0, seconds since wait started=3109

sleep time=12c, failed=0, =0

blocking sess=0x0000000000000000 seq=7382

Dumping Session Wait History

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 11 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

for 'smon timer' count=1 wait_time=4 min 53 sec

sleep time=12c, failed=0, =0

Sampled Session History of session 329 serial 1


可以看到， SMON 進程在等“ SMON TIMER ”，即空閑等待。


這說明 SMON 沒有因為阻塞在異常的等待上，導(dǎo)致無法騰出時間來處理前臺進程發(fā)過來的 undo segment 擴展請求。


> > > >

操作系統(tǒng)

The problem is a defect in the pw_wait() O/S system call.
On HP-UX 11.31, this is caused by a problem with the HP-UX scheduler patch PHKL_37456:

PHKL_37456 scheduler cumulative patch

即 HPUX11.31 上，當(dāng)安裝了 PHKL_37456 這個調(diào)度補丁后，操作系統(tǒng)調(diào)用 pw_wait 存在缺陷，導(dǎo)致進程無法從 post/wait 中被喚醒，解決方案是 Solution: on 11.31 install PHKL_38397 or later equivalent.


以下是官網(wǎng)原文


Processes Hang Waiting on 'cursor: pin S wait on X' (and other Wait Events) on HP-UX 11.23 and 11.31 Itanium Systems (Doc ID 580273.1)

In this Document

Symptoms

Changes

Cause

Solution

APPLIES TO:

Oracle Database - Enterprise Edition - Version 9.2.0.1 and later
HP-UX Itanium
***Checked for relevance on 23-JUL-2013***

  • cursor: pin S wait on X (10g wait)

  • kksfbc child completion

  • SGA: allocation forcing component growth

    • There is no blocker process.
    The variety in wait events is explained by the fact that the underlying issue is with the pw_wait() HP-UX system call.
    Therefore, the above list is not exhaustive, use the pstack output below to match the problem in all cases.
    The problem is commonly seen on Parallel Execution Slave processes but can affect any Oracle process.
    A command to generate a systemstate, processstate, or errorstack dump e.g. via ALTER SESSION or oradebug command frees the hanging process.

    An example of the top of the call stack of an affected process, obtained using pstack:

    0: c0000000003e2ff0 : pw_wait() + 0x30 (/usr/lib/hpux64/libc.so.1)
    1: 4000000002e98a20 : pw_wait() + 0x80

  • Workaround: oradebug setospid+unlimit to free the hanging process:

    • 1.

  • Solution: on 11.31 install PHKL_38397 or later equivalent.

  • Solution: on 11.23 install PHKL_37809 or later equivalent.

    • Note: the patches whose names begin with PHKL_ are HP-UX patches. Please check with HP-UX support on the latest applicable patch numbers as such patches are regularly updated and superceded.


    3
    原因總結(jié)和建議

    > > > >

    INSERT INTO TABLE_NAME(COL1,COL2,COL3,COL4,COL5,COL6,COL7)VALUES(:1,:2,:3,:4,:5,:6,:7)

    之所以執(zhí)行不下去，不是因為死鎖，而是因為該會話即 SID=315 的會話 , 需要執(zhí)行 DML ，因此需要 UNDO SEGMENT 即回滾段來存儲前鏡像，但發(fā)現(xiàn)回滾段空間不足，需要通知 SMON 后臺進程來完成擴展的請求 , 但是長時間沒有獲得回滾段擴展成功與否的返回消息。前臺進程和 SMON 之間通過 POST/WAIT 進制來通訊。

    由于操作系統(tǒng) HPUX 調(diào)度的缺陷，具體來說是 pw_wait 系統(tǒng)調(diào)用 (post/wait) 存在缺陷，當(dāng) SMON 進程完成回滾段擴展后，消息返回時，前臺進程 SID=315 并沒有能被及時調(diào)度到 CPU 上繼續(xù)處理后續(xù)工作，即體現(xiàn)出來就是等待在“ undo segment extension “事件上等待，當(dāng)我們?nèi)藶槭褂? ORADEBUG 對 SID 315 收集信息并間接喚醒了該前臺進程后，前臺進行可以繼續(xù)往下工作，這更加印證了 SMON 已經(jīng)將消息已經(jīng)返回給前臺進程，只是由于操作系統(tǒng)調(diào)度進制的問題，未能即使將前臺進程調(diào)度到 CPU 上，拿到 UNDO 擴展成功的消息

    造成該故障的根本原因是操作系統(tǒng)調(diào)度機制的問題，該問題命中操作系統(tǒng) HPUX 上的已知缺陷。

    The problem is a defect in the pw_wait() O/S system call.
    On HP-UX 11.31, this is caused by a problem with the HP-UX scheduler patch PHKL_37456:

    PHKL_37456 scheduler cumulative patch

    即 HPUX11.31 上，當(dāng)安裝了 PHKL_37456 這個調(diào)度補丁后，操作系統(tǒng)調(diào)用 pw_wait 存在缺陷，導(dǎo)致進程無法從 post/wait 中被喚醒，解決方案是 Solution: on 11.31 install PHKL_38397 or later equivalent.


    > > > >   3.2 建議


    Solution: on 11.31 install PHKL_38397 or later equivalent.

    請系統(tǒng)管理員為操作系統(tǒng)安裝 PHKL_38397 補丁。


    本文是轉(zhuǎn)載中亦安圖的文章。

    向AI問一下細節(jié)

    免責(zé)聲明：本站發(fā)布的內(nèi)容（圖片、視頻和文字）以原創(chuàng)、轉(zhuǎn)載和分享為主，文章觀點不代表本網(wǎng)站立場，如果涉及侵權(quán)請聯(lián)系站長郵箱：is@yisu.com進行舉報，并提供相關(guān)證據(jù)，一經(jīng)查實，將立刻刪除涉嫌侵權(quán)內(nèi)容。

    AI
    助
    手