oracle 频繁io,oracle IO性能问题故障诊断案例

一业务系统在白天业务时间出现了严重了IO性能问题,下面是下午业务高峰时间(3-5)的awr报告

从等待事件来看主要都是与IO相关

从上面可以看到除了几个语句的逻辑读很高，其实物理不是很高,每秒产生的重做日志以及物理读也不高.

检查磁盘IO

rx6600-1:[/]#sar -d 1 10

HP-UX rx6600-1 B.11.23 U ia64 07/15/14

16:18:45 device %busy avque r+w/s blks/s avwait avserv

16:18:46 c39t0d3 100.00 0.50 18 1130 0.00 132.11

c41t0d3 83.50 0.50 6 450 0.00 290.78

16:18:47 c3t0d0 0.99 0.50 2 63 0.00 7.12

c39t0d3 91.09 0.50 10 982 0.00 115.53

c41t0d3 100.00 0.50 12 586 0.00 291.67

16:18:48 c3t0d0 3.03 0.50 2 32 0.00 15.93

c39t0d3 100.00 0.50 9 1034 0.00 139.76

c41t0d3 92.93 0.50 7 388 0.00 310.07

16:18:49 c3t0d0 2.00 0.50 4 64 0.00 19.59

c39t0d3 100.00 0.50 12 1088 0.00 127.33

c41t0d3 86.00 0.50 8 416 0.00 251.32

16:18:50 c3t0d0 1.01 0.50 1 2 0.00 8.99

c39t0d3 100.00 0.50 16 954 0.00 117.10

c41t0d3 100.00 0.50 9 614 0.00 295.52

16:18:51 c3t0d0 0.99 0.50 1 8 0.00 10.60

c39t0d3 93.07 0.50 17 913 0.00 110.59

c41t0d3 100.00 0.50 9 350 0.00 326.92

16:18:52 c39t0d3 100.00 0.50 21 1168 0.00 127.22

c41t0d3 88.00 0.50 11 544 0.00 252.08

16:18:53 c3t0d0 2.02 0.50 3 48 0.00 18.51

c39t0d3 88.89 0.50 19 1164 0.00 98.25

c41t0d3 100.00 0.50 11 630 0.00 324.39

16:18:54 c3t0d0 3.00 0.50 3 20 0.00 12.39

c39t0d3 95.00 0.50 20 954 0.00 131.90

c41t0d3 81.00 0.50 9 610 0.00 289.05

16:18:55 c3t0d0 9.00 0.50 11 134 0.00 8.62

c39t0d3 100.00 0.50 19 1090 0.00 137.20

c41t0d3 100.00 0.50 11 512 0.00 327.16

Average c39t0d3 99.50 0.50 16 1048 0.00 123.38

Average c41t0d3 100.00 0.50 9 510 0.00 296.44

Average c3t0d0 2.20 0.50 3 37 0.00 12.28

rx6600-1:[/]#sar -d 1 10

HP-UX rx6600-1 B.11.23 U ia64 07/15/14

16:20:04 device %busy avque r+w/s blks/s avwait avserv

16:20:05 c3t0d0 1.00 0.50 1 16 0.00 8.33

c39t0d3 98.00 0.50 16 928 0.00 114.86

c41t0d3 98.00 0.50 10 684 0.00 266.43

16:20:06 c3t0d0 1.98 0.50 4 81 0.00 8.57

c39t0d3 93.07 0.50 19 1251 0.00 128.81

c41t0d3 91.09 0.50 6 475 0.00 365.83

16:20:07 c3t0d0 2.00 0.50 3 48 0.00 5.87

c39t0d3 98.00 0.50 23 1216 0.00 113.66

c41t0d3 98.00 0.50 8 576 0.00 307.92

16:20:08 c3t0d0 1.00 0.50 2 32 0.00 5.36

c39t0d3 100.00 0.50 21 1132 0.00 118.47

c41t0d3 100.00 0.50 7 592 0.00 300.71

16:20:09 c3t0d0 6.00 0.58 13 194 2.22 26.05

c39t0d3 89.00 0.50 17 1152 0.00 123.54

c41t0d3 87.00 0.50 8 512 0.00 298.26

16:20:10 c3t0d0 3.00 0.50 6 96 0.00 22.78

c39t0d3 85.00 0.50 17 1136 0.00 114.79

c41t0d3 98.00 0.50 9 592 0.00 252.52

16:20:11 c3t0d0 1.00 0.50 1 2 0.00 8.04

c39t0d3 100.00 0.50 17 1216 0.00 138.04

c41t0d3 100.00 0.50 12 672 0.00 291.69

16:20:12 c3t0d0 2.00 0.50 3 34 0.00 9.24

c39t0d3 99.00 0.50 16 1024 0.00 122.11

c41t0d3 88.00 0.50 9 476 0.00 299.79

16:20:13 c39t0d3 91.00 0.50 18 1024 0.00 111.77

c41t0d3 92.00 0.50 3 384 0.00 396.25

16:20:14 c39t0d3 99.00 0.50 17 892 0.00 132.15

c41t0d3 100.00 0.50 10 608 0.00 233.54

Average c3t0d0 1.80 0.53 3 50 0.87 17.64

Average c39t0d3 96.00 0.50 18 1097 0.00 121.54

Average c41t0d3 100.00 0.50 8 557 0.00 290.35

在业务人员下班后重启的双机软件，但在启动数据库时停在了Completed redo application这一步

SQL> startup

ORACLE instance started.

Total System Global Area 1.0318E+10 bytes

Fixed Size 2073176 bytes

Variable Size 3238006184 bytes

Database Buffers 7063207936 bytes

Redo Buffers 14700544 bytes

Database mounted.

从alert.log文件中可以看到如下信息:

Tue Jul 15 22:23:29 2014

Starting ORACLE instance (normal)

LICENSE_MAX_SESSION = 0

LICENSE_SESSIONS_WARNING = 0

Picked latch-free SCN scheme 3

Autotune of undo retention is turned on.

IMODE=BR

ILAT =61

LICENSE_MAX_USERS = 0

SYS auditing is disabled

ksdpec: called for event 13740 prior to event group initialization

Starting up ORACLE RDBMS Version: 10.2.0.4.0.

System parameters with non-default values:

processes = 500

sessions = 555

__shared_pool_size = 3154116608

__large_pool_size = 16777216

__java_pool_size = 33554432

__streams_pool_size = 33554432

sga_target = 10317987840

control_files = /sx_data/ORCL/control01.ctl, /sx_data/ORCL/control02.ctl, /sx_data/ORCL/control03.ctl

db_block_size = 8192

__db_cache_size = 7063207936

compatible = 10.2.0.3.0

log_archive_dest_1 = LOCATION=/sx_data/arch_ORCL/

log_archive_format = %t_%s_%r.dbf

db_file_multiblock_read_count= 16

db_recovery_file_dest = /oracle/flash_recovery_area

db_recovery_file_dest_size= 2147483648

undo_management = AUTO

undo_tablespace = UNDOTBS1

undo_retention = 39600

fast_start_parallel_rollback= FALSE

remote_login_passwordfile= EXCLUSIVE

db_domain =

dispatchers = (PROTOCOL=TCP) (SERVICE=ORCLXDB)

local_listener = ORCL

job_queue_processes = 10

background_dump_dest = /oracle/admin/ORCL/bdump

user_dump_dest = /oracle/admin/ORCL/udump

core_dump_dest = /oracle/admin/ORCL/cdump

audit_file_dest = /oracle/admin/ORCL/adump

db_name = ORCL

open_cursors = 2000

optimizer_index_cost_adj = 20

optimizer_index_caching = 90

pga_aggregate_target = 2576351232

PMON started with pid=2, OS id=13613

PSP0 started with pid=3, OS id=13615

MMAN started with pid=4, OS id=13617

DBW0 started with pid=5, OS id=13619

LGWR started with pid=6, OS id=13621

CKPT started with pid=7, OS id=13623

SMON started with pid=8, OS id=13625

RECO started with pid=9, OS id=13627

CJQ0 started with pid=10, OS id=13629

MMON started with pid=11, OS id=13631

Tue Jul 15 22:23:30 2014

starting up 1 dispatcher(s) for network address '(ADDRESS=(PARTIAL=YES)(PROTOCOL=TCP))'...

MMNL started with pid=12, OS id=13635

Tue Jul 15 22:23:30 2014

starting up 1 shared server(s) ...

Tue Jul 15 22:23:31 2014

ALTER DATABASE MOUNT

Tue Jul 15 22:23:39 2014

Setting recovery target incarnation to 2

Tue Jul 15 22:23:42 2014

Successful mount of redo thread 1, with mount id 1380841571

Tue Jul 15 22:23:42 2014

Database mounted in Exclusive Mode

Completed: ALTER DATABASE MOUNT

Tue Jul 15 22:23:42 2014

ALTER DATABASE OPEN

Tue Jul 15 22:23:47 2014

Beginning crash recovery of 1 threads

parallel recovery started with 7 processes

Tue Jul 15 22:23:50 2014

Started redo scan

Tue Jul 15 22:23:52 2014

Completed redo scan

336597 redo blocks read, 78835 data blocks need recovery

Tue Jul 15 22:23:52 2014

Started redo application at

Thread 1: logseq 2270, block 29

Tue Jul 15 22:23:53 2014

Recovery of Online Redo Log: Thread 1 Group 4 Seq 2270 Reading mem 0

Mem# 0: /sx_data/ORCL/redo04.log

Tue Jul 15 22:23:58 2014

Completed redo application

一直停在Completed redo application这，而这时的等待事件是checkpoint complete开始以为是并行恢复慢造成的，就查询了v$transaction，v$fast_start_transactions但视图中并没有进行恢复操作的事务存在.后来咨询了老熊，老熊说检查一下IO情况看是不是存储出问题了，如是再次检查存储IO性能:

rx6600-1:[/]#sar 1 10

HP-UX rx6600-1 B.11.23 U ia64 07/15/14

22:36:41 %usr %sys %wio %idle

22:36:42 2 2 12 84

22:36:43 1 0 12 87

22:36:44 0 0 17 83

22:36:45 0 0 13 87

22:36:46 0 1 12 87

22:36:47 2 1 13 84

22:36:48 1 1 16 82

22:36:49 0 0 12 88

22:36:50 0 0 12 88

22:36:51 0 0 22 78

Average 1 0 14 85

从上面可以看到现在实际上并没有业务在跑居然还存在IO等待这是不正常的

rx6600-2:[/]#bdf

Filesystem kbytes used avail %used Mounted on

/dev/vg00/lvol3 983040 422504 556176 43% /

/dev/vg00/lvol1 1835008 135048 1686776 7% /stand

/dev/vg00/lvol8 8912896 8535352 374824 96% /var

/dev/vg00/lvol7 7962624 2762312 5159704 35% /usr

/dev/vg00/lvol4 524288 83192 437784 16% /tmp

/dev/vg00/tmplv 2064384 93512 1847942 5% /oratmp

/dev/vg00/orasoft 10256384 3144652 6668390 32% /orasoft

/dev/vg00/oracle 20480000 5480497 14062042 28% /oracle

/dev/vg00/lvol6 9076736 5206384 3840128 58% /opt

/dev/vg00/lvol5 131072 25472 104824 20% /home

/dev/cwjcvg/cwjc_datalv

414973952 134188114 263239842 34% /cwjc_data

/dev/sxvg/sx_datalv

624689152 298665485 305654147 49% /sx_data

rx6600-2:[/]#time dd if=/dev/zero of=/var/test bs=8k count=100000

下面对小机自身的磁盘进行IO测试写800M的数据只要12秒左右

msgcnt 2 vxfs: mesg 001: vx_nospace - /dev/vg00/lvol8 file system full (1 block extent)

I/O error

47185+0 records in

47184+1 records out

real 11.7

user 0.0

sys 0.8

但是对EMC存储进行IO测试写800M的数据只要30多分还没有完成

rx6600-2:[/]#time dd if=/dev/zero of=/sx_data/test bs=8k count=100000

711856+0 records in

711855+0 records out

real 30:58.4

user 0.5

sys 13.0

这明显的是存储出了问题,后面得知管理人员早上10点多发现了存储有一个磁盘损坏了，存储做的raid 5,有热备盘.而且还有上百G的数据进行存储级的同步.与出现性能问题的时间一至。

到此问题原因找到了解决起来也就简单了.幸亏问题解决了，第二天有大领导来检查要不就.......哈哈