【案例】Oracle等待事件event enq: KO - fast object checkpoint解决办法

时间:2016-11-03 10:11   来源:Oracle研究中心   作者:HTZ   点击:

次

天萃荷净

Oracle研究中心案例分析：运维DBA反映业务系统缓慢查询等待事件发现fast checkpoint居多，分析event enq: KO - fast object checkpoint解决办法。

业务反应下发短信效率低，已经开始阻塞，要求分析一下数据库。

查看数据库等待事件

oracleplus.net> @we.sql

USERNMAE

LAST_CALL SESS_SERIAL BLOCK_SESS ROW_WAIT

I EVENT SEQ# OSPID COMMAND INST:SESS FILE#:OBJ#:BLOCK#:ROW#

– ————————- – ———————- —————– ———- ————— ———————-

1 log file sync HTZ.PW:0:7763 1364:29869:2222 UNKNOWN VALID:1:1153 0:-1:0:0

log file sync HTZ.PW:0:4357 6:38911:3743 UNKNOWN VALID:1:1153 0:-1:0:0

enq: KO – fast object che HTZ.PW:4927:19877 214:44705:5864 SELECT VALID:1:1249 22:56156347:139266:0

enq: KO – fast object che HTZ.PW:40:1654 1089:31179:18321 SELECT VALID:1:1249 1:75:22362:0

db file sequential read HTZ.PW:9:4887 33:25605:9941 SELECT NO HOLDER:: 22:56156362:28149:0

latch: cache buffers chai HTZ.PW:1:54 1267:4853:3952 UPDATE NOT IN WAIT:: 0:-1:0:0

db file sequential read HTZ.PW:0:12065 881:707:14867 INSERT NO HOLDER:: 40:56280929:633312:0

direct path read HTZ.PW:1116:43971 31:5141:14857 SELECT NOT IN WAIT:: 86:54108778:173189:0

enq: KO – fast object che HTZ.PW:87:47269 1063:11835:14849 SELECT VALID:1:1249 40:74444:64251:0

SQL*Net message from dbli HTZ.PW:38201603:1763 1262:14743:9604 UPDATE UNKNOWN:: 0:-1:0:0

SQL*Net message to client SYS:0:458 310:12461:521 SELECT NOT IN WAIT:: 1:37:46132:0

SQL*Net message from dbli HTZ.PW:38201604:42722 1156:33029:9602 UPDATE UNKNOWN:: 3:0:142092:0

enq: KO – fast object che HTZ.PW:35:10454 1468:36069:9939 SELECT VALID:1:1249 41:74457:228856:0

log file sync HTZ.PW:0:521 407:36635:3739 UNKNOWN VALID:1:1153 0:-1:0:0

log file sync HTZ.PW:0:12414 1354:58849:10187 UNKNOWN VALID:1:1153 56:0:625345:0

SQL*Net message from dbli HTZ.PW:38201605:33407 1367:50923:9606 UPDATE UNKNOWN:: 3:0:272:0

buffer busy waits HTZ.PW:0:55 971:18127:3853 SELECT NOT IN WAIT:: 56:0:6736:0

SQL*Net message from dbli HTZ.PW:38201606:3597 412:13075:9588 UNKNOWN UNKNOWN:: 3:0:296:0

I EVENT COUNT(*)

– —————————————- ———-

1 log file sync 5

SQL*Net message from dblink 4

enq: KO – fast object checkpoint 4

db file sequential read 2

SQL*Net message to client 1

buffer busy waits 1

latch: cache buffers chains 1

direct path read 1

这里发现数据库当才会话的个数相当的少，有一个异常的enq: KO – fast object checkpoint等待事件。

此等待事件主要是由于对象的fast checkpoint导致的，常见原因如：直接路径读导致的，特别是11G环境中，对大表默认情况下会启用直接路径读。根本原因是由于：IO性能低下导致的。

查看锁的信息

oracleplus.net> @block.sql Oracle oracleplus.net

STATUS

USERNAME sid:serial:os session STATE ID1:ID2 LMODE:QUEST CTIME EVENT

———- —————————— ———- ——— ——————– —– ——————–

Holder: HTZ:1249:1:6714 ACTIVE 65595:1 2||Row Share:NULL 93 rdbms ipc message

HTZ.PW Waiter: HTZ:1063:11835:14849 ACTIVE 65595:1 5||Shr Row Excl:6||E 93 enq: KO – fast objec

xclusive

Holder: HTZ:1249:1:6714 ACTIVE 65666:1 2||Row Share:NULL 41 rdbms ipc message

HTZ.PW Waiter: HTZ:214:44705:5864 ACTIVE 65666:1 5||Shr Row Excl:6||E 41 enq: KO – fast objec

xclusive

Holder: HTZ:1249:1:6714 ACTIVE 65771:1 2||Row Share:NULL 16 rdbms ipc message

HTZ.PW Waiter: HTZ:1089:31179:18321 ACTIVE 65771:1 5||Shr Row Excl:6||E 16 enq: KO – fast objec

xclusive

查看阻塞者信息

oracleplus.net> @print_table.sql

Enter value for query_sql: select * from v$session where sid=1249

SADDR : 0000000218B44C48

SID : 1249

SERIAL# : 1

AUDSID : 0

PADDR : 00000002186475D0

USER# : 0

USERNAME :

COMMAND : 0

OWNERID : 2147483644

TADDR :

LOCKWAIT :

STATUS : ACTIVE

SERVER : DEDICATED

SCHEMA# : 0

SCHEMANAME : SYS

OSUSER : oracle

PROCESS : 6714

MACHINE : htz.pw

PORT : 0

TERMINAL : UNKNOWN

PROGRAM : oracle@htz.pw (CKPT)

TYPE : BACKGROUND

这里可以看到是CKPT进程

查看IO信息

[root@htz.pw ~]# iostat -xm 5 100

avg-cpu: %user %nice %system %iowait %steal %idle

3.99 0.00 2.37 17.74 0.00 75.90

Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await svctm %util

sda 0.00 10.20 0.60 2.00 0.00 0.05 41.23 0.06 24.77 17.08 4.44

sda1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00

sda2 0.00 10.20 0.60 2.00 0.00 0.05 41.23 0.06 24.77 17.08 4.44

sdb 0.00 0.40 3.20 0.40 0.02 0.00 14.67 0.04 10.83 10.50 3.78

sdc 118.80 42.40 56.60 31.60 5.85 0.27 142.19 3.89 44.08 11.34 100.04

sdd 5.20 0.00 98.20 0.00 2.11 0.00 43.93 1.75 17.81 9.77 95.98

sde 0.00 19.80 41.20 15.60 0.32 0.14 16.56 0.72 12.60 9.56 54.28

sdf 0.00 63.80 6.40 46.80 0.05 0.43 18.41 0.94 17.61 15.66 83.30

dm-0 0.00 0.00 0.60 6.40 0.00 0.03 8.69 0.33 47.54 4.37 3.06

dm-1 0.00 0.00 0.00 5.80 0.00 0.02 8.00 0.13 23.14 2.41 1.40

dm-2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00

dm-3 0.00 0.00 47.60 146.00 0.37 0.57 9.92 3.25 16.75 5.15 99.80

dm-4 0.00 0.00 287.60 75.00 7.92 0.29 46.42 13.47 36.57 2.76 100.02

这里看到IO磁盘的%util达到了100%，但是IO的速度不达10M/S，这里我们需要看dm开头的磁盘，dm才是多路径软件聚合后的磁盘名

下面看一个很异常的

dm-4 0.00 0.00 4.00 3290.40 0.12 12.85 8.07 3689348813900497.50 5984.02 0.30 100.02

由于存储是共享的，其它的工作交由存储工程师去处理

查看alert日志

Fri Dec 05 13:38:50 2014

Thread 1 cannot allocate new log, sequence 52699

Private strand flush not complete

Current log# 7 seq# 52698 mem# 0: /htz/htz/redo07.log

Thread 1 advanced to log sequence 52699 (LGWR switch)

Current log# 3 seq# 52699 mem# 0: /htz/htz/redo03.log

这里看到不能分配日志。

解决方案：

1，使用异常IO(11G可以通过V$IOSTAT_FILE中的ASYNCH_IO/ACCESS_METHOD来判断是否启用异步IO与异步IO的方式)。

2，增加日志组(增加后效果有一点提供)

3，使用更好的存储(一小时后观察，IO性能已经恢复正常，业务也正常)

……..

本文固定链接: http://www.htz.pw/2014/12/05/event-enq-ko-fast-object-checkpoint.html | 认真就输

--------------------------------------ORACLE-DBA----------------------------------------

最权威、专业的Oracle案例资源汇总之【案例】Oracle等待事件event enq: KO - fast object checkpoint解决办法