数据库：Oracle 10.2.0.1
平台：HP-UX B.11.23 ia64
故障描述
客户反映在2009-01-19上午7点左右，应用无法连接到数据库，之后将数据库重启，并增大了PROCESSES参数。客户希望查找问题原因。
原因分析：
ALERT LOG分析：
从ALERT LOG中的信息可以看到：
Tue Jan 19 06:11:22 2010
Process J000 died, see its trace file
Tue Jan 19 06:11:22 2010
kkjcre1p: unable to spawn jobq slave process
Tue Jan 19 06:11:22 2010
Errors in file /oracle/admin/vc/bdump/vc_cjq0_16001.trc:
Tue Jan 19 06:12:33 2010
Process J000 died, see its trace file
Tue Jan 19 06:12:33 2010
kkjcre1p: unable to spawn jobq slave process
Tue Jan 19 06:12:33 2010
Errors in file /oracle/admin/vc/bdump/vc_cjq0_16001.trc:
在19号的06:11:22时出现错误：
原因是由于无法分配jobq slave process进程导致J000进程died。
从/oracle/admin/vc/bdump/vc_cjq0_16001.trc看到：
*** 2010-01-19 06:11:22.293
Process J000 is dead (pid=15748, state=3):
*** 2010-01-19 06:12:33.315
Process J000 is dead (pid=15947, state=3):
该问题出现过两次，都是由调度进程CJQ0产生的。
从同时间点的后台trace文件看到出现该问题的主要原因是达到了最大进程数限制
/oracle/admin/vc/bdump/vc_ora_15748.trc内容：
error 20 in job queue process
ORA-00020: maximum number of processes (1000) exceeded
尽管无法分配进程给job队列使用，但是并不会导致数据库宕机或挂起。数据库仅是由于达到了最大进程数限制，而导致应用无法连接。
此时数据库的状态仍然是OPEN状态，仍能通过管理员用户登入到数据库。
客户在数据库出现问题之后对数据库的操作：
06:53:41开始，使用管理员用户重启数据库实例：
Tue Jan 19 06:53:41 2010
Starting ORACLE instance (normal)
第一次启动不成功，于07:12:36将数据库shutdown abort：
Tue Jan 19 07:12:36 2010
Shutting down instance (abort)
License high water mark = 980
Instance terminated by USER, pid = 25808
之后在07:12:46时正常重启数据库，并启动成功：
Tue Jan 19 07:12:46 2010
Starting ORACLE instance (normal)
分析listener.log：
分析大量连接的客户端：
通过统计分析listener.log日志，2.log为最后100000行的listener.log，统计结果如下：
统计2010年1月19日，1-7点之间的192.168.1.6的连接信息：
cat 2.log | grep "19-JAN-2010 01" | grep "establish" | grep "192.168.1.6" | wc -l result:217
cat 2.log | grep "19-JAN-2010 02" | grep "establish" | grep "192.168.1.6" | wc -l result:283
cat 2.log | grep "19-JAN-2010 03" | grep "establish" | grep "192.168.1.6" | wc -l result:275
cat 2.log | grep "19-JAN-2010 04" | grep "establish" | grep "192.168.1.6" | wc -l result:282
cat 2.log | grep "19-JAN-2010 05" | grep "establish" | grep "192.168.1.6" | wc -l result:290
cat 2.log | grep "19-JAN-2010 06" | grep "establish" | grep "192.168.1.6" | wc -l result:397
统计2010年1月19日，1-7点之间的132.96.63.75的连接信息：
cat 2.log | grep "19-JAN-2010 01" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "19-JAN-2010 02" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "19-JAN-2010 03" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "19-JAN-2010 04" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "19-JAN-2010 05" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "19-JAN-2010 06" | grep "establish" | grep "132.96.63.75" | wc -l result:85
统计2010年1月18日，1-7点之间的192.168.1.6的连接信息：
cat 2.log | grep "18-JAN-2010 01" | grep "establish" | grep "192.168.1.6" | wc -l result:68
cat 2.log | grep "18-JAN-2010 02" | grep "establish" | grep "192.168.1.6" | wc -l result:20
cat 2.log | grep "18-JAN-2010 03" | grep "establish" | grep "192.168.1.6" | wc -l result:26
cat 2.log | grep "18-JAN-2010 04" | grep "establish" | grep "192.168.1.6" | wc -l result:21
cat 2.log | grep "18-JAN-2010 05" | grep "establish" | grep "192.168.1.6" | wc -l result:69
cat 2.log | grep "18-JAN-2010 06" | grep "establish" | grep "192.168.1.6" | wc -l result:20
统计2010年1月18日，1-7点之间的132.96.63.75的连接信息：
cat 2.log | grep "18-JAN-2010 01" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "18-JAN-2010 02" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "18-JAN-2010 03" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "18-JAN-2010 04" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "18-JAN-2010 05" | grep "establish" | grep "132.96.63.75" | wc -l result:132
cat 2.log | grep "18-JAN-2010 06" | grep "establish" | grep "132.96.63.75" | wc -l result:132
由统计可见192.168.1.6出现了比平时更多的连接。
Listener.log报错信息：
19-JAN-2010 06:07:33 * (CONNECT_DATA=(SID=vc)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.
6)(PORT=62396)) * establish * vc * 12518
TNS-12518: TNS:listener could not hand off client connection
TNS-12547: TNS:lost contact
TNS-12560: TNS:protocol adapter error
TNS-00517: Lost contact
HPUX Error: 32: Broken pipe
2010-01-19第一次出现连接失败的时间为06:07:33，客户端为192.168.1.6，该时间点与数据库的alert log报错的时间点极为接近。
TNS-12518: TNS:listener could not hand off client connection
该错误通常表明是由于资源问题导致的连接失败。
AWR报告分析：
19号5点-6点AWR报告/tmp/awrrpt_1_15639_15640.html中同样也出现了关于资源限制的警告信息。
Resource Limit Stats
only rows with Current or Maximum Utilization > 80% of Limit are shown
ordered by resource name
Current Maximum Initial
Resource Name Utilization Utilization Allocation Limit
------------- ------------- ------------ ----------- ------
processes 991 999 1000 1000
sessions 997 1,003 1105 1105
问题的主要原因是客户端192.168.1.6的大量连接使数据库达到了最大processes限制导致用户无法连接，数据库并没有出现宕机。管理员用户仍然能正常登入数据库对数据库进行重启。
阅读(2322) | 评论(0) | 转发(1) |
