database and os was hang with ORA-240 ERROR

xiaofan23z

Environment：  AIX 6.1 ，TWO node rac，oracle 10.2.0.4

Symptom ：

  用户反映无法打开MES程序，连接到2号节点查看，发现sqlplus /as sysdba

回车后卡死，cancel不掉？重新开一个连接，到root账户下 crsctl check crs 命令也卡死，lsnrctl status 命令卡死，OS命令正常。

1号节点正常。

Alterlog有如下报错

Sat Nov  3 16:37:32 2012

Thread 2 advanced to log sequence 55778 (LGWR switch)

  Current log# 8 seq# 55778 mem# 0: +SFC3DB_DATA/sfc3db/onlinelog/group_8.304.722515055

  Current log# 8 seq# 55778 mem# 1: +SFC3DB_ARCH/sfc3db/onlinelog/group_8.264.722515055

Sat Nov  3 16:40:19 2012

Errors in file /apps/oracle/admin/sfc3db/bdump/sfc3db2_arc0_1843352.trc:

ORA-00240: control file enqueue held for more than 120 seconds

Sat Nov  3 16:42:29 2012

Errors in file /apps/oracle/admin/sfc3db/bdump/sfc3db2_arc1_565424.trc:

ORA-00240: control file enqueue held for more than 120 seconds

Sat Nov  3 16:47:00 2012

kkjcre1p: unable to spawn jobq slave process

Sat Nov  3 16:47:00 2012

Sat Nov  3 17:04:22 2012

ksvsubmit: Process(O001) creation failed

系统应该是无法分配新的进程了，所以这些命令都卡死，  但是当时OS free的内存还有10多G，也远没有达到最大进程数。

我最后的解决办法是直接reboot OS，重启后OK， 各位大神有遇到过这种情况的吗？需要什么LOG 我发上来。

如下是trc文件

sfc3rac2:/apps/oracle/admin/sfc3db/bdump$ cat /apps/oracle/admin/sfc3db/bdump/sfc3db2_cjq0_5861420.trc

Dump file /apps/oracle/admin/sfc3db/bdump/sfc3db2_cjq0_5861420.trc

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production

With the Partitioning, Real Application Clusters, OLAP, Data Mining

and Real Application Testing options

ORACLE_HOME = /apps/oracle/product/10.2.0

System name:    AIX

Node name:      sfc3rac2

Release:        1

Version:        6

Machine:        00C8B9724C00

Instance name: sfc3db2

Redo thread mounted by this instance: 2

Oracle process number: 15

Unix process pid: 5861420, image: oracle@sfc3rac2 (CJQ0)

*** 2012-11-03 06:00:41.427

*** SERVICE NAMESYS$BACKGROUND) 2012-11-03 06:00:41.419

*** SESSION ID2192.1) 2012-11-03 06:00:41.419

GATHER_STATS_JOB: Stopped by Scheduler.

Consider increasing the maintenance window duration if this happens frequently.

The following objects/segments were not analyzed due to timeout:

*** 2012-11-03 16:31:39.479

Waited for process J000 to initialize for 60 seconds

*** 2012-11-03 16:31:39.479

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 3.77 3.49 3.60

swap info: free_mem = 9427.14M rsv = 64.00M

           alloc = 241.15M avail = 16384.00M swap_free = 16142.85M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:33:40.701

*** 2012-11-03 16:33:50.907

Waited for process J000 to initialize for 70 seconds

*** 2012-11-03 16:33:50.907

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 2.86 3.25 3.49

swap info: free_mem = 9348.35M rsv = 64.00M

           alloc = 241.11M avail = 16384.00M swap_free = 16142.89M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:35:52.258

*** 2012-11-03 16:36:02.459

Waited for process J000 to initialize for 80 seconds

*** 2012-11-03 16:36:02.459

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 2.74 3.00 3.36

swap info: free_mem = 9385.39M rsv = 64.00M

           alloc = 241.10M avail = 16384.00M swap_free = 16142.90M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:38:03.960

*** 2012-11-03 16:38:14.165

Waited for process J000 to initialize for 90 seconds

*** 2012-11-03 16:38:14.165

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 2.56 2.96 3.30

swap info: free_mem = 9440.27M rsv = 64.00M

           alloc = 241.00M avail = 16384.00M swap_free = 16143.00M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:40:16.175

*** 2012-11-03 16:40:26.384

Waited for process J000 to initialize for 100 seconds

*** 2012-11-03 16:40:26.384

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 2.82 2.90 3.23

swap info: free_mem = 9488.88M rsv = 64.00M

           alloc = 240.96M avail = 16384.00M swap_free = 16143.04M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:42:29.100

*** 2012-11-03 16:42:39.305

Waited for process J000 to initialize for 110 seconds

*** 2012-11-03 16:42:39.305

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 4.05 3.26 3.32

swap info: free_mem = 9640.50M rsv = 64.00M

           alloc = 240.90M avail = 16384.00M swap_free = 16143.10M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:44:43.732

*** 2012-11-03 16:44:53.936

Waited for process J000 to initialize for 120 seconds

*** 2012-11-03 16:44:53.936

Dumping diagnostic information for J000:

OS pid = 917522

loadavg : 3.03 3.16 3.28

swap info: free_mem = 9667.09M rsv = 64.00M

           alloc = 240.84M avail = 16384.00M swap_free = 16143.16M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle  917522       1   0  60 20 1ad230590 89196          16:30:38      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 917522 2>&1' timed out after 60 seconds

*** 2012-11-03 16:47:00.265

Killing process (ospid 917522):  (reason=x4 error=0)

... and the process is still alive after kill!

*** 2012-11-03 17:05:23.892

Waited for process J000 to initialize for 60 seconds

*** 2012-11-03 17:05:23.892

Dumping diagnostic information for J000:

OS pid = 3915970

loadavg : 2.43 2.42 2.75

swap info: free_mem = 10365.04M rsv = 64.00M

           alloc = 239.53M avail = 16384.00M swap_free = 16144.47M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle 3915970       1   0  60 20 105d26590 89196          17:04:22      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 3915970 2>&1' timed out after 60 seconds

*** 2012-11-03 17:07:35.954

*** 2012-11-03 17:07:46.156

Waited for process J000 to initialize for 70 seconds

*** 2012-11-03 17:07:46.156

Dumping diagnostic information for J000:

OS pid = 3915970

loadavg : 2.24 2.33 2.67

swap info: free_mem = 10400.53M rsv = 64.00M

           alloc = 239.37M avail = 16384.00M swap_free = 16144.63M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle 3915970       1   0  60 20 105d26590 89196          17:04:22      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 3915970 2>&1' timed out after 60 seconds

*** 2012-11-03 17:09:58.294

*** 2012-11-03 17:10:08.495

Waited for process J000 to initialize for 80 seconds

*** 2012-11-03 17:10:08.495

Dumping diagnostic information for J000:

OS pid = 3915970

loadavg : 2.36 2.38 2.64

swap info: free_mem = 10389.09M rsv = 64.00M

           alloc = 239.23M avail = 16384.00M swap_free = 16144.77M

       F S      UID     PID    PPID   C PRI NI ADDR    SZ    WCHAN    STIME    TTY  TIME CMD

1040005 A   oracle 3915970       1   0  60 20 105d26590 89196          17:04:22      -  0:00 [oracle]

skgpgpstack: read() for cmd /bin/sh -c '/usr/bin/procstack 3915970 2>&1' timed out after 60 seconds

*** 2012-11-03 17:12:20.685

*** 2012-11-03 17:12:30.886

Waited for process J000 to initialize for 90 seconds

*** 2012-11-03 17:12:30.886

Dumping diagnostic information for J000:

还有个trc文件太大暂时不放了 。

系统应该是无法分配新的进程了，所以这些命令都卡死，  但是当时OS free的内存还有10多G，也远没有达到最大进程数。

我最后的解决办法是直接reboot OS，重启后OK， 各位大神有遇到过这种情况的吗？

irenetongying

好像跟JOB有关：
1、kkjcre1p: unable to spawn jobq slave process
2、*** 2012-11-03 16:31:39.479
Waited for process J000 to initialize for 60 seconds
*** 2012-11-03 17:12:30.886
Waited for process J000 to initialize for 90 seconds


ksvsubmit: Process(O001) creation failed这个错好像跟processes不足有关，参考http://www.oracledatabase12g.com ... B8%80%E4%BE%8B.html，需要进一步确认~

xiaofan23z

job_queue_processes   是默认值  10，当前可用的job不超过30，这个参数已经够用了
processes  数为  2000，当时出现异常时为周末，肯定没有达峰值。

irenetongying

不是job_queue_processes默认值的问题，而是那个时间点跑了什么JOB，是不是那个JOB造成的~

dotaddjj

如果当时能做个hanganalyze还是能清晰内部hang住的原因的，单从上面的trace来看仅仅就是一个子进程分配在等待，而等待往往是资源方面，内存 cpu 信号量等。

xiaofan23z

dotaddjj 发表于 2012-11-6 09:34
如果当时能做个hanganalyze还是能清晰内部hang住的原因的，单从上面的trace来看仅仅就是一个子进程分配在等 ...

因为是生产系统，为了最短时间回复生产，所以当时没有多做分析，但是可以肯定应该不是内存问题，内存内存足够大，发生为题是还有10多G内存空闲。  还有哪些log 可供分析吗？

iori809

GATHER_STATS_JOB: Stopped by Scheduler

可能是自动收集统计信息这个JOB影响的~
这种自动的JOB应该关掉~

killerzhjl

smitty chsys看看操作系统最大进程到底是多少。

jieyancai

vmo -a
看看配置

xiaofan23z

lsattr -El sys0
SW_dist_intr    false              Enable SW distribution of interrupts              True
autorestart     true               Automatically REBOOT OS after a crash             True
boottype        disk               N/A                                               False
capacity_inc    1.00               Processor capacity increment                      False
capped          true               Partition is capped                               False
conslogin       enable             System Console Login                              False
cpuguard        enable             CPU Guard                                         True
dedicated       true               Partition is dedicated                            False
enhanced_RBAC   true               Enhanced RBAC Mode                                True
ent_capacity    2.00               Entitled processor capacity                       False
frequency       1593000000         System Bus Frequency                              False
fullcore        false              Enable full CORE dump                             True
fwversion       IBM,EL340_075      Firmware version and revision levels              False
id_to_partition 0X80000D50B4E00001 Partition ID                                      False
id_to_system    0X80000D50B4E00000 System ID                                         False
iostat          true               Continuously maintain DISK I/O history            True
keylock         normal             State of system keylock at boot time              False
log_pg_dealloc  true               Log predictive memory page deallocation events    True
max_capacity    2.00               Maximum potential processor capacity              False
max_logname     9                  Maximum login name length at boot time            True
maxbuf          20                 Maximum number of pages in block I/O BUFFER CACHE True
maxmbuf         0                  Maximum Kbytes of real memory allowed for MBUFS   True
maxpout         8193               HIGH water mark for pending write I/Os per file   True
maxuproc        10000              Maximum number of PROCESSES allowed per user      Truemin_capacity    1.00               Minimum potential processor capacity              False
minpout         4096               LOW water mark for pending write I/Os per file    True
modelname       IBM,8203-E4A       Machine name                                      False
ncargs          256                ARG/ENV list size in 4K byte blocks               True
nfs4_acl_compat secure             NFS4 ACL Compatibility Mode                       True
pre430core      false              Use pre-430 style CORE dump                       True
pre520tune      disable            Pre-520 tuning compatibility mode                 True
realmem         32505856           Amount of usable physical memory in Kbytes        False
rtasversion     1                  Open Firmware RTAS version                        False
sed_config      select             Stack Execution Disable (SED) Mode                True
systemid        IBM,02068B972      Hardware system identifier                        False
variable_weight 0                  Variable processor capacity weight                False

最大process为10000 肯定够用的  4CORE 32GB P6小机 硬件还是够用的