刚下楼，电话就响了，是阿伟的，一看知道准没好事。
这家伙，上次帮他解决几个问题的钱还没给我呢，还倒贴了车费。谁叫他是朋友呢，认了。
果然，他们正在谈维护合同的一个客户，今天系统变得很慢，希望得到帮助。而现在正处于拿下这个单子的关键时期，希望我能过去支援一下。
我问他系统怎么回事，据客户给他的描述，早上客户在建一个索引，系统就慢得不行了，所有日常工作都受到了影响。
照例，我问了一下系统资源的使用情况，据他说现在好几个盘都是busy 100%,WIO也比较高，将近40%。
听完大概明白慢的原因了，系统估计存在不少的全表扫描，所以盘很忙。
于是让他检查了一下gv$session_wait，发现了大量的db file scattered read和gc buffer busy。
看来应用并没有针对RAC系统做设计，而是单纯的采用了load balance.
另外，这个客户的系统的是AIX 5.3上的ORACLE RAC 10.2.0.2,2个节点，用了ASM。
我想了一下，系统是今天早上才突然出现这个情况的。针对这个情况的描述，基本可以确定为执行计划发生了变化。
10g上创建索引时会自动收集统计信息，相比9i来说是一个大的进步。
9i下如果创建完索引没有及时收集统计信息，例如只是create index而未采用create index ..compute statistics，是可能会造成原有语句的执行计划发生改变的。
问题是据阿伟的描述，现在索引还在创建过程中，而不是已经创建完了。所以按理应该不存在新建索引导致执行计划变慢的情况才对啊。
不想了，到现场了再说,先干好自己手上的的活吧。
中间又来了几次电话催，晕，我总不能请假跑出去吧，看来客户把他逼得很紧。
好不容易等到中午11点下班，打车还是坐300呢？从南三环到北三环，打车怎么也要60了，还是300吧，才4毛钱。
再说打车钱估计也是我自己倒贴，现在赚钱不容易啊，一路想着就过了天桥，今天老天爷还算配合，678倒了一站到了草桥，300在草桥是始发站，因此很顺利的找到了一个座位,爱死300了.
好不容易找到地方，已经全身是汗了。阿伟把我接进去，刚坐下来，客户就说了，能否在一个小时内搞定，否则下午的工作还是受到影响，今天他们领导已经追问过好几次了，问到底什么时候能好。我笑了笑，‘尽力吧。’
[@more@]1.2.1 TOPAS检查系统资源情况$ topas
Topas Monitor for host: HOST_A EVENTS/QUEUES FILE/TTY
Fri Jul 3 12:18:37 2009 Interval: 2 Cswitch 6263 Readch 3116.0K
Syscall 51407 Writech 11115
Kernel 6.4 |## | Reads 680 Rawin 0
User 11.5 |#### | Writes 41 Ttyout 356
Wait 31.4 |######### | Forks 26 Igets 0
Idle 50.7 |############### | Execs 26 Namei 1043
Runqueue 2.0 Dirblk 0
Network KBPS I-Pack O-Pack KB-In KB-Out Waitqueue 0.0
en1 4758.7 2375.0 3425.0 1645.6 3113.1
en0 2.7 11.0 8.5 1.0 1.7 PAGING MEMORY
lo0 0.1 1.0 1.0 0.0 0.0 Faults 4506 Real,MB 7936
Steals 0 % Comp 48.8
Disk Busy% KBPS TPS KB-Read KB-Writ PgspIn 0 % Noncomp 48.7
hdisk4 99.5 7414.8 202.0 7412.0 2.8 PgspOut 0 % Client 48.7
hdisk8 98.5 6476.0 147.0 6476.0 0.0 PageIn 0
hdisk9 97.0 6284.0 171.0 6276.0 8.0 PageOut 0 PAGING SPACE
hdisk3 17.0 2.5 3.0 2.0 0.5 Sios 0 Size,MB 8192
dac3 0.0 0.0 0.0 0.0 0.0 % Used 27.9
hdisk2 0.0 0.0 0.0 0.0 0.0 NFS (calls/sec) % Free 72.0
dac0 0.0 0.0 0.0 0.0 0.0 ServerV2 0
hdisk1 0.0 0.0 0.0 0.0 0.0 ClientV2 0 Press:
hdisk5 0.0 0.0 0.0 0.0 0.0 ServerV3 0 “h” for help
hdisk0 0.0 0.0 0.0 0.0 0.0 ClientV3 0 “q” to quit
hdisk6 0.0 0.0 0.0 0.0 0.0
Name PID CPU% PgSp Owner
oracle 737384 1.9 18.3 oracle
oracle 684162 1.9 18.4 oracle
oracle 1695758 0.8 8.0 oracle
oracle 1020066 0.7 6.6 oracle
oracle 979084 0.5 8.1 oracle
oracle 934028 0.5 8.7 oracle
oracle 802940 0.5 8.7 oracle
oracle 1646764 0.4 8.5 oracle
可以看到，系统WAIT IO达到30%，hdisk4 hdisk8 hdisk8的繁忙程度达到95%以上。eth1是private network,流量达到5M/秒。
系统中消耗最大CPU的进程仅为1.9%,没有消耗CPU很大的进程
初步判断为数据库中存在大量全表扫描的语句，并且节点间块传输很频繁，导致系统性能变慢。
1.2.2 检查ORACLE数据库的资源等待情况
SQL> select sid,event,p1,p2,seconds_in_wait from v$session_wait where event not like ‘%SQL%’ and event not like ‘%rdbms%’ and event not like ‘%message%’ and event not like ‘%Streams AQ%’ AND EVENT NOT LIKE ‘%slave%’ order by event;
SID EVENT P1 P2 SECONDS_IN_WAIT
———- —————————————- ———- ———- —————
1633 ASM background timer 0 0 14807
1654 DIAG idle wait 1 1 526787
1413 db file scattered read 10 14770 0
1565 db file scattered read 13 265086 0
1555 db file scattered read 7 1656962 0
1528 db file scattered read 11 2362149 0
1523 db file scattered read 9 2750922 0
1472 db file scattered read 7 3760416 0
1466 db file sequential read 7 3733274 0
1455 db file sequential read 11 2077697 0
1471 db file sequential read 7 3773789 0
1475 gc buffer busy 7 3760416 0
1597 gc buffer busy 7 3760416 0
1583 gc buffer busy 7 3773789 0
1513 gc buffer busy 7 3760416 0
1499 gc buffer busy 7 3760416 0
1598 gc buffer busy 7 3773789 0
1497 gc cr multi block request 10 1685761 0
1655 pmon timer 300 0 72250
1406 read by other session 11 2077697 0
1457 read by other session 11 2077697 0
1554 read by other session 11 2077697 0
1551 read by other session 11 2077697 0
1538 read by other session 7 1656962 0
1415 read by other session 11 2077697 0
1518 read by other session 11 2077697 0
1508 read by other session 7 3760416 0
1500 read by other session 11 2362149 0
1478 read by other session 7 3760416 0
1469 read by other session 11 2362149 0
1468 read by other session 11 2077697 0
1463 read by other session 11 2077697 0
1522 read by other session 7 3760416 0
1440 read by other session 10 14770 0
1432 read by other session 11 2077697 0
1416 read by other session 11 2077697 0
1642 smon timer 300 0 15
37 rows selected.
可以看到，数据库中存在大量的db file scattered read和gc buffer busy等待。
db file scattered read指发生了全表扫描或索引快速全扫描。
gc buffer busy 指在RAC两个实例中出现了热块冲突，出现了GLOBAL CACHE的竞争。
1.2.3检查出现问题的语句
SQL> @sql_sid
Enter value for sid: 1413
old 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’&sid’) order by piece
new 1: select sql_text from v$sqltext where hash_value in(select decode(sql_hash_value,0,prev_hash_value,sql_hash_value) from v$session where sid=’1413′) order by piece
SQL_TEXT
—————————————————————-
SELECT COUNT(ID) FROM TABLE_A WHERE COL0107 =” || :B1
1.2.4 检查问题语句的执行计划
SQL> explain plan for SELECT COUNT(ID) FROM TABLE_A WHERE COL0107 =” || :B1;
Explained.
SQL> select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
——————————————————————————————————————————————————————————————————–
———————————————————————-
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)|
———————————————————————-
| 0 | SELECT STATEMENT | | 1 | 17 | 421K (1)|
| 1 | SORT AGGREGATE | | 1 | 17 | |
| 2 | TABLE ACCESS FULL| TABLE_A | 30631 | 508K| 421K (1)|
———————————————————————-
Note
—–
– ‘PLAN_TABLE’ is old version
可以看到该语句执行计划正是全表扫描，验证了一开始的判断。
由于大量的并发在两个INSTANCE上发生，因此发生了很多的全局热块冲突，这也是导致新索引建了3个小时还没建成功的最主要原因。
1.2.5 检查问题表上是否存在索引
SQL>select index_name,column_name,column_position from user_ind_columns where table_name=’TABLE_A’ order by 1,3
INDEX_NAME COLUMN_NAME COLUMN_POSITION
—————————— —————————— —————
INX_TABLE_A_127_129_18 COL0127 1
INX_TABLE_A_127_129_18 COL0129 2
INX_TABLE_A_127_129_18 COL0018 3
INX_TABLE_A_175_102_60 COL0175 1
INX_TABLE_A_175_102_60 COL0102 2
INX_TABLE_A_175_102_60 COL0060 3
INX_TABLE_A_60_97 COL0060 1
INX_TABLE_A_60_97 COL0097 2
INX_TABLE_A_COL129_3000_127 COL0129 1
INX_TABLE_A_COL129_3000_127 SYS_NC00197$ 2
INX_TABLE_A_COL129_3000_127 COL0127 3
PK_TABLE_A ID 1
可以看到列COL0107上不存在索引
1.2.6 定位问题产生的原因
为什么列COL0107上不存在索引呢？
经了解，列COL0107原来存在的索引A已经被干掉了。而现在正在建索引B，对应列COL0107和COL0018。索引B建了3个小时了还未成功。所以系统性能很慢。
问题找到了，
不应该先干掉索引A再建索引B
而应该是先建好索引B，再干掉索引A
1.2.7相应调整
1、取消正在建的索引B
表的大小
SQL> select sum(bytes)/1024/1024 from user_segments where segment_name=’TABLE_A’;
SUM(BYTES)/1024/1024
——————–
15341
SQL> select num_rows from user_tables where table_name=’TABLE_A’;
NUM_ROWS
———-
1623451
表大小为15G，约160万行。
正在建的索引B由于gc busy wait而巨慢无比。因此取消在建的索引B，换一个方式来建
2、屏蔽该语句
一般的处理办法是：停掉一个节点，把所有业务加到另外一个节点上，这样可避免gc busy wait，使索引建的更快。由于客户不同意,此次未采用该办法。
经了解，该语句实现的功能是:展现页面左边的功能菜单的一个数字,如还有N个单子未处理此处的N.也就是说,即使该数字N不展现也不影响系统的使用
并且该语句为存储过程中的一个SQL(很庆幸,该语句没有嵌入JAVA中,不然改动起来就麻烦了)，可注释掉而不影响系统的使用。注释掉后，也就不存在gc busy wait等待了，也可以使建索引更快。因此采用该办法
3、重新编译存储过程
重新编译的过程中hang住了，停止不动。查看等待事件，有不少的library cache pin.如下
1620 library cache pin 5.0440E+17 5.0440E+17 178
1564 library cache pin 5.0440E+17 5.0440E+17 102
1562 library cache pin 5.0440E+17 5.0440E+17 111
1491 library cache pin 5.0440E+17 5.0440E+17 42
1619 library cache pin 5.0440E+17 5.0440E+17 167
1485 library cache pin 5.0440E+17 5.0440E+17 166
1610 library cache pin 5.0440E+17 5.0440E+17 90
1462 library cache pin 5.0440E+17 5.0440E+17 54
1459 library cache pin 5.0440E+17 5.0440E+17 196
等待了196秒了。因为每个会话登陆的时候都会调用该存储过程，存储过程运行过程中又存在一个很慢的全表扫描和gc busy wait,由于编译不过去，等了好几分钟，越来越多的会话受到了影响。客户看到编译不过去，就急了。刚好现在是中休息午时间，于是我一拍脑袋‘这样吧，你们能否把weblogic停一分钟，一分钟就可以，之后的问题就OK了。不然什么时候好我也不敢打保票’。听我这么一说，他们一咬牙，去发临时维护公告了。之后weblogic刚停下来，存储过程马上编译成功。
Weblogic再起，应用已经不再受影响。只是展现‘还有N个单子未处理’里的N变成了0个。
1.2.8 系统恢复正常
由于该语句被屏蔽，已经不存在全局cache的竞争了。
重新设置并行4，建新索引B，和阿伟下楼买了瓶饮料，抽了会烟，回来的时候索引已经建成了。算了算，只花了15分钟接着恢复存储过程中被注释掉的原语句。
重新编译顺利完成。然后恢复索引并行度
SQL>
SQL> select DEGREE from user_indexes where index_name=’INX_TABLE_A_107_18′;
DEGREE
—————————————-
4
SQL> alter index INX_TABLE_A_107_18 parallel 1;
Index altered.
SQL> select DEGREE from user_indexes where index_name=’INX_TABLE_A_107_18′;
DEGREE
—————————————-
1
处理完毕后，系统一切恢复了正常
处理后数据库资源和主机情况如下
SQL> @wait
SID EVENT P1 P2 SECONDS_IN_WAIT
———- —————————————- ———- ———- —————
1633 ASM background timer 0 0 20869
1654 DIAG idle wait 1 1 532849
1513 db file sequential read 11 3717213 0
1498 gc current request 3 3656 0
1655 pmon timer 300 0 78312
1642 smon timer 300 0 104
$topas
Topas Monitor for host: HOST_A EVENTS/QUEUES FILE/TTY
Fri Jul 3 13:59:53 2009 Interval: 2 Cswitch 1780 Readch 1194.7K
Syscall 11849 Writech 18090
Kernel 2.0 |# | Reads 483 Rawin 0
User 4.0 |## | Writes 172 Ttyout 313
Wait 12.0 |#### | Forks 18 Igets 0
Idle 82.0 |######################## | Execs 18 Namei 688
Runqueue 0.0 Dirblk 0
Network KBPS I-Pack O-Pack KB-In KB-Out Waitqueue 0.0
en1 306.7 410.5 508.5 121.0 185.7
en0 39.8 162.5 148.5 15.1 24.6 PAGING MEMORY
lo0 0.1 1.0 1.0 0.0 0.0 Faults 2883 Real,MB 7936
Steals 0 % Comp 45.9
Disk Busy% KBPS TPS KB-Read KB-Writ PgspIn 0 % Noncomp 49.7
hdisk4 58.5 560.0 70.0 556.0 4.0 PgspOut 0 % Client 49.7
hdisk8 20.0 128.0 16.0 128.0 0.0 PageIn 0
hdisk9 19.0 160.2 19.5 156.0 4.2 PageOut 0 PAGING SPACE
hdisk3 0.5 1.5 2.0 1.2 0.2 Sios 0 Size,MB 8192
dac3 0.0 0.0 0.0 0.0 0.0 % Used 27.9
hdisk2 0.0 0.0 0.0 0.0 0.0 NFS (calls/sec) % Free 72.0
dac0 0.0 0.0 0.0 0.0 0.0 ServerV2 0
hdisk1 0.0 0.0 0.0 0.0 0.0 ClientV2 0 Press:
hdisk5 0.0 0.0 0.0 0.0 0.0 ServerV3 0 “h” for help
hdisk0 0.0 0.0 0.0 0.0 0.0 ClientV3 0 “q” to quit
hdisk6 0.0 0.0 0.0 0.0 0.0
Name PID CPU% PgSp Owner
oracle 1609876 1.5 8.5 oracle
oracle 1044598 0.9 11.0 oracle
oracle 737384 0.4 18.3 oracle
oracle 1237140 0.3 8.2 oracle
oracle 684162 0.3 18.4 oracle
oracle 974964 0.2 8.3 oracle
topas 843844 0.1 2.0 oracle
sh 491766 0.1 0.6 root
oracle 782462 0.1 6.6 oracle
oracle 720996 0.1 17.9 oracle
ocssd.bi 512078 0.0 25.0 oracle
oracle 593920 0.0 18.1 oracle
oracle 692378 0.0 18.3 oracle
Signal 2 received
可以看到系统资源恢复了正常。
应用测试，功能和速度都已恢复，问题解决。
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/11619497/viewspace-1029453/ ，如需转载，请注明出处，否则将追究法律责任。
-
博文量1
-
访问量1223
