处理XX医院服务器定时死机过程 TNS-12547 TNS:lost contact

紧急求援

      上周正在QJRMYY现场进行集成项目的硬件调试，突然接到XZH的电话，说TY渠道有个紧急的数据库问题需要处理下，叫我放下手上的工作，收下邮件。虽然这种急刹车式的变换工作状态的方式是我最不愿意接受的，但是既然是紧急事情，那也只有马上服从安排。找了医院的一台能上网的机器，打开公司邮箱，找到XZH转发的TY渠道的邮件，看了下大体意思是反映其负责的JM医院数据库经常不定时出现死机现象，表现为全院都无法访问HIS数据库，需要重新启动服务器才能正常访问。该现象出现了多次，已经影响到医院HIS业务的正常使用，需要我们部门协助解决。邮件刚看完，手机就响了，一看是外地的陌生号码，猜到估计是渠道的技术人员的电话过来了，这效率那不是一般的高，互相寒暄了下，就进入正题，首先对邮件描述不是很清楚的地方进行了询问，对一些细节进行了补充，最后大体罗列了以下几点有用的信息：

1.出现问题的时间比较固定，并不是邮件反馈不定时，一般都是上午8点左右，其他时间段暂时未发生该现象。

2.问题表现为客户端用户无法访问数据库，但是未检查本地是否能够访问，不排除数据库并没有死机，而只是客户段无法访问的情况。

3.重启服务器问题得到立即解决。

      通过上面的分析，首先怀疑是否服务器上有什么定时作业，如自动备份，杀毒软件更新等，在8点多执行时，消耗了大量系统资源，导致客户端无法登录，表现为数据库成假死状态，通过重启服务器释放了系统资源，表现为问题暂时得以解决。因此立即首先询问渠道技术人员，是否有定时作业，但是通过从技术人员那里得到的反馈，并没有这种情况，因此很快排除了以上的推断，接着就需要从数据库方面进行排查。

日志分析

      要了解数据库出现问题当时的状态，我们需要排查数据库的告警日志（alert.log），这里面有很多关键的信息。于是再次联系渠道技术人员，让其把日志打包传输过来进行排查，看是否在出现问题的时段有异常提示，结果还真的发现了问题，如下：

Sat Jul 30 06:00:06 2011

GATHER_STATS_JOB encountered errors. Check the trace file.

Sat Jul 30 06:00:06 2011

Errors in filed:\oracle\product\10.2.\admin\orcl\bdump\orcl_j000_5924.trc

ORA-20000: index "ZLHIS"."号码控制表_UQ_项目名称" or partition of such index is in unusable state

 

Sat Jul 30 07:22:52 2011

Thread 1 advanced to log sequence 28201 (LGWR switch)

 Current log# 3 seq# 28201 mem# 0: S:\ORACLE\ORADATA\ORCL\REDO03.LOG

Dump file d:\oracle\product\10.2.0/admin/orcl/bdump\alert_orcl.log

Sat Jul 30 08:06:58 2011

ORACLE V10.2.0.4.0 - 64bit Production vsnsta=0

vsnsql=14 vsnxtr=3

Windows Server 2003 Version V5.2 Service Pack 2

CPU                : 8 - type 8664, 2 Physical Cores

Process Affinity   : 0x0000000000000000

Memory (Avail/Total): Ph:7228M/8190M, Ph+PgF:15188M/15940M

Sat Jul 30 08:06:58 2011

Starting ORACLE instance (normal)

LICENSE_MAX_SESSION = 0

LICENSE_SESSIONS_WARNING = 0

Picked latch-free SCN scheme 3

Autotune of undo retention is turned on.

IMODE=BR

ILAT =97

LICENSE_MAX_USERS = 0

SYS auditing is disabled

ksdpec: called for event 13740 prior to event group initialization

Starting up ORACLE RDBMS Version: 10.2.0.4.0.

      通过日志可以看到，8.06分，数据库进行了重启，重启前并未有任何错误信息，但是在6.00的时候，有一个错误信息ORA-20000，根据提示进一步查看d:\oracle\product\10.2.0\admin\orcl\bdump\orcl_j000_5924.trc文件，有如下错误信息：

*** ACTION NAME:(GATHER_STATS_JOB) 2011-07-30 06:00:06.140

*** MODULE NAME:(DBMS_SCHEDULER) 2011-07-30 06:00:06.140

*** SERVICE NAME:(SYS$USERS) 2011-07-30 06:00:06.140

*** SESSION ID:(691.41214) 2011-07-30 06:00:06.140

ORA-20000: index "ZLHIS"."号码控制表_UQ_项目名称" or partition of such index is in unusable state

*** 2011-07-30 06:00:06.140

GATHER_STATS_JOB: GATHER_TABLE_STATS('"ZLHIS"','"号码控制表"','""', ...)

ORA-20000: index "ZLHIS"."号码控制表_UQ_项目名称" or partition of such index is in unusable state

   是否数据库在6：00已经出现了问题，且无法登录，但是由于医院是8点多才上班，这时集中登录数据库，因此错误的认为8：00时分数据库才死机？问了下现场的技术人员，说不清楚是否晚上就不能登录。不管怎么说，先把这个错误处理了再观察。通过错误提示，可以看到应该是号码控制表_UQ_项目名称 索引状态失效导致，查看该索引状态：

SQL>select status from dba_indexes where index_name ='号码控制表_UQ_项目名称';

STATUS
------------------------
unusable

   引起索引状态unusable的原因很多，比如基表进行了物理移动，即我们所说的move表或者直接通过命令alter index 进行状态修改，还有就是如使用分区表的时候，如果创建的是全局索引，如果其中一个分区被删除，全局索引也会被unusable，由于我们未使用分区表，这种情况可以不用考虑，至于本例中为什么索引状态会变成unusable呢？暂时先不去深究，先处理索引的状态，只需要重新创建该索引就行，因此联系TY公司的同事，说明错误提示，叫其在晚上业务不繁忙的时候删除该索引重建，然后再观察是否问题有所改善。

   另外再看日志的时候，还发现在业务高峰期，数据库日志中有大量checkpoint未完成的提示，如下：

Fri Jul 29 09:37:58 2011

Thread 1 cannot allocate new log, sequence 28171

Checkpoint not complete

 Current log# 2 seq# 28170 mem# 0: S:\ORACLE\ORADATA\ORCL\REDO02.LOG

Fri Jul 29 09:38:00 2011

Thread 1 advanced to log sequence 28171 (LGWR switch)

 Current log# 3 seq# 28171 mem# 0: S:\ORACLE\ORADATA\ORCL\REDO03.LOG

Fri Jul 29 09:41:38 2011

Thread 1 cannot allocate new log, sequence 28172

Checkpoint not complete

 Current log# 3 seq# 28171 mem# 0: S:\ORACLE\ORADATA\ORCL\REDO03.LOG

   虽然这与本次问题处理没有任何关系，但是考虑到对用户和渠道负责的态度，顺便也对该问题进行了处理，产生该问题的原因大多数是磁盘读写能力不足或者日志太小，切换过于频繁，一般的处理方法是增大在线日志(redo)，这里我重新设置其大小为100m,并增加redo文件组到5组，默认是3组，进行完以上处理后，就邮件通知渠道技术人员进行观察，备案，希望问题能够就此解决。

   就这么一折腾，已经过去2个多小时，自己手上正式工作还没做完呢，难不成又要加班，赶紧接着调试QJRMYY服务器的硬件环境。

问题依旧

      两天过去，本来已经没有把这个事情挂在心上，突然一天早上，又接到TY渠道技术人员电话，说JM医院数据库在正常使用了两天后，又死机了，现象和以前一样。第一反应是难道又是同样的索引失效导致？连忙叫现场技术人员把数据库日志传送过来查看，发现日志中以前出现的异常情况都已经消失，证明已经排除，这次除了数据库实例的启动信息，未再有任何有价值的信息，这下我也满头雾水了。冷静下来重新理下思路，首先列举下影响客户端无法登录的因素：

1.客户端程序问题。（已排除）

2.网络硬件问题。（已排除）

3.操作系统环境。（已排除）

4.数据库实例。（已排除）

5.数据库监听。（未检查）

      看来得从数据库监听方面排查，首先，看下监听的日志（linstener.log）,这一检查还真发现了问题，linstener.log文件居然有400多M，采用记事本根本无法打开，会不会与日志文件太大有关系呢？另辟蹊径，查看下sqlnet.log文件，在问题时段有大量如下错误信息：

TNS-12547: TNS:lost contact

TNS-12547: TNS:lost contact
TNS-12560: TNS protocol adapter error
  TNS-00517: Lost contact

      看来问题的根本原因应该就是监听导致的，接下来就是静下心来分析下为什么监听日志过大会导致数据库死机呢？

彻底解决

      那到底是不是由于linstener.log过大导致数据库死机的呢？我们重新结合实际环境进行下分析：

      医院反映死机都是在早上8：00多，这个时间段用户集中登录，在登录过程中，数据库需要频繁的访问写入linstener.log日志；由于linstener.log日志过大，导致写入时候发生堵塞；最后就表现为前端应用就是客户端无法登录，用户误认为数据库已经死机，其实这个时候，只需要重新启动下监听，问题就应该能够解决，因为清理了堵塞连接，用户由于不清楚具体原因，所以采用重新启动服务器的方式解决的问题。

      分析完现象后处理过程就非常简单了,2种方式，要么不写log,要么清空linstener.log日志，我们这里采用后者，清空linstener.log日志，然后重新启动下监听程序，联系现场技术人员，让其这段时间持续观察数据库的运行状态。事情过去半个月，该医院也未在出现数据库死机的现象，看来问题是彻底解决了，还算比较圆满。

后续总结

      通过本次问题的处理的描述，我们至少应该学会以下2点问题处理思路：

      1.学会查看数据库的日志，一般能快速找到产生问题的原因。

      2.善于分析问题，罗列关键因素，步步排查，最后必定能够找到问题产生的根源。

    通过解决问题的思路的表述，希望对以后处理数据库问题的同学有所帮助.