前不久某运营商客户反映某套业务系统在2016年8月4日凌晨出现过无法访问数据库的情况。当接到客户请求之后我才通过VPN登录进行日志分析。首先我分析数据库告警日志发现，8月4日凌晨54分开始出现unable to spawn jobq slave process相关错误，如下所示。
Thu Aug 04 00:54:10 CST 2016 Process J006 died, see its trace file Thu Aug 04 00:54:10 CST 2016 kkjcre1p: unable to spawn jobq slave process Thu Aug 04 00:54:10 CST 2016 Errors in file /oracle/app/oracle/admin/fwktdb/bdump/fwktdb_cjq0_5487.trc: Process J006 died, see its trace file Thu Aug 04 00:54:11 CST 2016 kkjcre1p: unable to spawn jobq slave process Thu Aug 04 00:54:11 CST 2016 Errors in file /oracle/app/oracle/admin/fwktdb/bdump/fwktdb_cjq0_5487.trc: …… Thread 1 advanced to log sequence 111405 (LGWR switch) Current log# 3 seq# 111405 mem# 0: /dev/vx/rdsk/datadg02/fwkt_redo1_3_raw_512m Thu Aug 04 03:09:55 CST 2016 Process J007 died, see its trace file Thu Aug 04 03:09:55 CST 2016 kkjcre1p: unable to spawn jobq slave process Thu Aug 04 03:09:55 CST 2016 Errors in file /oracle/app/oracle/admin/fwktdb/bdump/fwktdb_cjq0_5487.trc: …… Thu Aug 04 06:07:50 CST 2016 Process J002 died, see its trace file Thu Aug 04 06:07:50 CST 2016 kkjcre1p: unable to spawn jobq slave process Thu Aug 04 06:07:50 CST 2016 Errors in file /oracle/app/oracle/admin/fwktdb/bdump/fwktdb_cjq0_5487.trc:
从上述告警日志来看，没有明显的ORA相关错误。但是我们细心一点就会发现上述日志中存在一些告警信息，比如kkjcrelp:unable to spawn jobq slave process，该告警也值得我们关注。那么这个告警信息的产生一般有哪些原因呢？根据kkjcrelp:unable to spawn jobq slave process错误来看，一般有以下几种原因。
（1）数据库进程参数processes参数设置偏小。
（2）job 参数job_queue_processes设置过小。
（3）系统资源（CPU/IO/Memory）不足，例如内存不足，导致新产生的进程无法获取资源。
根据经验我们知道，这极有可能是资源的问题。因为如果是数据库实例processes参数设置偏小，那么alert log通常会伴随 ORA-00200 类似的错误，然而我们却并没有发现。因此我们可以很容易的排除第一种可能性。至于第2、3种可能原因，这里我们暂时还无法排除，还需要进一步分析相关日志才能下结论。
既然是应用程序无法访问，那么数据库监听日志应该会有一些相关记录。我继续检查数据库监听日志发现，4日凌晨确实出现了大量的TNS相关错误，如下所示。
04-AUG-2016 01:33:58 * (CONNECT_DATA=(SERVICE_NAME=fwktdb)(CID=(PROGRAM=SigService) (HOST=wljhinas35)(USER=inas))) * (ADDRESS=(PROTOCOL=tcp)(HOST=135.160.9.35)(PORT=48172)) * establish * fwktdb * 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 Solaris Error: 32: Broken pipe 04-AUG-2016 01:33:58 * …… 04-AUG-2016 01:34:06 * (CONNECT_DATA=(SERVICE_NAME=fwktdb)(CID=(PROGRAM=WlanService) (HOST=nxwljh1.localdomain)(USER=inas))) * (ADDRESS=(PROTOCOL=tcp)(HOST=135.160.9.42)(PORT=50613)) * establish * fwktdb * 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 Solaris Error: 32: Broken pipe
上面这部分内容，我相信大家并不陌生，这是非常常见的一些错误。我相信很多人第一感觉是搜索Oracle MOS，确认TNS-12518 是什么意思，什么原因。想必大家应该会看到这样的文章，ORA-12518 / TNS-12518 Troubleshooting （ID 556428.1）。
该文档描述的解决方案有很多种，这里我大致描述一下，有如下几种。
（1）操作系统时钟问题，建议设置设置如下参数：
stener.ora: INBOUND_CONNECT_TIMEOUT_listenername SQLnet.ora: SQLNET.INBOUND_CONNECT_TIMEOUT。
（2）操作系统可用内存不足，建议增加内存。
（3）数据库参数processes设置过小，建议调大一些。
（4）启用大内存支持，突破内核的单进程只能消耗1GB内存的限制，这实际上通常是指的windows环境。
（5）PGA内存不足，而SGA设置过大，导致进程内存不足。建议缩小SGA，给PGA预留更多内存。
（6）配置MTS共享模式。
（7）如果监听报错TNS-12518，并进程crash，那么很可能是命中一些因为系统压力过大或者内存溢出等相关oracle Bug,例如6139856。
实际上当我们遇到上述类似错误时，不应该直接往下判断。首先在分析这个问题时，我们要确认一点客户所说是否是真实的。也就是说这个问题之前是否出现过，还是仅仅是8月4日凌晨出现过1次。带这这样的疑问，我继续检查分析监听日志，发现实际上8月3日也出现无法连接数据库的情况。
03-AUG-2016 18:24:48 * (CONNECT_DATA=(SID=fwktdb)(CID=(PROGRAM=JDBC Thin Client) (HOST=__jdbc__) (USER=bea))) * (ADDRESS=(PROTOCOL=tcp)(HOST=135.161.23.93)(PORT=35059)) * establish * fwktdb * 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 Solaris Error: 32: Broken pipe …… 03-AUG-2016 18:24:52 * (CONNECT_DATA=(SERVICE_NAME=fwktdb)(CID=(PROGRAM=SigService)(HOST=wljhinas33)(USER=inas))) * (ADDRESS=(PROTOCOL=tcp)(HOST=135.160.9.33)(PORT=59837)) * establish * fwktdb * 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 Solaris Error: 32: Broken pipe 对于Oracle 的错误分析，我给大家的建议都是应该从下往上看，比如下面所列的错误。 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 Solaris Error: 32: Broken pipe
Oracle 监听日志在这里其实抛出了一连串的告警信息，我们需要有所判断，确认其中的哪行信息是关键信息，是产生问题的根源。很明显最后一行的Solaris Error:32：Broken pipe 是此问题的关键所在。
针对Solaris error:32 broken pipe错误，这里我不自行进行解释，我选择引用Oracle官方的解释。
The error 32 indicates the communication has been broken while the listener is trying to hand off the client connection to the server process or dispatcher process.
这里我简单解释一下上述文档内容的描述，简单地讲就是：Oracle 监听程序尝试去处理客户端到服务器端进程或者调度器（dispatcher processes）进程之前的连接时，将客户端进程通信强行中断了。那么监听程序为什么要终止连接呢？文档解释说有如下几种可能性原因。
1. One of reason would be processes parameter being low, and can be verified by the v$resource_limit view. 2. In Shared Server mode, check the 'lsnrctl services' output and see if the dispatcher has refused any connections, if so, then consider increasing the number of dispatchers. 3. Check the alert log for any possible errors. 4. Memory resource is also another cause for this issue. Check the swap, memory usage of the OS. 5. If RAC/SCAN or listener is running in separate home, check the following note。
从Oracle 文档描述来看，产生该问题原因主要有如下几种。
（1）processes参数设置过小。
（2）共享服务器模式下，dispatcher不足。
（3）内存资源不足。
由于客户这里实际上是Oracle 10.2.0.4 环境，因此就不需要考虑上述第5条描述了。
从上述问题描述的内容来看，与我们之前讲述TNS-12518 错误几种可能性的原因有些类似。那么我们如何去定位这个问题呢？针对类似的问题，我通常的建议是使用最简单的方法：排除法。
首先我们来从数据库层面判断是否可以直接排除第1种可能性原因。我分析了数据库在8月4日凌晨1-2点的AWR数据库，发现数据库进程并没有达到processes参数设置限制，如图13-1所示。
图13-1
所以可以排除第1种可能性原因，同时由于数据库是专用模式，因此也可以排除第2种可能性原因。因此，这里似乎可以大致断定导致此次问题的原因是第3种可能性了，即系统资源使用方面。
我们知道操作系统资源主要分为CPU/IO以及内存资源，接下来从数据库监控角度来判断一下数据库资源在故障期间内的使用情况如何。通过器监控发现，CPU资源消耗正常，swap内存消耗存在一定的波动，但是整体来看也是正常的，如图13-2、图13-3所示。
图13-2
图13-3
基于前面的分析不难看出，系统资源在使用上没有任何问题，没有出现资源过度消耗或资源不足的情况。到这里整个问题的分析似乎陷入了僵局。
Oracle数据库是基于操作系统，因此实际上，当数据库出现异常之后，我们在进行问题分析时，首先应该确认操作系统本身是否正常，比如内核参数设置是否正确等。因此自然而然应该进一步检查数据库服务器操作系统日志是否存在相关蛛丝马迹。
正如心中所想，再检查Solaris 操作系统的日志发现，确实存在相关错误。
Aug 4 00:54:24 nxfwktdb SC[SUNWscor.oracle_server.monitor]:nxfwktdb_rg:ora-fwktdb_rs: [ID 564643 local7.error] Fault monitor detected error DBMS_ERROR: 20 DEFAULT Action=NONE : Max. number of DBMS processes exceeded Aug 4 00:54:54 nxfwktdb SC[SUNWscor.oracle_server.monitor]:nxfwktdb_rg:ora-fwktdb_rs: [ID 564643 local7.error] Fault monitor detected error DBMS_ERROR: 1045 DEFAULT Action=NONE : Fault monitor user lacks CREATE SESSION privilege; logon denied. …… Aug 4 02:26:57 nxfwktdb SC[SUNWscor.oracle_server.monitor]:nxfwktdb_rg:ora-fwktdb_rs: [ID 564643 local7.error] Fault monitor detected error DBMS_ERROR: 1045 DEFAULT Action=NONE : Fault monitor user lacks CREATE SESSION privilege; logon denied. Aug 4 02:28:26 nxfwktdb last message repeated 3 times Aug 4 02:28:56 nxfwktdb SC[SUNWscor.oracle_server.monitor]:nxfwktdb_rg:ora-fwktdb_rs: [ID 564643 local7.error] Fault monitor detected error DBMS_ERROR: 20 DEFAULT Action=NONE : Max. number of DBMS processes exceeded
从上述日志来看，确实存在processes超过限制的情况。同时还能发现有监控用户由于缺乏权限，仍然在不断尝试登陆数据库，这也是一个安全隐患。针对操作系统日志中的Max number of DBMS processes execeeded 错误信息，Oracle 官方文档有如下类似解释。
There can be several contributors to this failure. Solaris kernel may have resource (memory/cpu) shortage, performance problem or the database itself could be having some issues for example: detected error DBMS_ERROR: 20 DEFAULT Action=NONE : Max. number of DBMS processes exceeded
说明：参考文档 Solaris Cluster 3.x HA-Oracle Fault Monitor Dumps Core With "Aborting fault monitor child process" or "probe response time exceeded timeout" (ID 1381317.1)
根据Oracle Solaris的文档解释来看，上述错误ERROR 20表示 Solaris 操作系统本身内核资源使用可能存在异常，或者存在性能问题，或者数据库本身可能存在某些问题。这个分析与我们前面的种种分析似乎比较接近。这里我需要说明的是，我期间分析了故障前后的AWR和ASH 相关数据，没有发现明显异常，因此可以断定数据库本身是正常的。
分析到这个层面，我相信大家心中已经有了答案。有没有可能是操作系统本身有问题呢？这里需要注意的是，操作系统本身有问题，并不代表是指的操作系统资源使用有问题，也有可能是Solaris 相关内核参数设置问题。实际上我们通过前面的操作系统监控信息就可以排除系统资源消耗异常的可能性。所以这里我们很有必要对Solaris系统本身的相关内核参数进行全面检查一次，通过检查发现确实存在参数设置不合理的情况，如下所示。
---操作系统内核参数
root@nxfwktdb # cat /etc/system|grep 'sys' . set semsys:seminfo_semmni=100 set semsys:seminfo_semmns=2048 set semsys:seminfo_semmsl=256 set semsys:seminfo_semvmx=32767 set shmsys:shminfo_shmmax=17179869184 set shmsys:shminfo_shmmin=1 set shmsys:shminfo_shmmni=100 set shmsys:shminfo_shmseg=10 root@nxfwktdb # cat /etc/project system:0:::: user.root:1:::: noproject:2:::: default:3:::: group.staff:10::::
---数据库会话总数
SQL> select count(1) from v$session; COUNT(1) ---------- 1866
对于上述的内核参数，这里我不做过多解释，大家可以参考Oracle官方安装文档，里面有详细的描述。从Soalris 10开始，已经废弃了如下几个参数：
semsys:seminfo_semmns——操作系统信号灯最大个数； shmsys:shminfo_shmmin——共享内存段最小值； semsys:seminfo_semvmx——操作系统信号灯的最大值。
同时，从Solaris 10开始，已经不再建议通过修改/etc/system的方式来调整内核参数了。建议通过project的方式来进行控制，而客户这里没有为Oracle用户单独创建project，而使用了默认的default project，如下：
root@nxfwktdb # id -p oracle uid=101(oracle) gid=100(dba) projid=3(default)
那么我们来进一步检查default project设置是否恰当。其中Solaris 10版本中使用process.max-sem-nsems来替代 semsys:seminfo_semmsl 参数的控制，该参数表示一个信号组中信号灯等最大数量，由于Oracle用户默认使用了default project，因此这里我们来检查default project的设置情况，如下所示。
root@nxfwktdb # prctl -i project default project: 3: default NAME PRIVILEGE VALUE FLAG ACTION RECIPIENT project.max-contracts privileged 10.0K - deny - system 2.15G max deny - project.max-device-locked-memory privileged 1.96GB - deny - system 16.0EB max deny - project.max-port-ids privileged 8.19K - deny - system 65.5K max deny - project.max-shm-memory privileged 1.56TB - deny - system 16.0EB max deny - project.max-shm-ids privileged 128 - deny - system 16.8M max deny - project.max-msg-ids privileged 128 - deny - system 16.8M max deny - project.max-sem-ids privileged 128 - deny - system 16.8M max deny - project.max-crypto-memory privileged 7.83GB - deny - system 16.0EB max deny - project.max-tasks system 2.15G max deny - project.max-lwps system 2.15G max deny - project.cpu-shares privileged 1 - none - system 65.5K max none - zone.max-lwps system 2.15G max deny - zone.cpu-shares privileged 1 - none - -
我们可以看到default project中定义了project.max-sem-ids，它表示系统中信号组的最大值，即128，表示目前该系统最大default project中所定义的用户创建的最大信号组之和不能超过128。同时/etc/system中的参数semsys:seminfo_semmsl 为256，表示该default project 的每一个信号组最大只能创建256个信号灯。可以通过ipcs 命令直接查看这一点。
root@nxfwktdb # ipcs -sb IPC status from <running system> as of Tue Aug 16 16:00:01 CST 2016 T ID KEY MODE OWNER GROUP NSEMS Semaphores: s 12 0x4b623218 --ra-r----- oracle dba 256 s 11 0x4b623217 --ra-r----- oracle dba 256 s 10 0x4b623216 --ra-r----- oracle dba 256 s 9 0x4b623215 --ra-r----- oracle dba 256 s 8 0x4b623214 --ra-r----- oracle dba 256 s 7 0x4b623213 --ra-r----- oracle dba 256 s 6 0x4b623212 --ra-r----- oracle dba 256 s 5 0x4b623211 --ra-r----- oracle dba 256 s 4 0x4b623210 --ra-r----- oracle dba 256 s 0 0x71050a00 --ra-ra-ra- root root 1 root@nxfwktdb # ipcs -ma …… T ID KEY MODE OWNER GROUP CREATOR CGROUP NATTCH SEGSZ CPID LPID ATIME DTIME CTIME Shared Memory: m 1 0x333184c8 --rw-r----- oracle dba oracle dba 1870 12884934656 5253 24096 17:07:40 17:07:40 0:36:07
上述查询结果的NSEMS 列即表示每个信号组中最大的信号灯数量。同时从NATTCH的值可以看出，目前当前Oracle用户已经创建了1 870个进程。实际上seminfo_semmsl参数的设置应该是大于processes参数设置的。目前数据库processes参数设置为2 048，且数据库进程已经超过1 850，因此建议将该参数调整的更大一些。
从前面的数据来看，目前default project中所有用户能够消耗的最大信号灯约等于128×256=32 768。尽管这个数值看上去已经够大，其实不然。在操作系统命令来看，一个进程和信号灯等对应关系通常是一对多。而且从查询结果来看Oracle实际上只分配了9个信号组，每组最大的信号灯数量是256。如果根据这个计算也就是9×256=2 304。而目前数据库实例的进程数量已经接近2 000。
因此最后我们建议将seminfo_semmsl 参数调整的更大一些，建议设置为512以上。
以上三则案例基本上跟数据库的内存管理和系统参数设置相关。每一个故障都不是单一方面的问题产生的，也涉及各方面的知识。对于DBA来说，具备完整的技术观非常重要。
