一业务系统在白天业务时间出现了严重了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的数据进行存储级的同步.与出现性能问题的时间一至。
到此问题原因找到了解决起来也就简单了.幸亏问题解决了，第二天有大领导来检查要不就…….哈哈