当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底层通讯代码冲突,造成通讯故障,从而引发数据库故障。

先到这里,等有空再把这个问题详细研究一下。

转载于:https://www.cnblogs.com/rootq/archive/2008/08/13/1266936.html

  • 0
    点赞
  • 0
    评论
  • 0
    收藏
  • 扫一扫,分享海报

参与评论 您还未登录,请先 登录 后发表或查看评论
©️2022 CSDN 皮肤主题:编程工作室 设计师:CSDN官方博客 返回首页
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值