当Web端查询某些特殊记录时Oracle就死掉[转]
一个系统最近频频死掉，症状是系统的CPU资源全部耗尽，系统环境如下：
双CPU、RAID5
Oracle 8.1.7.0.1
Weblogic 8.12
JAVA JDBC
FT的是Oracle和weblogic分别跑在RedHat 7.3上！也不知道是怎么想的！
字符集是ZHS16GBK
系统每隔一段时间就会出现CPU被99%占用，两个CPU空闲全为0，同时v$session_wait中的事件都是SQL*Net more data to client或SQL*Net message from client，alert.log中一切正常，StatsPack Report也没有发现任何的不正常，唯独SQL*Net事件等待次数非常的多！最初以为是不是内网的交换机出问题了，网络原因导致数据库问题？
后来经分析发现，当在Web客户端查询某个表的特定记录时，CPU占用率直线上升，而Web却查不到这个记录，但是这个记录在数据库表里的确存在！如果只有一个Web在查这个记录一个CPU被耗尽，如果开了多个Web查这个记录比如开5个，则这5个server process平均每个占20%左右CPU，同时两个CPU被耗尽，系统挂掉！但是在SQLPLUS里查询该记录没有任何的不正常！
针对一个号码的测试如下(X为隐藏部分)：
现在在Web客户端查询130XXXXXXXX这个号码，然后TOP里看到：
1:22pm up 1 day, 10:15, 4 users, load average: 0.98, 0.50, 0.33
106 processes: 104 sleeping, 2 running, 0 zombie, 0 stopped
CPU0 states: 15.0% user, 6.0% system, 0.0% nice, 78.4% idle
CPU1 states: 90.3% user, 1.4% system, 0.0% nice, 7.2% idle
Mem: 1031044K av, 1021448K used, 9596K free, 0K shrd, 46060K buff
Swap: 2097112K av, 37424K used, 2059688K free 860096K cached
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
5309 oracle 25 0 8832 8832 8252 R 99.0 0.8 0:59 oracle
3026 oracle 16 0 138M 138M 137M S 2.9 13.7 27:41 oracle
3028 oracle 16 0 144M 144M 143M S 2.5 14.3 28:59 oracle
3030 oracle 16 0 129M 129M 129M S 2.1 12.8 23:25 oracle
5193 oracle 15 0 1092 1092 856 S 2.1 0.1 1:39 top
5310 oracle 15 0 1092 1092 856 R 2.1 0.1 0:06 top
1234 oracle 15 0 136M 136M 135M S 0.3 13.5 1:27 oracle
3020 oracle 15 0 26004 25M 25380 S 0.3 2.5 3:48 oracle
1199 oracle 15 0 11788 11M 11256 S 0.1 1.1 0:13 oracle
1219 oracle 15 0 161M 161M 159M S 0.1 16.0 0:47 oracle
1 root 15 0 476 432 416 S 0.0 0.0 0:05 init
2 root 15 0 0 0 0 SW 0.0 0.0 0:00 keventd
3 root 34 19 0 0 0 SWN 0.0 0.0 0:00 ksoftirqd_CPU0
4 root 34 19 0 0 0 SWN 0.0 0.0 0:00 ksoftirqd_CPU1
5 root 15 0 0 0 0 SW 0.0 0.0 0:06 kswapd
6 root 25 0 0 0 0 SW 0.0 0.0 0:00 bdflush
7 root 15 0 0 0 0 SW 0.0 0.0 0:00 kupdated
8 root 25 0 0 0 0 SW 0.0 0.0 0:00 mdrecoveryd
16 root 15 0 0 0 0 SW 0.0 0.0 0:28 kjournald
95 root 16 0 0 0 0 SW 0.0 0.0 0:00 khubd
此时：
SQL> select a.sid,status from v$session a,v$process b where a.paddr=b.addr and b.spid=5309;
SID STATUS
---------- --------
29 ACTIVE
SQL> select sid,event,wait_time,seconds_in_wait,state from v$session_wait where sid=29;
SID EVENT WAIT_TIME SECONDS_IN_WAIT STATE
---------- ----------------------------- ---------- --------------- -------------------
29 SQL*Net more data to client -1 56 WAITED SHORT TIME
在SQLPLUS中：
SQL> select rowid,tel,name from teluser_tbl where tel='130XXXXXXXX';
ROWID TEL NAME
------------------ -------------------- ---------------------
AAAGHgAAFAAAU27AAA 130XXXXXXXX 某某华南工程有限公
显然这里"公"后面少了"司"
用PL/SQL Developer的"SQL窗口"查询，"司"是一个乱码：
TEL NAME
-------------------- ---------------------
130XXXXXXXX 某某华南工程有限公￠
用PL/SQL Developer的"命令窗口"查询，"公"后面是个"？"
问题就出在这个NAME字段上！如果把"公"后面的乱码删掉就没有任何问题了！系统就一切正常了！
我用dbms_system.set_sql_trace_in_session来跟踪PID=5309的session不会生成任何trace文件，也就是他的SQL已经执行完了，正在给Web返回数据，而Web始终接收不到这个数据，server process却悬在这里并且占用着大量的CPU资源。
我开7个IE窗口查询同样的手机号码，TOP如下：
7:46pm up 16:40, 4 users, load average: 7.81, 7.77, 7.62
105 processes: 96 sleeping, 9 running, 0 zombie, 0 stopped
CPU0 states: 96.4% user, 3.1% system, 0.0% nice, 0.0% idle
CPU1 states: 99.0% user, 1.0% system, 0.0% nice, 0.0% idle
Mem: 1031044K av, 1021452K used, 9592K free, 0K shrd, 36812K buff
Swap: 2097112K av, 42588K used, 2054524K free 881416K cached
PID USER PRI NI SIZE RSS SHARE STAT %CPU %MEM TIME COMMAND
3438 oracle 25 0 9592 9592 8988 R 32.7 0.9 21:29 oracle
3431 oracle 25 0 11900 11M 11300 R 32.3 1.1 21:57 oracle
3436 oracle 25 0 9136 9136 8552 R 30.9 0.8 20:51 oracle
3454 oracle 25 0 11916 11M 11260 R 24.5 1.1 14:39 oracle
3433 oracle 25 0 25028 24M 24376 R 23.5 2.4 16:06 oracle
3442 oracle 25 0 9092 9092 8508 R 23.5 0.8 15:51 oracle
3452 oracle 25 0 9056 9056 8472 R 23.5 0.8 14:36 oracle
这七个进程的EVENT全部是：SQL*Net more data to client
而WEB端不会有任何现在，也就是数据根本无法传递给WEB！！！
相应的SQL很简单，执行计划很好，成本也很低，我用TOP-PID+v$session、v$process、v$sqlarea抓到SQL，执行计划如下：
select rowid, t.tel,t.password,t.language,t.isfree,t.status,
t.enddate,t.endprocess,t.province,t.city,t.code,t.name,
t.address,t.postcode,t.companytel,t.familytel,t.fax,t.qq,
t.email,t.regdate,t.unregdate,t.logincount
from teluser_tbl t where t.tel ='133XXXXXXXX'
Elapsed: 00:00:00.45
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 TABLE ACCESS (BY INDEX ROWID) OF 'TELUSER_TBL'
2 1 INDEX (UNIQUE SCAN) OF 'SYS_C001736' (UNIQUE)
Statistics
----------------------------------------------------------
0 recursive calls
0 db block gets
4 consistent gets
0 physical reads
0 redo size
1628 bytes sent via SQL*Net to client
425 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
显然这是个不错执行计划。
把这个记录的block dump出来：
SQL> select file_id from dba_extents where segment_name='TELUSER_TBL';
FILE_ID
---------------
5
SQL> set serveroutput on
SQL> declare
2 a number;
3 begin
4 a:=dbms_rowid.rowid_block_number('AAAGHgAAFAAAU27AAA');
5 dbms_output.put_line(a);
6 end;
7 /
85435
PL/SQL 过程已成功完成。
SQL> declare
2 a number;
3 begin
4 a:=dbms_rowid.rowid_row_number('AAAGHgAAFAAAU27AAA');
5 dbms_output.put_line(a);
6 end;
7 /
0
PL/SQL 过程已成功完成。
SQL> alter system dump datafile 5 block 85435;
System altered.
TRACE文件如下（只贴row 0的）：
[oracle@sxdb udump]$ less ora_5301.trc
/opt/ora/admin/sxit/udump/ora_5301.trc
Oracle8i Enterprise Edition Release 8.1.7.0.1 - Production
With the Partitioning option
JServer Release 8.1.7.0.1 - Production
ORACLE_HOME = /opt/ora/8.1.7
System name: Linux
Node name: sxdb
Release: 2.4.18-3smp
Version: #1 SMP Thu Apr 18 07:27:31 EDT 2002
Machine: i686
Instance name: sxit
Redo thread mounted by this instance: 1
Oracle process number: 45
Unix process pid: 5301, image: oracle@sxdb (TNS V1-V3)
*** 2005-01-20 13:11:49.539
*** SESSION ID:(19.25087) 2005-01-20 13:11:49.538
Start dump data blocks tsn: 4 file#: 5 minblk 85435 maxblk 85435
buffer tsn: 4 rdba: 0x01414dbb (5/85435)
scn: 0x0000.058b81ce seq: 0x01 : 0x02 tail: 0x81ce0601
frmt: 0x02 chkval: 0x0000 type: 0x06=trans data
Block header dump: 0x01414dbb
Object id on Block? Y
seg/obj: 0x61e0 csc: 0x00.58b81cd itc: 1 : - typ: 1 - DATA
fsl: 0 fnx: 0x0 ver: 0x01
Itl Xid Uba Flag Lck Scn/Fsc
0x01 xid: 0x0003.031.0000aa4c uba: 0x00c003de.10f4.48 --U- 1 fsc 0x0000.058b81ce
data_block_dump
===============
tsiz: 0x1fb8
hsiz: 0x58
pbl: 0x09724644
bdba: 0x01414dbb
flag=-----------
ntab=1
nrow=35
frre=-1
fsbo=0x58
fseo=0x312
avsp=0x389
tosp=0x389
0xe:pti[0] nrow=35 offs=0
0x12:pri[0] offs=0x1edf
0x14:pri[1] offs=0x1e13
0x16:pri[2] offs=0x1d47
0x18:pri[3] offs=0x1c75
0x1a:pri[4] offs=0x1ba9
0x1c:pri[5] offs=0x1add
0x1e:pri[6] offs=0x1a11
0x20:pri[7] offs=0x1945
0x22:pri[8] offs=0x1879
0x24:pri[9] offs=0x17ad
0x26:pri[10] offs=0x16e2
0x28:pri[11] offs=0x1617
0x2a:pri[12] offs=0x154c
0x2c:pri[13] offs=0x1481
0x2e:pri[14] offs=0x13b6
0x30:pri[15] offs=0x12eb
0x32:pri[16] offs=0x1220
0x34:pri[17] offs=0x1155
0x36:pri[18] offs=0x108c
0x38:pri[19] offs=0xfc1
0x3a:pri[20] offs=0xef6
0x3c:pri[21] offs=0xe2d
0x3e:pri[22] offs=0xd62
0x40:pri[23] offs=0xc99
0x42:pri[24] offs=0xbce
0x44:pri[25] offs=0xb05
0x46:pri[26] offs=0xa39
0x48:pri[27] offs=0x96d
0x4a:pri[28] offs=0x8a5
0x4c:pri[29] offs=0x7d9
0x4e:pri[30] offs=0x70d
0x50:pri[31] offs=0x645
0x52:pri[32] offs=0x57d
0x54:pri[33] offs=0x3e2
0x56:pri[34] offs=0x312
block_row_dump:
tab 0, row 0, @0x1edf
tl: 217 fb: --H-FL-- lb: 0x0 cc: 50
col 0: [11] 31 33 30 3X 3X 3X 3X 3X 3X 3X 3X (X-是我隐藏的，避免泄露客户信息)
col 1: [ 6] 32 30 30 35 30 31
col 2: [ 4] b9 e3 b6 ab
col 3: [ 4] b7 f0 c9 bd
col 4: [ 4] 30 37 36 35
col 5: [19] c2 b7 c7 c5 bb aa c4 cf b9 a4 b3 cc d3 d0 cf de b9 ab cb ——这就是NAME字段一共存储了19个字节，这行记录的NAME是"某某华南工程有限公"一共9个字符，显然数据库多存储了一个字节！而这个字节造成了乱码！
col 6: *NULL*
col 7: *NULL*
col 8: *NULL*
col 9: *NULL*
col 10: *NULL*
col 11: *NULL*
col 12: *NULL*
col 13: [14] 32 30 30 35 30 31 30 35 31 37 31 34 33 32
col 14: [14] 32 30 30 35 30 31 30 35 31 37 31 34 33 32
col 15: [ 2] c1 02
col 16: [ 1] 80
col 17: [ 1] 80
col 18: [ 2] c1 02
col 19: [14] 32 30 30 35 30 31 30 35 31 37 31 34 33 32
col 20: [14] 32 30 30 35 30 31 30 35 31 37 31 34 33 32
col 21: [ 1] 80
col 22: [ 1] 80
col 23: [ 2] c1 04
col 24: [ 1] 80
col 25: [ 2] c1 06
col 26: [ 2] c1 02
col 27: [ 4] 30 30 30 30
col 28: [ 1] 80
col 29: *NULL*
col 30: [14] 32 30 30 35 30 31 30 35 31 37 31 34 33 32
col 31: [ 1] 80
col 32: *NULL*
col 33: [ 1] 80
col 34: [ 1] 80
col 35: *NULL*
col 36: *NULL*
col 37: *NULL*
col 38: *NULL*
col 39: *NULL*
col 40: *NULL*
col 41: [ 1] 80
col 42: [ 1] 80
col 43: [ 1] 80
col 44: [ 1] 80
col 45: [ 1] 80
col 46: [ 1] 80
col 47: [ 1] 80
col 48: [14] 32 30 30 35 30 33 30 37 31 37 31 34 33 32
col 49: [ 2] c1 0c
由于这个字段不是很重要，最后用update teluser_tbl set name=rtrim(name,substr(name,-1));节断了最右端的一个字符，系统恢复正常。
后来开发人员详细检查程序，发现C语言在读入数据的时候少读了一个字节！
那为什么这个字节会造成如此严重的问题呢，目前唯一的解释是ZHS16GBK字符集的Bug，这个字节在ZHS16GBK字符集中对应的字符与OS底层通讯代码冲突，造成通讯故障，从而引发数据库故障。
先到这里，等有空再把这个问题详细研究一下。
