问题简述：数据库外面应用程序经常连接不上，导致业务受到中断

操作系统：HP-Unix 物理内存24G,交换分区20G

数据库：oracle 10.2.0.4

2010-9-2下午四点钟赶到用户现场,登录到数据库主机,检查监听和数据库日志。

   监听日志从2010-9-2下午14点23分开始报如下错误:

     02-SEP-2010 14:23:25 * (CONNECT_DATA=(SID=ora10g)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) * (ADDRESS=(PROTOCOL=tcp)(HOST=*.*.*.*)(PORT=2024)) * establish * ora10g * 12518

TNS-12518: TNS:listener could not hand off client connection

 TNS-12549: TNS:operating system resource quota exceeded

  TNS-12560: TNS:protocol adapter error

   TNS-00519: Operating system resource quota exceeded

    HPUX Error: 12: Not enough space

   数据库日志从2010-9-2下午14点也报如下错误:

   这里取的是17点多的一段日志

kkjcre1p: unable to spawn jobq slave process

Thu Sep  2 17:06:15 2010

Errors in file /oracle/app/oracle/admin/ora10g/bdump/ora10g_cjq0_2922.trc:

Thu Sep  2 17:06:20 2010

Process startup failed, error stack:

Thu Sep  2 17:06:20 2010

Errors in file /oracle/app/oracle/admin/ora10g/bdump/ora10g_psp0_2906.trc:

ORA-27300: Message 27300 not found; No message file for product=RDBMS, facility=

ORA; arguments: [fork] [11]

ORA-27301: Message 27301 not found; No message file for product=RDBMS, facility=

ORA; arguments: [Resource temporarily unavailable]

ORA-27302: Message 27302 not found; No message file for product=RDBMS, facility=

ORA; arguments: [skgpspawn5]

ORA-27303: Message 27303 not found; No message file for product=RDBMS, facility=

ORA; arguments: [skgpspawn5]

Thu Sep  2 17:06:21 2010

Process J002 died, see its trace file

Thu Sep  2 17:06:21 2010

kkjcre1p: unable to spawn jobq slave process

Thu Sep  2 17:06:21 2010

Errors in file /oracle/app/oracle/admin/ora10g/bdump/ora10g_cjq0_2922.trc:

Thu Sep  2 17:06:46 2010

Errors in file /oracle/app/oracle/admin/ora10g/bdump/ora10g_psp0_2906.trc:

ORA-27300: Message 27300 not found; No message file for product=RDBMS, facility=

ORA; arguments: [fork] [12]

ORA-27301: Message 27301 not found; No message file for product=RDBMS, facility=

ORA; arguments: [Not enough space]

ORA-27302: Message 27302 not found; No message file for product=RDBMS, facility=

ORA; arguments: [skgpspawn3]

Thu Sep  2 17:06:47 2010

Process J002 died, see its trace file

Thu Sep  2 17:06:47 2010

kkjcre1p: unable to spawn jobq slave process

Thu Sep  2 17:06:47 2010

Errors in file /oracle/app/oracle/admin/ora10g/bdump/ora10g_cjq0_2922.trc:

Thu Sep  2 17:07:30 2010

Errors in file /oracle/app/oracle/admin/ora10g/udump/ora10g_ora_21196.trc:

ORA-27102: out of memory

HPUX-ia64 Error: 12: Not enough space

Additional information: 108

Additional information: 458752

1          检查过程

1.   检查cpu占用资源

top cpu空闲率90%多，没有相关oracle进程占用cpu资源

      procs           memory                   page

 faults       cpu

 r     b     w      avm    free   re   at    pi   po    fr   de    sr     in

 sy    cs  us sy id

 1     1     0   190706   25014    0    0     0    0     0    0     0   9422

573  4068   5  1 94

 1     1     0   190706   24897    0    0     0    0     0    0     0   3686

721   379   8  0 92

 2     1     0   179575   24897    0    0     0    0     0    0     0   3681

852   379   8  0 92

 2     1     0   179575   24896    0    0     0    0     0    0     0   3682

149   381   8  0 91

 2     1     0   179575   24896    0    0     0    0     0    0     0   3777

240   454   8  0 92

 2     1     0   179575   24898    0    0     0    0     0    0     0   3662

492   343   0  0 100

 2     1     0   179575   24898    0    0     0    0     0    0     0   3578

100   262   0  0 100

 1     0     0   196811   24898    0    0     0    0     0    0     0   3539

758   212   0  0 100

 1     0     0   196811   24897    0    0     0    0     0    0     0   3499

193   180   1  0 99

 1     0     0   196811   24897    0    0     0    0     0    0     0   3475

274   165   8  0 92

2.   检查物理内存和交换分区使用情况

       rx8640a:[/var/adm/syslog]#swapinfo -atm

             Mb      Mb      Mb   PCT  START/      Mb

TYPE      AVAIL    USED    FREE  USED   LIMIT RESERVE  PRI  NAME

dev       20480     342   20138    2%       0       -    1  /dev/vg00/lvol2

reserve       -   20138  -20138

memory    23251   23164      87  100%

total     43731   43644      87  100%       -       0    -

     可以看到物理内存全部用完，交换分区只占用2%。

3.   检查操作系统日志

dmesg

Pid 21214 was killed due to failure in writing the signal context - possible stack overflow.

Deferred swap reservation failure pid: 21910

Deferred swap reservation failure pid: 21908

Deferred swap reservation failure pid: 21912

Deferred swap reservation failure pid: 21912

Deferred swap reservation failure pid: 21912

Deferred swap reservation failure pid: 21909

报很多进程ID失败的信息

4.   查看数据库连接数

su - oracle

ps -ef|grep LOCAL|wc -l

924  咨询库开发人员，这个连接数正常。

5.   检查操作系统进程连接参数

sam

kernel configure

maxuprc  1500

连接数没有超过进程连接参数值

2    处理过程

7.   启动数据库后，应用访问正常，但连接数又突然增加到920

  su - oracle

ps -ef|grep LOCAL|wc -l

 920

         通过glance工具，发现每个LOCAL=NO的进程平均占用20多M

                                  PROCESS LIST                      Users=    3

                         User      CPU %    Thrd Disk        Memory       Block

Process Name     PID     Name   (1200% max) Cnt  IOrate      RSS/VSS      On

--------------------------------------------------------------------------------

ora_j001_ora       13731 oracle       41.9     1 334.2   685.4mb  701.9mb    IO

glance             13896 root          3.0     1   0.0     2.7mb    8.2mb STRMS

vxfsd                133 root          2.7    16   1.1     1.6mb    1.8mb SLEEP

midaemon            1975 root          0.0     8   0.0   263.4mb  268.1mb SLEEP

oracleora10g        4581 oracle        0.0     1   0.0    21.3mb   28.3mb SOCKT

oracleora10g        4687 oracle        0.0     1   0.0    22.3mb   25.3mb SOCKT

oracleora10g        4983 oracle        0.0     1   0.0    23.4mb   24.3mb SOCKT

oracleora10g        4482 oracle        0.0     1   0.0    25.2mb   27.2mb SOCKT

oracleora10g        4482 oracle        0.0     1   0.0    26.4mb   29.5mb SOCKT

oracleora10g        4482 oracle        0.0     1   0.0    27.5mb   32.3mb SOCKT7

ora_cjq0_ora       13704 oracle        0.0     1   0.0   656.1mb  695.5mb OTHER

      C - cum/interval toggle                                       Page 1 of 2

  大概估算下，900多个连接数大概占用物理18000M,根据swapinfo –atm

命令查看物理内存已经使用91%，一旦到100%,外面应用可能又无法连接。

               继续分析进程ID，查到大部分是由机器名为db的应用连进来，状态为inactive,

sql全部为select 1 from dual;

   但这时不知道hzdb机器的ip地址，和用户一起协商，

把数据库启动后的这段时间根据listener.log全部列举出来,

主要是由以下三个ip连接进来：

        192.168.0.55,192.168.0.213,192.168.3.26 

          用户感觉192.168.0.55 ip有问题,通过沟通，确认是这个IP引起。

       临时解决方法：把192.168.0.55应用连接到数据库用户锁住。

9.   用户锁住后，重起数据库 物理内存占用66% 应用恢复正常

rx8640a:[/opt]#swapinfo -atm

             Mb      Mb      Mb   PCT  START/      Mb

TYPE      AVAIL    USED    FREE  USED   LIMIT RESERVE  PRI  NAME

dev       20480       0   20480    0%       0       -    1  /dev/vg00/lvol2

reserve       -   13238  -13238

memory    23251   15413    7838   66%

total     43731   28651   15080   66%       -       0    -

3          总结

主要是应用自动连接造成的,并且连接属于C/S架构，一对一，而且设置成自动连接,一起就是900多个连接，所以消耗大量物理内存。

前面咨询开发人员说是900多连接,其实开发人员说的不准确,导致我们误判,这也就告诉我们在解决问题的时候全部要靠自己去检查,不能相信任何人说的话。

oracle公司的人也说过，不能相信客户说的话。