【中亦安图】小机上运行Oracle需要注意的进程调度bug(1)

第一章技术人生系列 · 我和数据中心的故事——第一期

第一期：技术人生系列 · 我和数据中心的故事（第一期）小机上运行Oracle需要注意的进程调度bug。

2016-01-11 小y 中亦安图

前言

小y这个名字，是笔者临时想的一个笔名，其实没有什么特殊的含义，就暂且用他来代表我们这些为各个数据中心奉献自己青春的一群默默无闻的IT人吧！

小y今天要和大家分享的是一个疑难杂症的分析过程。如果大家有耐心读完这个案例，一定会或多或少有些收获，也就没浪费小y的一片苦心。

具体来说是一个应用间歇性局部挂起案例的分析过程，报告中将对Oracle数据库稳定运行的共性风险和隐患作出提醒。

1问题描述

据客户反映，应用会间歇性出现异常，包括insert单条记录在内的操作长时间无法完成，按照客户的说法，数据库内可能有“死锁”现象，希望能够找到问题发生的根因，提出解决方案，以避免问题再次发生。

2015年12月23日，问题再次发生，客户再次联系到小y，小y通过远程方式进行了信息收集和故障诊断，最终定位了问题的根本原因。

环境介绍：

操作系统 HPUX IA64 B.11.31

数据库 ORACLE 10.2.0.5,单实例

2分析过程

>>> 2.1 异常时刻数据库出现异常等待

可以看到：

有2个会话在等待行锁（拿不到事务锁，需要一直等待），另外有一个会话在等待“undo segment extension”。

>>>> 2.2 梳理异常等待之间的关系

1）分析行锁等待的阻塞者

可以看到：

SID 285/290的两个会话都是被SID=315的会话阻塞了，他们在等待行锁，时间已经超过60000秒。

2）查看阻塞者SID=315在做什么

可以看到：

SID=315的会话阻塞了其他两个会话，他本身也处于一个资源的等待上，在等待“undo segment extension”,已经等了70384秒了！该等待事件没有阻塞者。

3）SID=315在执行的SQL语句

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

>>>> 2.3 什么是“undo segment extension”等待事件

“undo segment extension”即等待回滚段扩展完成。当执行增删改等操作时，数据库需要回滚段来存储前镜像，当回滚段空间不足时，则需要扩展。

具体来说，undo segment的扩展或者回收（extend / shrink）都是前台进程通过通知SMON后台进程来完成的。

发出下列命令查看undo的使用情况，UNDO表有空有1个文件27750M，其中目前活动的值有8M，未过undo retention的1892M，过了undo retention的有40M未发现异常。

>>>> 2.4 收集数据库hanganalyze和systemstate信息

发出下列命令异常时候的hanganalyze和systemstate信息

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

>>>> 2.5 问题在收集信息后自动解决

在发出上述命令收集相关信息后，再次检查，发现数据库异常等待居然已经自动解决掉了。

从原理和经验分析，这是因为oradebug 在收集systemstate dump时，其中会调用dbx等OS命令去做进程堆栈的打印，此时会将进行wakeup(唤醒)。

如下所示

>>>> 2.6 获得SID：315会话的活动会话历史

可以看到，确实一直在等待undo segment extension

>>>> 2.7 分析systemstate dump定位问题根因

其中SID=315的会话在等待”undo segment extension”,该会话对应PROCESS 19 SSD当中的信息如下:

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<-<-_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,而是做” db file sequential read”。

从前面的分析得知，“undo segment extension”即等待回滚段扩展完成。当执行增删改等操作时，数据库需要回滚段来存储前镜像，当回滚段空间不足时，则需要扩展。具体来说，undo segment的扩展或者回收（extend / shrink）都是前台进程通过通知SMON后台进程来完成的。CallStack堆栈的调用中，最后停在“pw_wait”的调用上，即说明在等待SMON返回扩展UNDO SEGMENT成功与否的消息。

因此，我们需要查看SMON进程的状态。

检查SMON的信息如下：

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<-<-_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